Skip to contentSkip to conversation

percpu: add preemption checks to __this_cpu ops

PATCH In review Grygorii Strashko 3 participants 10 messages Mar 18, 2014 – Apr 15, 2014

Subsystems (4)
lore
Share & tools
lore
#0 lore raw

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
index a270dce..73a2004 100644
@@ -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

#1 lore raw
Quoted 5 lines · Grygorii Strashko
lib/smp_processor_id.c +0 -0
index a270dce..73a2004 100644

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
Index: linux/lib/smp_processor_id.c
===================================================================
@@ -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);
author Tested-by
#2 lore raw
Quoted 8 lines · Christoph Lameter
Quoted 6 lines · Grygorii Strashko
lib/smp_processor_id.c +0 -0
index a270dce..73a2004 100644
@@ -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 -4
  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.

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);
Tested-by Grygorii Strashko
#3 lore raw
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 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
Index: linux/lib/smp_processor_id.c
===================================================================
@@ -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);
maintainer
#4 lore raw
Quoted 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 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??

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.

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

Quoted 1 line
#5 lore raw
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 conditions

snprintf 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 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.

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.

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

Regards,
-grygorii

#6 lore raw
In reply to Andrew Morton
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 a WARN_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.

#7 lore raw

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

In reply to 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)

Anyone else sees the same thing?

Regards,
-grygorii

#8 lore raw

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
Index: linux/mm/vmscan.c
===================================================================
@@ -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;
 }
author Tested-by
#9 lore raw

Re: [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_state instead.

This should fix it:

Quoted 6 lines

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.

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_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;
  }