[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Grygorii Strashko]

Hi All,

The regression is observed in the current linux-next on ARM Keystone 2 SoC:
- system is booted till console and in a second or two and then stall, no messages displayed
(CONFIG_DEBUG_PREEMPT=y).

The cause of regression has been bisected to the commit:

commit 589a606f9539663f162e4a110d117527833b58a4
Author: Christoph Lameter <cl@linux.com>
Date:   Mon Mar 17 11:27:41 2014 +1100

    percpu: add preemption checks to __this_cpu ops
    
    We define a check function in order to avoid trouble with the include
    files.  Then the higher level __this_cpu macros are modified to invoke the
    preemption check.
    
    Signed-off-by: Christoph Lameter <cl@linux.com>
    Acked-by: Ingo Molnar <mingo@kernel.org>
    Cc: Tejun Heo <tj@kernel.org>
    Signed-off-by: Andrew Morton <akpm@linux-foundation.org>

[=== 1 ===]
If above patch is reverted - system can boot again.

[=== 2 ===]
If I apply below change - system can boot again.

diff --git a/lib/smp_processor_id.c b/lib/smp_processor_id.c
index a270dce..73a2004 100644
--- a/lib/smp_processor_id.c
+++ b/lib/smp_processor_id.c
@@ -58,9 +58,6 @@ EXPORT_SYMBOL(debug_smp_processor_id);
 
 notrace void __this_cpu_preempt_check(const char *op)
 {
-       char text[40];
-
-       snprintf(text, sizeof(text), "__this_cpu_%s()", op);
-       check_preemption_disabled(text);
+       check_preemption_disabled(op);
 }
 EXPORT_SYMBOL(__this_cpu_preempt_check);


linux-next top commits:
3bd688c Add linux-next specific files for 20140318
9a63a74 Merge branch 'akpm/master'
ccdf335 mm: add strictlimit knob
589a606 percpu: add preemption checks to __this_cpu ops
cdbd87c net: replace __this_cpu_inc in route.c with raw_cpu_inc
049fcfe modules: use raw_cpu_write for initialization of per cpu refcount.
b46b094 mm: use raw_cpu ops for determining current NUMA node
d934df8 percpu: add raw_cpu_ops
c4a8790 arm: move arm_dma_limit to setup_dma_zone

Regards,
-grygorii

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Christoph Lameter]

On Tue, 18 Mar 2014, Grygorii Strashko wrote:

> diff --git a/lib/smp_processor_id.c b/lib/smp_processor_id.c
> index a270dce..73a2004 100644
> --- a/lib/smp_processor_id.c
> +++ b/lib/smp_processor_id.c
> @@ -58,9 +58,6 @@ EXPORT_SYMBOL(debug_smp_processor_id);
>
>  notrace void __this_cpu_preempt_check(const char *op)
>  {
> -       char text[40];
> -
> -       snprintf(text, sizeof(text), "__this_cpu_%s()", op);
> -       check_preemption_disabled(text);
> +       check_preemption_disabled(op);
>  }
>  EXPORT_SYMBOL(__this_cpu_preempt_check);

So it looks like there is an early this cpu operation in a context that
cannot handle snprintf. But the checks in check_preemption_disabled()
avoid processing there so that works.

We could fix this by moving the string concatenation operation into
the check function.

Index: linux/lib/smp_processor_id.c
===================================================================
--- linux.orig/lib/smp_processor_id.c	2014-03-18 09:36:31.330450525 -0500
+++ linux/lib/smp_processor_id.c	2014-03-18 09:36:37.822315534 -0500
@@ -7,7 +7,8 @@
 #include <linux/kallsyms.h>
 #include <linux/sched.h>

