percpu: add preemption checks to __this_cpu ops
Subsystems (4)
PATCH 1/1 percpu: add preemption checks to __this_cpu ops
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 <[email protected]> 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.
[=== 1 ===]
If above patch is reverted - system can boot again.
[=== 2 ===]
If I apply below change - system can boot again.
lib/smp_processor_id.c +1 -4
@@ -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
Quoted 5 lines · Grygorii Strashko
lib/smp_processor_id.c +0
-0
lib/smp_processor_id.c EXPORT_SYMBOL(debug_smp_processor_id); · line 63
Quoted 10 lines
lib/smp_processor_id.c +1
-4@@ -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.
lib/smp_processor_id.c +6 -8
@@ -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);
Grygorii Strashko
Tested-byQuoted 8 lines · Christoph Lameter
Quoted 6 lines · Grygorii Strashko
lib/smp_processor_id.c +0
-0@@ -58,9 +58,6 @@ EXPORT_SYMBOL(debug_smp_processor_id);
Quoted 13 lines
lib/smp_processor_id.c line 64
Quoted 9 lines
lib/smp_processor_id.c +1
-4notrace 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.
Quoted 48 lines
We could fix this by moving the string concatenation operation into the check function.
Index:
linux/lib/smp_processor_id.c
===================================================================lib/smp_processor_id.c +6
-8@@ -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);
Christoph Lameter
Tested-by Grygorii StrashkoQuoted 2 lines · Grygorii Strashko
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.
lib/smp_processor_id.c +6 -8
@@ -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);
Andrew Morton
maintainerQuoted 11 lines · On Tue, 18 Mar 2014 10:54:06 -0500 (CDT) Christoph Lameter <[email protected]> wrote:
Quoted 2 lines · Grygorii Strashko
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 conditionssnprintf 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??
Quoted 5 lines
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 <[email protected]>
Grygorii, thanks for testing linux-next on unusual machines - it's most helpful.
Quoted 1 line
Signed-off-by Christoph Lameter <[email protected]>
Quoted 13 lines · On 03/18/2014 11:37 PM, Andrew Morton wrote:> On Tue, 18 Mar 2014 10:54:06…
Quoted 6 lines · Grygorii Strashko
Quoted 3 lines
Any way, I can boot and console works fine with your change :) Thanks.
Quoted 6 lines
Ok here is the properly formatted patch:
Subject:
preemption_checks: Avoid snprintf before checking error conditionssnprintf can cause hangs.
Quoted 7 lines
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 aWARN_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.
Quoted 3 lines
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];
Quoted 10 lines
Quoted 6 lines
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 <[email protected]>Grygorii, thanks for testing linux-next on unusual machines - it's most helpful.
Regards,
-grygorii
Quoted 7 lines · Andrew Morton
Quoted 1 line
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 aWARN_ON()which presumably didn't trigger anyway.
Quoted 5 lines
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 &
In reply to Grygorii StrashkoHi 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?
Regards,
-grygorii
Re: [3.15-rc1] a huge number of warnings produced by xhci &
Quoted 27 lines · Grygorii Strashko
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)
Quoted 1 line
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.
mm/vmscan.c +1 -1
@@ -1158,7 +1158,7 @@ unsigned long reclaim_clean_pages_from_lTTU_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; }
Grygorii Strashko
Tested-byRe: [3.15-rc1] a huge number of warnings produced by xhci &
Quoted 38 lines · Christoph Lameter
Quoted 27 lines · Grygorii Strashko
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)Quoted 1 line
Anyone else sees the same thing?
Either disable interrupts or use
mod_zone_page_stateinstead.This should fix it:
Quoted 6 lines
Subject: vmscan:
reclaim_clean_pages_from_listmust usemod_zone_page_stateSeems to be called with preemption enabled. Therefore it must use
mod_zone_page_stateinstead.Signed-off-by Christoph Lameter <[email protected]>
This patch fixes issue for me on Keystone 2, thanks.
Quoted 14 lines
Index:
linux/mm/vmscan.c
===================================================================mm/vmscan.c +1
-1@@ -1158,7 +1158,7 @@ unsigned long reclaim_clean_pages_from_lTTU_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; }