From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1751824AbcCSELU (ORCPT ); Sat, 19 Mar 2016 00:11:20 -0400 Received: from mail-ig0-f176.google.com ([209.85.213.176]:33583 "EHLO mail-ig0-f176.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750725AbcCSELN (ORCPT ); Sat, 19 Mar 2016 00:11:13 -0400 Date: Sat, 19 Mar 2016 12:10:30 +0800 From: Boqun Feng To: Steven Rostedt Cc: Peter Zijlstra , LKML , Ingo Molnar , Thomas Gleixner Subject: Re: [PATCH] sched: Add preempt checks in preempt_schedule() code Message-ID: <20160319041030.GA24958@fixme-laptop.cn.ibm.com> References: <20160318130602.25f6c9cd@gandalf.local.home> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="6TrnltStXW4iwmi0" Content-Disposition: inline In-Reply-To: <20160318130602.25f6c9cd@gandalf.local.home> User-Agent: Mutt/1.5.24 (2015-08-30) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org --6TrnltStXW4iwmi0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable Hi Steven, On Fri, Mar 18, 2016 at 01:06:02PM -0400, Steven Rostedt wrote: > While testing the tracer preemptoff, I hit this strange trace: >=20 > # cmd pid ||||| time | caller =20 > # \ / ||||| \ | / =20 > <...>-259 0...1 0us : schedule <-worker_thread > <...>-259 0d..1 0us : rcu_note_context_switch <-__schedule > <...>-259 0d..1 0us : rcu_sched_qs <-rcu_note_context_switch > <...>-259 0d..1 0us : rcu_preempt_qs <-rcu_note_context_switch > <...>-259 0d..1 0us : _raw_spin_lock <-__schedule > <...>-259 0d..1 0us : preempt_count_add <-_raw_spin_lock > <...>-259 0d..2 0us : do_raw_spin_lock <-_raw_spin_lock > <...>-259 0d..2 1us : deactivate_task <-__schedule > <...>-259 0d..2 1us : update_rq_clock.part.84 <-deactivate_task > <...>-259 0d..2 1us : dequeue_task_fair <-deactivate_task > <...>-259 0d..2 1us : dequeue_entity <-dequeue_task_fair > <...>-259 0d..2 1us : update_curr <-dequeue_entity > <...>-259 0d..2 1us : update_min_vruntime <-update_curr > <...>-259 0d..2 1us : cpuacct_charge <-update_curr > <...>-259 0d..2 1us : __rcu_read_lock <-cpuacct_charge > <...>-259 0d..2 1us : __rcu_read_unlock <-cpuacct_charge > <...>-259 0d..2 1us : clear_buddies <-dequeue_entity > <...>-259 0d..2 1us : account_entity_dequeue <-dequeue_entity > <...>-259 0d..2 2us : update_min_vruntime <-dequeue_entity > <...>-259 0d..2 2us : update_cfs_shares <-dequeue_entity > <...>-259 0d..2 2us : hrtick_update <-dequeue_task_fair > <...>-259 0d..2 2us : wq_worker_sleeping <-__schedule > <...>-259 0d..2 2us : kthread_data <-wq_worker_sleeping > <...>-259 0d..2 2us : pick_next_task_fair <-__schedule > <...>-259 0d..2 2us : check_cfs_rq_runtime <-pick_next_task_fair > <...>-259 0d..2 2us : pick_next_entity <-pick_next_task_fair > <...>-259 0d..2 2us : clear_buddies <-pick_next_entity > <...>-259 0d..2 2us : pick_next_entity <-pick_next_task_fair > <...>-259 0d..2 2us : clear_buddies <-pick_next_entity > <...>-259 0d..2 2us : set_next_entity <-pick_next_task_fair > <...>-259 0d..2 3us : put_prev_entity <-pick_next_task_fair > <...>-259 0d..2 3us : check_cfs_rq_runtime <-put_prev_entity > <...>-259 0d..2 3us : set_next_entity <-pick_next_task_fair > gnome-sh-1031 0d..2 3us : finish_task_switch <-__schedule > gnome-sh-1031 0d..2 3us : _raw_spin_unlock_irq <-finish_task_switch > gnome-sh-1031 0d..2 3us : do_raw_spin_unlock <-_raw_spin_unlock_irq > gnome-sh-1031 0...2 3us!: preempt_count_sub <-_raw_spin_unlock_irq > gnome-sh-1031 0...1 582us : do_raw_spin_lock <-_raw_spin_lock > gnome-sh-1031 0...1 583us : _raw_spin_unlock <-drm_gem_object_lookup > gnome-sh-1031 0...1 583us : do_raw_spin_unlock <-_raw_spin_unlock > gnome-sh-1031 0...1 583us : preempt_count_sub <-_raw_spin_unlock > gnome-sh-1031 0...1 584us : _raw_spin_unlock <-drm_gem_object_lookup > gnome-sh-1031 0...1 584us+: trace_preempt_on <-drm_gem_object_lookup > gnome-sh-1031 0...1 603us : > =3D> preempt_count_sub > =3D> _raw_spin_unlock > =3D> drm_gem_object_lookup > =3D> i915_gem_madvise_ioctl > =3D> drm_ioctl > =3D> do_vfs_ioctl > =3D> SyS_ioctl > =3D> entry_SYSCALL_64_fastpath >=20 > As I'm tracing preemption disabled, it seemed incorrect that the trace > would go across a schedule and report not being in the scheduler. > Looking into this I discovered the problem. >=20 > schedule() calls preempt_disable() but the preempt_schedule() calls > preempt_enable_notrace(). What happened above was that the gnome-shell > task was preempted on another CPU, migrated over to the idle cpu. The > tracer stared with idle calling schedule(), which called > preempt_disable(), but then gnome-shell finished, and it enabled > preemption with preempt_enable_notrace() that does stop the trace, even > though preemption was enabled. >=20 > The purpose of the preempt_disable_notrace() in the preempt_schedule() > is to prevent function tracing from going into an infinite loop. > Because function tracing can trace the preempt_enable/disable() calls > that are traced. The problem with function tracing is: >=20 > NEED_RESCHED set > preempt_schedule() > preempt_disable() > preempt_count_inc() Just out of curiosity, could this be solved by adding a barrier() here? > function trace (before incrementing preempt count) > preempt_disable_notrace() > preempt_enable_notrace() > sees NEED_RESCHED set > preempt_schedule() (repeat) >=20 I'm asking this because it seems to me if PREEMPT_COUNT=3Dy and PREEMPT_TRACER=3Dy, then preempt_disable_notrace(); preempt_disable_check(1); is actually __preempt_count_inc(); barrier(); preempt_disable_check(1); whereas =09 preempt_disable() is actually __preempt_count_inc(); preempt_disable_check(1); barrier(); so I think adding barrier() (or even moving the barrier() up) in preempt_disable() could solve the same problem. If so, seems we don't need to introduce preempt_disable_check() and preempt_enable_check(), even better, we can use preempt_disable() and preempt_enable_no_resched() in preempt_schedule(). Or Am I missing something subtle here? Regards, Boqun > Now by breaking out the preempt off/on tracing into their own code: > preempt_disable_check() and preempt_enable_check(), we can add these to > the preempt_schedule() code. As preemption would then be disabled, even > if they were to be traced by the function tracer, the disabled > preemption would prevent the recursion. >=20 > Signed-off-by: Steven Rostedt > --- > diff --git a/kernel/sched/core.c b/kernel/sched/core.c > index 9503d590e5ef..a925e1d2c4cd 100644 > --- a/kernel/sched/core.c > +++ b/kernel/sched/core.c > @@ -3023,6 +3023,17 @@ notrace unsigned long get_parent_ip(unsigned long = addr) > #if defined(CONFIG_PREEMPT) && (defined(CONFIG_DEBUG_PREEMPT) || \ > defined(CONFIG_PREEMPT_TRACER)) > =20 > +static inline void preempt_disable_check(int val) > +{ > + if (preempt_count() =3D=3D val) { > + unsigned long ip =3D get_parent_ip(CALLER_ADDR1); > +#ifdef CONFIG_DEBUG_PREEMPT > + current->preempt_disable_ip =3D ip; > +#endif > + trace_preempt_off(CALLER_ADDR0, ip); > + } > +} > + > void preempt_count_add(int val) > { > #ifdef CONFIG_DEBUG_PREEMPT > @@ -3040,17 +3051,17 @@ void preempt_count_add(int val) > DEBUG_LOCKS_WARN_ON((preempt_count() & PREEMPT_MASK) >=3D > PREEMPT_MASK - 10); > #endif > - if (preempt_count() =3D=3D val) { > - unsigned long ip =3D get_parent_ip(CALLER_ADDR1); > -#ifdef CONFIG_DEBUG_PREEMPT > - current->preempt_disable_ip =3D ip; > -#endif > - trace_preempt_off(CALLER_ADDR0, ip); > - } > + preempt_disable_check(val); > } > EXPORT_SYMBOL(preempt_count_add); > NOKPROBE_SYMBOL(preempt_count_add); > =20 > +static inline void preempt_enable_check(int val) > +{ > + if (preempt_count() =3D=3D val) > + trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1)); > +} > + > void preempt_count_sub(int val) > { > #ifdef CONFIG_DEBUG_PREEMPT > @@ -3067,13 +3078,15 @@ void preempt_count_sub(int val) > return; > #endif > =20 > - if (preempt_count() =3D=3D val) > - trace_preempt_on(CALLER_ADDR0, get_parent_ip(CALLER_ADDR1)); > + preempt_enable_check(val); > __preempt_count_sub(val); > } > EXPORT_SYMBOL(preempt_count_sub); > NOKPROBE_SYMBOL(preempt_count_sub); > =20 > +#else > +static inline void preempt_disable_check(int val) { } > +static inline void preempt_enable_check(int val) { } > #endif > =20 > /* > @@ -3349,7 +3362,14 @@ static void __sched notrace preempt_schedule_commo= n(void) > { > do { > preempt_disable_notrace(); > + /* > + * Function tracer requires disabling preemption before > + * tracing functions. But we still want to trace > + * preemption off locations. > + */ > + preempt_disable_check(1); > __schedule(true); > + preempt_enable_check(1); > preempt_enable_no_resched_notrace(); > =20 > /* > @@ -3403,6 +3423,12 @@ asmlinkage __visible void __sched notrace preempt_= schedule_notrace(void) > do { > preempt_disable_notrace(); > /* > + * Function tracer requires disabling preemption before > + * tracing functions. But we still want to trace > + * preemption off locations. > + */ > + preempt_disable_check(1); > + /* > * Needs preempt disabled in case user_exit() is traced > * and the tracer calls preempt_enable_notrace() causing > * an infinite recursion. > @@ -3411,6 +3437,7 @@ asmlinkage __visible void __sched notrace preempt_s= chedule_notrace(void) > __schedule(true); > exception_exit(prev_ctx); > =20 > + preempt_enable_check(1); > preempt_enable_no_resched_notrace(); > } while (need_resched()); > } --6TrnltStXW4iwmi0 Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- Version: GnuPG v2 iQEcBAABCAAGBQJW7NEzAAoJEEl56MO1B/q45s8H/1xBCYFn6BbLX+LxRo2C244f Sdhj6VpycISj+5dRBfeZXfZt2gytUGS9O0FWS1oz/9a8IaVIQ+8SJKh//dG/b0kX TMQW1/AqaejAChFH0B+uKLYyL0xGoQTDdktDxKAvKwwHu3eKEA/VFamUYxanpar2 CdG7felhivcK/T0DW9jQWELVxC9rXOWj5RLxewyb0eqTHqbsRxj5AKh0pLFM4nps kcLKARK+W72M56vUqYKRG3ooNb84mr03iJPdcKr8gVJbbABgBPdHavAV5MIK8ayI nuJ7zdXYAHi/8KDeB/ecCIvid78BGd9dtJzCNRbQ8cBzVcdaq/z7xu2RDaYE3/E= =U9zy -----END PGP SIGNATURE----- --6TrnltStXW4iwmi0--