-notrace static unsigned int check_preemption_disabled(char *what)
+notrace static unsigned int check_preemption_disabled(const char *what1,
+							const char *what2)
 {
 	int this_cpu = raw_smp_processor_id();

@@ -38,8 +39,8 @@
 	if (!printk_ratelimit())
 		goto out_enable;

-	printk(KERN_ERR "BUG: using %s in preemptible [%08x] code: %s/%d\n",
-		what, preempt_count() - 1, current->comm, current->pid);
+	printk(KERN_ERR "BUG: using %s%s() in preemptible [%08x] code: %s/%d\n",
+		what1, what2, preempt_count() - 1, current->comm, current->pid);

 	print_symbol("caller is %s\n", (long)__builtin_return_address(0));
 	dump_stack();
@@ -52,15 +53,12 @@

 notrace unsigned int debug_smp_processor_id(void)
 {
-	return check_preemption_disabled("smp_processor_id()");
+	return check_preemption_disabled("smp_processor_id","");
 }
 EXPORT_SYMBOL(debug_smp_processor_id);

 notrace void __this_cpu_preempt_check(const char *op)
 {
-	char text[40];
-
-	snprintf(text, sizeof(text), "__this_cpu_%s()", op);
-	check_preemption_disabled(text);
+	check_preemption_disabled("__this_cpu_", op);
 }
 EXPORT_SYMBOL(__this_cpu_preempt_check);

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Grygorii Strashko]

On 03/18/2014 04:37 PM, Christoph Lameter wrote:
> On Tue, 18 Mar 2014, Grygorii Strashko wrote:
>
>> diff --git a/lib/smp_processor_id.c b/lib/smp_processor_id.c
>> index a270dce..73a2004 100644
>> --- a/lib/smp_processor_id.c
>> +++ b/lib/smp_processor_id.c
>> @@ -58,9 +58,6 @@ EXPORT_SYMBOL(debug_smp_processor_id);
>>
>>   notrace void __this_cpu_preempt_check(const char *op)
>>   {
>> -       char text[40];
>> -
>> -       snprintf(text, sizeof(text), "__this_cpu_%s()", op);
>> -       check_preemption_disabled(text);
>> +       check_preemption_disabled(op);
>>   }
>>   EXPORT_SYMBOL(__this_cpu_preempt_check);
>
> So it looks like there is an early this cpu operation in a context that
> cannot handle snprintf. But the checks in check_preemption_disabled()
> avoid processing there so that works.

Just to be sure that I've described time point of issue correctly:
[    2.161746] dwc3 2690000.dwc3: failed to initialize core
[    2.167255] dwc3: probe of 2690000.dwc3 failed with error -38
[    2.259687] Freeing unused kernel memory: 280K (c0678000 - c06be000)

Please press Enter to activate this console.
^^^ system stall here


Any way, I can boot and console works fine with your change :)
Thanks.

Tested-by: Grygorii Strashko <grygorii.strashko@ti.com>

>
> We could fix this by moving the string concatenation operation into
> the check function.
>
> Index: linux/lib/smp_processor_id.c
> ===================================================================
> --- linux.orig/lib/smp_processor_id.c	2014-03-18 09:36:31.330450525 -0500
> +++ linux/lib/smp_processor_id.c	2014-03-18 09:36:37.822315534 -0500
> @@ -7,7 +7,8 @@
>   #include <linux/kallsyms.h>
>   #include <linux/sched.h>
>
> -notrace static unsigned int check_preemption_disabled(char *what)
> +notrace static unsigned int check_preemption_disabled(const char *what1,
> +							const char *what2)
>   {
>   	int this_cpu = raw_smp_processor_id();
>
> @@ -38,8 +39,8 @@
>   	if (!printk_ratelimit())
>   		goto out_enable;
>
> -	printk(KERN_ERR "BUG: using %s in preemptible [%08x] code: %s/%d\n",
> -		what, preempt_count() - 1, current->comm, current->pid);
> +	printk(KERN_ERR "BUG: using %s%s() in preemptible [%08x] code: %s/%d\n",
> +		what1, what2, preempt_count() - 1, current->comm, current->pid);
>
>   	print_symbol("caller is %s\n", (long)__builtin_return_address(0));
>   	dump_stack();
> @@ -52,15 +53,12 @@
>
>   notrace unsigned int debug_smp_processor_id(void)
>   {
> -	return check_preemption_disabled("smp_processor_id()");
> +	return check_preemption_disabled("smp_processor_id","");
>   }
>   EXPORT_SYMBOL(debug_smp_processor_id);
>
>   notrace void __this_cpu_preempt_check(const char *op)
>   {
> -	char text[40];
> -
> -	snprintf(text, sizeof(text), "__this_cpu_%s()", op);
> -	check_preemption_disabled(text);
> +	check_preemption_disabled("__this_cpu_", op);
>   }
>   EXPORT_SYMBOL(__this_cpu_preempt_check);
>

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Christoph Lameter]

