From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754329AbcG0JPe (ORCPT ); Wed, 27 Jul 2016 05:15:34 -0400 Received: from mail-wm0-f68.google.com ([74.125.82.68]:35864 "EHLO mail-wm0-f68.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752948AbcG0JPc (ORCPT ); Wed, 27 Jul 2016 05:15:32 -0400 Date: Wed, 27 Jul 2016 11:15:28 +0200 From: Ingo Molnar To: Vegard Nossum Cc: Ingo Molnar , Peter Zijlstra , linux-kernel@vger.kernel.org, "Paul E. McKenney" , Thomas Gleixner , Rusty Russel Subject: Re: [PATCH] sched/core: make "Preemption disabled at" message more useful Message-ID: <20160727091527.GB6323@gmail.com> References: <1469260693-22260-1-git-send-email-vegard.nossum@oracle.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1469260693-22260-1-git-send-email-vegard.nossum@oracle.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 * Vegard Nossum wrote: > This message is currently really useless since it always prints a value > that comes from the printk() we just did, e.g.: > > BUG: sleeping function called from invalid context at mm/slab.h:388 > in_atomic(): 0, irqs_disabled(): 0, pid: 31996, name: trinity-c1 > Preemption disabled at:[] down_trylock+0x13/0x80 > > BUG: sleeping function called from invalid context at include/linux/freezer.h:56 > in_atomic(): 0, irqs_disabled(): 0, pid: 31996, name: trinity-c1 > Preemption disabled at:[] console_unlock+0x2f7/0x930 > > Here, both down_trylock() and console_unlock() is somewhere in the > printk() path. > > We should save the value before calling printk() and use the saved value > instead. That immediately reveals the offending callsite: > > BUG: sleeping function called from invalid context at mm/slab.h:388 > in_atomic(): 0, irqs_disabled(): 0, pid: 14971, name: trinity-c2 > Preemption disabled at:[] rhashtable_walk_start+0x46/0x150 > > (Bug report: http://marc.info/?l=linux-netdev&m=146925979821849&w=2) > > Cc: Peter Zijlstra > Cc: Paul E. McKenney > Cc: Thomas Gleixner > Cc: Ingo Molnar > Cc: Rusty Russel > Signed-off-by: Vegard Nossum > --- > kernel/sched/core.c | 21 +++++++++++++++++++-- > 1 file changed, 19 insertions(+), 2 deletions(-) > > diff --git a/kernel/sched/core.c b/kernel/sched/core.c > index 7171cf9..87689a6 100644 > --- a/kernel/sched/core.c > +++ b/kernel/sched/core.c > @@ -3144,9 +3144,18 @@ static inline void preempt_latency_stop(int val) { } > */ > static noinline void __schedule_bug(struct task_struct *prev) > { > +#ifdef CONFIG_DEBUG_PREEMPT > + unsigned long preempt_disable_ip; > +#endif > + > if (oops_in_progress) > return; > > +#ifdef CONFIG_DEBUG_PREEMPT > + /* Save this before calling printk(), since that will clobber it */ > + preempt_disable_ip = current->preempt_disable_ip; > +#endif These two blocks could be merged trivially, avoiding an #ifdef pair ... > + > printk(KERN_ERR "BUG: scheduling while atomic: %s/%d/0x%08x\n", > prev->comm, prev->pid, preempt_count()); > > @@ -3157,7 +3166,7 @@ static noinline void __schedule_bug(struct task_struct *prev) > #ifdef CONFIG_DEBUG_PREEMPT > if (in_atomic_preempt_off()) { > pr_err("Preemption disabled at:"); > - print_ip_sym(current->preempt_disable_ip); > + print_ip_sym(preempt_disable_ip); > pr_cont("\n"); > } > #endif > @@ -7541,6 +7550,9 @@ EXPORT_SYMBOL(__might_sleep); > void ___might_sleep(const char *file, int line, int preempt_offset) > { > static unsigned long prev_jiffy; /* ratelimiting */ > +#ifdef CONFIG_DEBUG_PREEMPT > + unsigned long preempt_disable_ip; > +#endif > > rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */ > if ((preempt_count_equals(preempt_offset) && !irqs_disabled() && > @@ -7551,6 +7563,11 @@ void ___might_sleep(const char *file, int line, int preempt_offset) > return; > prev_jiffy = jiffies; > > +#ifdef CONFIG_DEBUG_PREEMPT > + /* Save this before calling printk(), since that will clobber it */ > + preempt_disable_ip = current->preempt_disable_ip; > +#endif > + > printk(KERN_ERR > "BUG: sleeping function called from invalid context at %s:%d\n", > file, line); > @@ -7568,7 +7585,7 @@ void ___might_sleep(const char *file, int line, int preempt_offset) > #ifdef CONFIG_DEBUG_PREEMPT > if (!preempt_count_equals(preempt_offset)) { > pr_err("Preemption disabled at:"); > - print_ip_sym(current->preempt_disable_ip); > + print_ip_sym(preempt_disable_ip); > pr_cont("\n"); Ditto. Thanks, Ingo