[PATCH] sched/core: make "Preemption disabled at" message more useful

[PATCH] sched/core: make "Preemption disabled at" message more useful

[Vegard Nossum]

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:[<ffffffff8119db33>] 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:[<ffffffff811aaa37>] 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:[<ffffffff819bcd46>] rhashtable_walk_start+0x46/0x150

(Bug report: http://marc.info/?l=linux-netdev&m=146925979821849&w=2)

Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Rusty Russel <rusty@rustcorp.com.au>
Signed-off-by: Vegard Nossum <vegard.nossum@oracle.com>
---
 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
+
 	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");
 	}
 #endif
-- 
1.9.1

Re: [PATCH] sched/core: make "Preemption disabled at" message more useful

[Ingo Molnar]

* Vegard Nossum <vegard.nossum@oracle.com> 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:[<ffffffff8119db33>] 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:[<ffffffff811aaa37>] 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:[<ffffffff819bcd46>] rhashtable_walk_start+0x46/0x150
> 
> (Bug report: http://marc.info/?l=linux-netdev&m=146925979821849&w=2)
> 
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
> Cc: Thomas Gleixner <tglx@linutronix.de>
> Cc: Ingo Molnar <mingo@kernel.org>
> Cc: Rusty Russel <rusty@rustcorp.com.au>
> Signed-off-by: Vegard Nossum <vegard.nossum@oracle.com>
> ---
>  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

Re: [PATCH] sched/core: make "Preemption disabled at" message more useful

[Vegard Nossum]

[-- Attachment #1: Type: text/plain, Size: 1346 bytes --]

On 27 July 2016 at 11:15, Ingo Molnar <mingo@kernel.org> wrote:
>
> * Vegard Nossum <vegard.nossum@oracle.com> wrote:
[...]

> These two blocks could be merged trivially, avoiding an #ifdef pair ...

>> @@ -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
>
> Ditto.

I'm assuming you want to declare and initialise preempt_disable_ip at
once here, but it generates slightly worse code since it dereferences
current->preempt_disable_ip in the "fast path" (i.e. a sleeping
function is NOT called from an invalid context).

If you really prefer that I've attached an updated patch.

Let me know if I misunderstood :-)


Vegard

[-- Attachment #2: 0001-sched-core-make-Preemption-disabled-at-message-more-.patch --]
[-- Type: text/x-patch, Size: 3284 bytes --]

From 332d49d4da90f00304de73c7412311576e2e7f78 Mon Sep 17 00:00:00 2001
From: Vegard Nossum <vegard.nossum@oracle.com>
Date: Sat, 23 Jul 2016 09:46:39 +0200
Subject: [PATCH] sched/core: make "Preemption disabled at" message more useful

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:[<ffffffff8119db33>] 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:[<ffffffff811aaa37>] 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:[<ffffffff819bcd46>] rhashtable_walk_start+0x46/0x150

(Bug report: http://marc.info/?l=linux-netdev&m=146925979821849&w=2)

Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Rusty Russel <rusty@rustcorp.com.au>
Signed-off-by: Vegard Nossum <vegard.nossum@oracle.com>
---
 kernel/sched/core.c | 13 +++++++++++--
 1 file changed, 11 insertions(+), 2 deletions(-)

diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 7171cf9..e06354e 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3144,6 +3144,11 @@ static inline void preempt_latency_stop(int val) { }
  */
 static noinline void __schedule_bug(struct task_struct *prev)
 {
+#ifdef CONFIG_DEBUG_PREEMPT
+	/* Save this before calling printk(), since that will clobber it */
+	unsigned long preempt_disable_ip = current->preempt_disable_ip;
+#endif
+
 	if (oops_in_progress)
 		return;
 
@@ -3157,7 +3162,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 +7546,10 @@ 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
+	/* Save this before calling printk(), since that will clobber it */
+	unsigned long preempt_disable_ip = current->preempt_disable_ip;
+#endif
 
 	rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */
 	if ((preempt_count_equals(preempt_offset) && !irqs_disabled() &&
@@ -7568,7 +7577,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");
 	}
 #endif
-- 
1.9.1

Re: [PATCH] sched/core: make "Preemption disabled at" message more useful

[Ingo Molnar]

* Vegard Nossum <vegard.nossum@gmail.com> wrote:

> On 27 July 2016 at 11:15, Ingo Molnar <mingo@kernel.org> wrote:
> >
> > * Vegard Nossum <vegard.nossum@oracle.com> wrote:
> [...]
> 
> > These two blocks could be merged trivially, avoiding an #ifdef pair ...
> 
> >> @@ -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
> >
> > Ditto.
> 
> I'm assuming you want to declare and initialise preempt_disable_ip at
> once here, but it generates slightly worse code since it dereferences
> current->preempt_disable_ip in the "fast path" (i.e. a sleeping
> function is NOT called from an invalid context).

Could you please add a likely() branch to see whether GCC will delay the 
initialization?

The 4 #ifdefs were really ugly, so yes, it would be nice to at least reduce them 
to 2.

Thanks,

	Ingo

Re: [PATCH] sched/core: make "Preemption disabled at" message more useful

[Vegard Nossum]

[-- Attachment #1: Type: text/plain, Size: 573 bytes --]

On 07/27/2016 12:38 PM, Ingo Molnar wrote:
> * Vegard Nossum <vegard.nossum@gmail.com> wrote:
>> I'm assuming you want to declare and initialise preempt_disable_ip at
>> once here, but it generates slightly worse code since it dereferences
>> current->preempt_disable_ip in the "fast path" (i.e. a sleeping
>> function is NOT called from an invalid context).
>
> Could you please add a likely() branch to see whether GCC will delay the
> initialization?
>
> The 4 #ifdefs were really ugly, so yes, it would be nice to at least reduce them
> to 2.

How about this?


Vegard

[-- Attachment #2: 0001-sched-core-make-Preemption-disabled-at-message-more-.patch --]
[-- Type: text/x-patch, Size: 4505 bytes --]

>From 9d0e4bb63f0fada627a4f99432db8d39add487b4 Mon Sep 17 00:00:00 2001
From: Vegard Nossum <vegard.nossum@oracle.com>
Date: Sat, 23 Jul 2016 09:46:39 +0200
Subject: [PATCH] sched/core: make "Preemption disabled at" message more useful

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:[<ffffffff8119db33>] 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:[<ffffffff811aaa37>] 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:[<ffffffff819bcd46>] rhashtable_walk_start+0x46/0x150

(Bug report: http://marc.info/?l=linux-netdev&m=146925979821849&w=2)

Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Thomas Gleixner <tglx@linutronix.de>
Cc: Ingo Molnar <mingo@kernel.org>
Cc: Rusty Russel <rusty@rustcorp.com.au>
Signed-off-by: Vegard Nossum <vegard.nossum@oracle.com>
---
 include/linux/sched.h |  9 +++++++++
 kernel/sched/core.c   | 21 +++++++++++++--------
 2 files changed, 22 insertions(+), 8 deletions(-)

diff --git a/include/linux/sched.h b/include/linux/sched.h
index 253538f2..cdbcc2e 100644
--- a/include/linux/sched.h
+++ b/include/linux/sched.h
@@ -3142,6 +3142,15 @@ static inline void cond_resched_rcu(void)
 #endif
 }
 
+static inline unsigned long get_preempt_disable_ip(struct task_struct *p)
+{
+#ifdef CONFIG_DEBUG_PREEMPT
+	return p->preempt_disable_ip;
+#else
+	return 0;
+#endif
+}
+
 /*
  * Does a critical section need to be broken due to another
  * task waiting?: (technically does not depend on CONFIG_PREEMPT,
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index 7171cf9..afd2403 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -3144,6 +3144,9 @@ static inline void preempt_latency_stop(int val) { }
  */
 static noinline void __schedule_bug(struct task_struct *prev)
 {
+	/* Save this before calling printk(), since that will clobber it */
+	unsigned long preempt_disable_ip = get_preempt_disable_ip(current);
+
 	if (oops_in_progress)
 		return;
 
@@ -3154,13 +3157,12 @@ static noinline void __schedule_bug(struct task_struct *prev)
 	print_modules();
 	if (irqs_disabled())
 		print_irqtrace_events(prev);
-#ifdef CONFIG_DEBUG_PREEMPT
-	if (in_atomic_preempt_off()) {
+	if (IS_ENABLED(CONFIG_DEBUG_PREEMPT)
+	    && 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
 	dump_stack();
 	add_taint(TAINT_WARN, LOCKDEP_STILL_OK);
 }
@@ -7541,6 +7543,7 @@ EXPORT_SYMBOL(__might_sleep);
 void ___might_sleep(const char *file, int line, int preempt_offset)
 {
 	static unsigned long prev_jiffy;	/* ratelimiting */
+	unsigned long preempt_disable_ip;
 
 	rcu_sleep_check(); /* WARN_ON_ONCE() by default, no rate limit reqd. */
 	if ((preempt_count_equals(preempt_offset) && !irqs_disabled() &&
@@ -7551,6 +7554,9 @@ void ___might_sleep(const char *file, int line, int preempt_offset)
 		return;
 	prev_jiffy = jiffies;
 
+	/* Save this before calling printk(), since that will clobber it */
+	preempt_disable_ip = get_preempt_disable_ip(current);
+
 	printk(KERN_ERR
 		"BUG: sleeping function called from invalid context at %s:%d\n",
 			file, line);
@@ -7565,13 +7571,12 @@ void ___might_sleep(const char *file, int line, int preempt_offset)
 	debug_show_held_locks(current);
 	if (irqs_disabled())
 		print_irqtrace_events(current);
-#ifdef CONFIG_DEBUG_PREEMPT
-	if (!preempt_count_equals(preempt_offset)) {
+	if (IS_ENABLED(CONFIG_DEBUG_PREEMPT)
+	    && !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");
 	}
-#endif
 	dump_stack();
 	add_taint(TAINT_WARN, LOCKDEP_STILL_OK);
 }
-- 
1.9.1