On Tue, 18 Mar 2014, Grygorii Strashko wrote:

> Any way, I can boot and console works fine with your change :)
> Thanks.

Ok here is the properly formatted patch:


Subject: preemption_checks: Avoid snprintf before checking error conditions

snprintf can cause hangs. Move the string processing into the function
so that the string operations only occur when necessary after the
conditions have been checked.

Tested-by: Grygorii Strashko <grygorii.strashko@ti.com>
Signed-off-by: Christoph Lameter <cl@linux.com>



Index: linux/lib/smp_processor_id.c
===================================================================
--- linux.orig/lib/smp_processor_id.c	2014-03-18 09:36:31.330450525 -0500
+++ linux/lib/smp_processor_id.c	2014-03-18 09:36:37.822315534 -0500
@@ -7,7 +7,8 @@
 #include <linux/kallsyms.h>
 #include <linux/sched.h>

-notrace static unsigned int check_preemption_disabled(char *what)
+notrace static unsigned int check_preemption_disabled(const char *what1,
+							const char *what2)
 {
 	int this_cpu = raw_smp_processor_id();

@@ -38,8 +39,8 @@
 	if (!printk_ratelimit())
 		goto out_enable;

-	printk(KERN_ERR "BUG: using %s in preemptible [%08x] code: %s/%d\n",
-		what, preempt_count() - 1, current->comm, current->pid);
+	printk(KERN_ERR "BUG: using %s%s() in preemptible [%08x] code: %s/%d\n",
+		what1, what2, preempt_count() - 1, current->comm, current->pid);

 	print_symbol("caller is %s\n", (long)__builtin_return_address(0));
 	dump_stack();
@@ -52,15 +53,12 @@

 notrace unsigned int debug_smp_processor_id(void)
 {
-	return check_preemption_disabled("smp_processor_id()");
+	return check_preemption_disabled("smp_processor_id","");
 }
 EXPORT_SYMBOL(debug_smp_processor_id);

 notrace void __this_cpu_preempt_check(const char *op)
 {
-	char text[40];
-
-	snprintf(text, sizeof(text), "__this_cpu_%s()", op);
-	check_preemption_disabled(text);
+	check_preemption_disabled("__this_cpu_", op);
 }
 EXPORT_SYMBOL(__this_cpu_preempt_check);

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Andrew Morton]

On Tue, 18 Mar 2014 10:54:06 -0500 (CDT) Christoph Lameter <cl@linux.com> wrote:

> On Tue, 18 Mar 2014, Grygorii Strashko wrote:
> 
> > Any way, I can boot and console works fine with your change :)
> > Thanks.
> 
> Ok here is the properly formatted patch:
> 
> 
> Subject: preemption_checks: Avoid snprintf before checking error conditions
> 
> snprintf can cause hangs.

This is weird.  How the heck can snprintf() fail if called too early? 
All it does is shuffle chars around in memory.  The only external
dependency I'm seeing is a WARN_ON() which presumably didn't trigger
anyway.

I'm suspecting a misdiagnosis here.  Otherwise, we seriously need to
fix snprintf(), not work around it!

Also, what does "before checking error conditions" refer to?  Does this
mean you know why snprintf() failed??

