From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753383AbcCSJdk (ORCPT ); Sat, 19 Mar 2016 05:33:40 -0400 Received: from mail-ig0-f178.google.com ([209.85.213.178]:33161 "EHLO mail-ig0-f178.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752283AbcCSJdh (ORCPT ); Sat, 19 Mar 2016 05:33:37 -0400 Date: Sat, 19 Mar 2016 17:32:53 +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: <20160319093244.GD2203@fixme-laptop.cn.ibm.com> References: <20160318130602.25f6c9cd@gandalf.local.home> <20160319041030.GA24958@fixme-laptop.cn.ibm.com> MIME-Version: 1.0 Content-Type: multipart/signed; micalg=pgp-sha256; protocol="application/pgp-signature"; boundary="9crTWz/Z+Zyzu20v" Content-Disposition: inline In-Reply-To: <20160319041030.GA24958@fixme-laptop.cn.ibm.com> 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 --9crTWz/Z+Zyzu20v Content-Type: text/plain; charset=us-ascii Content-Disposition: inline Content-Transfer-Encoding: quoted-printable On Sat, Mar 19, 2016 at 12:10:30PM +0800, Boqun Feng wrote: > Hi Steven, >=20 > 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_ta= sk > > <...>-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_f= air > > <...>-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_swit= ch > > gnome-sh-1031 0d..2 3us : do_raw_spin_unlock <-_raw_spin_unlock_i= rq > > 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() >=20 > Just out of curiosity, could this be solved by adding a barrier() here? >=20 > > function trace (before incrementing preempt count) > > preempt_disable_notrace() > > preempt_enable_notrace() > > sees NEED_RESCHED set > > preempt_schedule() (repeat) > >=20 >=20 > I'm asking this because it seems to me if PREEMPT_COUNT=3Dy and > PREEMPT_TRACER=3Dy, then >=20 > preempt_disable_notrace(); > preempt_disable_check(1); >=20 > is actually >=20 > __preempt_count_inc(); > barrier(); > preempt_disable_check(1); >=20 > whereas > =09 > preempt_disable() >=20 > is actually >=20 > __preempt_count_inc(); > preempt_disable_check(1); > barrier(); >=20 > so I think adding barrier() (or even moving the barrier() up) in > preempt_disable() could solve the same problem. >=20 > 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(). >=20 > Or Am I missing something subtle here? >=20 Oops, seems I have the question because I really don't understand how function tracing works. I now understand the problem here, Please ignore this, sorry for the noise. Regards, Boqun > Regards, > Boqun >=20 > > 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 lon= g 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_com= mon(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 preemp= t_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= _schedule_notrace(void) > > __schedule(true); > > exception_exit(prev_ctx); > > =20 > > + preempt_enable_check(1); > > preempt_enable_no_resched_notrace(); > > } while (need_resched()); > > } --9crTWz/Z+Zyzu20v Content-Type: application/pgp-signature; name="signature.asc" -----BEGIN PGP SIGNATURE----- Version: GnuPG v2 iQEcBAABCAAGBQJW7RzCAAoJEEl56MO1B/q4o8UH/i0OdBmMOJQCTodUiLUC75hh KXAzR9YnLwDretmz4CceWXIIy1W67qPDbK3yUYH6iqa2Vajq6surVs1807gUy8FR n1Tg/zUl9fcypCOJGMvOe6PzAQHFv1L59l2C8KaqSzz35HnA82Vkj3uW91vDUg4v klvZ+KXyxy3hEzEn5R8eurFQX9HaivA3LW6M9B5cTEgc6JYKsfFh3crbkK3cNyoA 0hZDcoDLQSDOFEkE0mWL7hx9gbgWcio+sATFqYOQBFji0JVv6wa11GWte0uQ6/kX hW4ycnCQ0lq/DHg/BQIOA4+I/F6O/2QPNOJiZFhtDMR279qu5WpbOqgY3jqe9t8= =MvP5 -----END PGP SIGNATURE----- --9crTWz/Z+Zyzu20v--