> Move the string processing into the function
> so that the string operations only occur when necessary after the
> conditions have been checked.
> 
> Tested-by: Grygorii Strashko <grygorii.strashko@ti.com>

Grygorii, thanks for testing linux-next on unusual machines - it's most
helpful.

> Signed-off-by: Christoph Lameter <cl@linux.com>

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Grygorii Strashko]

On 03/18/2014 11:37 PM, Andrew Morton wrote:> On Tue, 18 Mar 2014 10:54:06 -0500 (CDT) Christoph Lameter <cl@linux.com> wrote:
> 
>> On Tue, 18 Mar 2014, Grygorii Strashko wrote:
>>
>>> Any way, I can boot and console works fine with your change :)
>>> Thanks.
>>
>> Ok here is the properly formatted patch:
>>
>>
>> Subject: preemption_checks: Avoid snprintf before checking error conditions
>>
>> snprintf can cause hangs.
> 
> This is weird.  How the heck can snprintf() fail if called too early?
> All it does is shuffle chars around in memory.  The only external
> dependency I'm seeing is a WARN_ON() which presumably didn't trigger
> anyway.
> 
> I'm suspecting a misdiagnosis here.  Otherwise, we seriously need to
> fix snprintf(), not work around it!

Not sure I can run debugger fast :(, but I'll try.

> 
> Also, what does "before checking error conditions" refer to?  Does this
> mean you know why snprintf() failed??

Just an assumption, May be the problem here not in snprintf, but in stack.
Looks like if I reduce stack usage the issue is gone:
char text[10];

> 
>> Move the string processing into the function
>> so that the string operations only occur when necessary after the
>> conditions have been checked.
>>
>> Tested-by: Grygorii Strashko <grygorii.strashko@ti.com>
> 
> Grygorii, thanks for testing linux-next on unusual machines - it's most
> helpful.
> 

Regards,
-grygorii

[linux-next][regression] [PATCH] percpu: add preemption checks to __this_cpu ops

[Christoph Lameter]

On Tue, 18 Mar 2014, Andrew Morton wrote:

> > snprintf can cause hangs.
>
> This is weird.  How the heck can snprintf() fail if called too early?
> All it does is shuffle chars around in memory.  The only external
> dependency I'm seeing is a WARN_ON() which presumably didn't trigger
> anyway.
>
> I'm suspecting a misdiagnosis here.  Otherwise, we seriously need to
> fix snprintf(), not work around it!
>
> Also, what does "before checking error conditions" refer to?  Does this
> mean you know why snprintf() failed??

No I dont. I only know that this fixes Grygorii's issues. There could be
numerous arch specific per cpu setup issues going on that may impact on
snprintf.

If I move it behind the checks then I can avoid using snprintf.

[3.15-rc1] a huge number of warnings produced by xhci &

[Christoph Lameter]

n Mon, 14 Apr 2014, Grygorii Strashko wrote:

> Hi All,
>
> I'm observing a huge number of warnings produced during the boot of my Keystone 2 board
> when USB is enabled.
>
> [    2.496460] BUG: using __this_cpu_read() in preemptible [00000000] code: khubd/202
> [    2.504030] caller is __mod_zone_page_state+0x20/0xc8
> [    2.509094] CPU: 1 PID: 202 Comm: khubd Not tainted 3.15.0-rc1-00015-ge521fa3-dirty #55
> [    2.517122] [<c0013788>] (unwind_backtrace) from [<c001129c>] (show_stack+0x10/0x14)
> [    2.524854] [<c001129c>] (show_stack) from [<c049f800>] (dump_stack+0x68/0xb8)
> [    2.532086] [<c049f800>] (dump_stack) from [<c02731c0>] (check_preemption_disabled+0xe8/0x10c)
> [    2.540708] [<c02731c0>] (check_preemption_disabled) from [<c00bc944>] (__mod_zone_page_state+0x20/0xc8)
> [    2.550187] [<c00bc944>] (__mod_zone_page_state) from [<c00b50c8>] (reclaim_clean_pages_from_list+0x16c/0x178)
> [    2.560193] [<c00b50c8>] (reclaim_clean_pages_from_list) from [<c00ac8f0>] (alloc_contig_range+0x10c/0x2d0)
> [    2.569932] [<c00ac8f0>] (alloc_contig_range) from [<c02b0e58>] (dma_alloc_from_contiguous+0x70/0x118)
> [    2.579241] [<c02b0e58>] (dma_alloc_from_contiguous) from [<c0017d24>] (__alloc_from_contiguous+0x34/0x160)
> [    2.588974] [<c0017d24>] (__alloc_from_contiguous) from [<c0018760>] (__dma_alloc+0x18c/0x294)
> [    2.597582] [<c0018760>] (__dma_alloc) from [<c00189f0>] (arm_dma_alloc+0xac/0xd8)
> [    2.605140] [<c00189f0>] (arm_dma_alloc) from [<c00d84a8>] (dma_pool_alloc+0xc8/0x1b8)
> [    2.613067] [<c00d84a8>] (dma_pool_alloc) from [<c0317120>] (xhci_alloc_container_ctx+0x70/0xe0)
> [    2.621851] [<c0317120>] (xhci_alloc_container_ctx) from [<c03194e8>] (xhci_alloc_virt_device+0x98/0x220)
> [    2.631418] [<c03194e8>] (xhci_alloc_virt_device) from [<c0315d28>] (xhci_alloc_dev+0x158/0x1f0)
> [    2.640207] [<c0315d28>] (xhci_alloc_dev) from [<c02f6310>] (usb_alloc_dev+0x1d4/0x27c)
> [    2.648217] [<c02f6310>] (usb_alloc_dev) from [<c02fb204>] (hub_thread+0x670/0x1204)
> [    2.655943] [<c02fb204>] (hub_thread) from [<c003d8d8>] (kthread+0xcc/0xe8)
> [    2.662906] [<c003d8d8>] (kthread) from [<c000e2f8>] (ret_from_fork+0x14/0x3c)
>
> Anyone else sees the same thing?

Either disable interrupts or use mod_zone_page_state instead.

This should fix it:




Subject: vmscan: reclaim_clean_pages_from_list must use mod_zone_page_state

Seems to be called with preemption enabled. Therefore it must use
mod_zone_page_state instead.

Signed-off-by: Christoph Lameter <cl@linux.com>

Index: linux/mm/vmscan.c
===================================================================
--- linux.orig/mm/vmscan.c	2014-04-09 11:35:43.917930976 -0500
+++ linux/mm/vmscan.c	2014-04-14 12:09:48.070745938 -0500
@@ -1158,7 +1158,7 @@ unsigned long reclaim_clean_pages_from_l
 			TTU_UNMAP|TTU_IGNORE_ACCESS,
 			&dummy1, &dummy2, &dummy3, &dummy4, &dummy5, true);
 	list_splice(&clean_pages, page_list);
-	__mod_zone_page_state(zone, NR_ISOLATED_FILE, -ret);
+	mod_zone_page_state(zone, NR_ISOLATED_FILE, -ret);
 	return ret;
 }

[3.15-rc1] a huge number of warnings produced by xhci &

[Grygorii Strashko]

On 04/14/2014 08:12 PM, Christoph Lameter wrote:
> n Mon, 14 Apr 2014, Grygorii Strashko wrote:
>
>> Hi All,
>>
>> I'm observing a huge number of warnings produced during the boot of my Keystone 2 board
>> when USB is enabled.
>>
>> [    2.496460] BUG: using __this_cpu_read() in preemptible [00000000] code: khubd/202
>> [    2.504030] caller is __mod_zone_page_state+0x20/0xc8
>> [    2.509094] CPU: 1 PID: 202 Comm: khubd Not tainted 3.15.0-rc1-00015-ge521fa3-dirty #55
>> [    2.517122] [<c0013788>] (unwind_backtrace) from [<c001129c>] (show_stack+0x10/0x14)
>> [    2.524854] [<c001129c>] (show_stack) from [<c049f800>] (dump_stack+0x68/0xb8)
>> [    2.532086] [<c049f800>] (dump_stack) from [<c02731c0>] (check_preemption_disabled+0xe8/0x10c)
>> [    2.540708] [<c02731c0>] (check_preemption_disabled) from [<c00bc944>] (__mod_zone_page_state+0x20/0xc8)
>> [    2.550187] [<c00bc944>] (__mod_zone_page_state) from [<c00b50c8>] (reclaim_clean_pages_from_list+0x16c/0x178)
>> [    2.560193] [<c00b50c8>] (reclaim_clean_pages_from_list) from [<c00ac8f0>] (alloc_contig_range+0x10c/0x2d0)
>> [    2.569932] [<c00ac8f0>] (alloc_contig_range) from [<c02b0e58>] (dma_alloc_from_contiguous+0x70/0x118)
>> [    2.579241] [<c02b0e58>] (dma_alloc_from_contiguous) from [<c0017d24>] (__alloc_from_contiguous+0x34/0x160)
>> [    2.588974] [<c0017d24>] (__alloc_from_contiguous) from [<c0018760>] (__dma_alloc+0x18c/0x294)
>> [    2.597582] [<c0018760>] (__dma_alloc) from [<c00189f0>] (arm_dma_alloc+0xac/0xd8)
>> [    2.605140] [<c00189f0>] (arm_dma_alloc) from [<c00d84a8>] (dma_pool_alloc+0xc8/0x1b8)
>> [    2.613067] [<c00d84a8>] (dma_pool_alloc) from [<c0317120>] (xhci_alloc_container_ctx+0x70/0xe0)
>> [    2.621851] [<c0317120>] (xhci_alloc_container_ctx) from [<c03194e8>] (xhci_alloc_virt_device+0x98/0x220)
>> [    2.631418] [<c03194e8>] (xhci_alloc_virt_device) from [<c0315d28>] (xhci_alloc_dev+0x158/0x1f0)
>> [    2.640207] [<c0315d28>] (xhci_alloc_dev) from [<c02f6310>] (usb_alloc_dev+0x1d4/0x27c)
>> [    2.648217] [<c02f6310>] (usb_alloc_dev) from [<c02fb204>] (hub_thread+0x670/0x1204)
>> [    2.655943] [<c02fb204>] (hub_thread) from [<c003d8d8>] (kthread+0xcc/0xe8)
>> [    2.662906] [<c003d8d8>] (kthread) from [<c000e2f8>] (ret_from_fork+0x14/0x3c)
>>
>> Anyone else sees the same thing?
>
> Either disable interrupts or use mod_zone_page_state instead.
>
> This should fix it:
>
>
>
>
> Subject: vmscan: reclaim_clean_pages_from_list must use mod_zone_page_state
>
> Seems to be called with preemption enabled. Therefore it must use
> mod_zone_page_state instead.
>
> Signed-off-by: Christoph Lameter <cl@linux.com>

This patch fixes issue for me on Keystone 2, thanks.
Tested-by: Grygorii Strashko <grygorii.strashko@ti.com>

>
> Index: linux/mm/vmscan.c
> ===================================================================
> --- linux.orig/mm/vmscan.c	2014-04-09 11:35:43.917930976 -0500
> +++ linux/mm/vmscan.c	2014-04-14 12:09:48.070745938 -0500
> @@ -1158,7 +1158,7 @@ unsigned long reclaim_clean_pages_from_l
>   			TTU_UNMAP|TTU_IGNORE_ACCESS,
>   			&dummy1, &dummy2, &dummy3, &dummy4, &dummy5, true);
>   	list_splice(&clean_pages, page_list);
> -	__mod_zone_page_state(zone, NR_ISOLATED_FILE, -ret);
> +	mod_zone_page_state(zone, NR_ISOLATED_FILE, -ret);
>   	return ret;
>   }
>