- Fix stack overflow for large values of MAX_APICS

PATCH In review Jack Steiner 3 participants 10 messages Jun 20, 2008 – Jun 26, 2008

Subsystems (2)

Memory management x86

lore

Share & tools

lore

Jack Steiner

author

2008-06-20 02:51 UTC #0 lore raw

PATCH 1/1 - Fix stack overflow for large values of MAX_APICS

physid_mask_of_physid() causes a huge stack (12k) to be created if the number of APICS is large. Replace physid_mask_of_physid() with a new function that does not create large stacks. This is a problem only on large x86_64 systems.

Signed-off-by Jack Steiner <[email protected]>

---

Ingo - the "Increase MAX_APICS patch" can now works. Do you want me to resend???

 arch/x86/kernel/apic_32.c |    2 +-
 arch/x86/kernel/apic_64.c |    2 +-
 arch/x86/kernel/smpboot.c |    5 ++---
 include/asm-x86/mpspec.h  |    7 +++++++
 4 files changed, 11 insertions(+), 5 deletions(-)

arch/x86/kernel/apic_32.c +1 -1

Index: linux/arch/x86/kernel/apic_32.c
===================================================================
@@ -1267,7 +1267,7 @@ int __init APIC_init_uniprocessor(void)
 #ifdef CONFIG_CRASH_DUMP
 	boot_cpu_physical_apicid = GET_APIC_ID(read_apic_id());
 #endif
-	phys_cpu_present_map = physid_mask_of_physid(boot_cpu_physical_apicid);
+	physid_set_mask_of_physid(boot_cpu_physical_apicid, &phys_cpu_present_map);
 
 	setup_local_APIC();

arch/x86/kernel/apic_64.c +1 -1

Index: linux/arch/x86/kernel/apic_64.c
===================================================================
@@ -920,7 +920,7 @@ int __init APIC_init_uniprocessor(void)
 
 	connect_bsp_APIC();
 
-	phys_cpu_present_map = physid_mask_of_physid(boot_cpu_physical_apicid);
+	physid_set_mask_of_physid(boot_cpu_physical_apicid, &phys_cpu_present_map);
 	apic_write(APIC_ID, SET_APIC_ID(boot_cpu_physical_apicid));
 
 	setup_local_APIC();

arch/x86/kernel/smpboot.c +2 -3

Index: linux/arch/x86/kernel/smpboot.c
===================================================================
@@ -1042,10 +1042,9 @@ static __init void disable_smp(void)
 	smpboot_clear_io_apic_irqs();
 
 	if (smp_found_config)
-		phys_cpu_present_map =
-				physid_mask_of_physid(boot_cpu_physical_apicid);
+		physid_set_mask_of_physid(boot_cpu_physical_apicid, &phys_cpu_present_map);
 	else
-		phys_cpu_present_map = physid_mask_of_physid(0);
+		physid_set_mask_of_physid(0, &phys_cpu_present_map);
 	map_cpu_to_logical_apicid();
 	cpu_set(0, per_cpu(cpu_sibling_map, 0));
 	cpu_set(0, per_cpu(cpu_core_map, 0));

include/asm-x86/mpspec.h +7 -0

Index: linux/include/asm-x86/mpspec.h
===================================================================
@@ -122,6 +122,7 @@ typedef struct physid_mask physid_mask_t
 		__physid_mask;						\
 	})
 
+/* Note: will create very large stack frames if physid_mask_t is big */
 #define physid_mask_of_physid(physid)					\
 	({								\
 		physid_mask_t __physid_mask = PHYSID_MASK_NONE;		\

@@ -129,6 +130,12 @@ typedef struct physid_mask physid_mask_t
 		__physid_mask;						\
 	})
 
+static inline void physid_set_mask_of_physid(int physid, physid_mask_t *map)
+{
+	physids_clear(*map);
+	physid_set(physid, *map);
+}
+
 #define PHYSID_MASK_ALL		{ {[0 ... PHYSID_ARRAY_SIZE-1] = ~0UL} }
 #define PHYSID_MASK_NONE	{ {[0 ... PHYSID_ARRAY_SIZE-1] = 0UL} }

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in the body to [email protected]. For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"[email protected]"> [email protected] </a>

Ingo Molnar

2008-06-20 10:27 UTC #1 lore raw

Quoted 4 lines · Jack Steiner

physid_mask_of_physid() causes a huge stack (12k) to be created if the number of APICS is large. Replace physid_mask_of_physid() with a new function that does not create large stacks. This is a problem only on large x86_64 systems.

ah, that indeed makes sense. Applied to tip/x86/uv - thanks Jack.

Quoted 2 lines

Ingo - the "Increase MAX_APICS patch" can now works. Do you want me to resend???

no need, i have reactivated it in tip/x86/uv. (after your physid_mask_of_physid() patch, so that it's still all bisectable)

Ingo

Ingo Molnar

2008-06-20 10:39 UTC #2 lore raw

In reply to Jack Steiner

Quoted 4 lines · Jack Steiner

physid_mask_of_physid() causes a huge stack (12k) to be created if the number of APICS is large. Replace physid_mask_of_physid() with a new function that does not create large stacks. This is a problem only on large x86_64 systems.

this indeed fixes the crash i reported here:

http://lkml.org/lkml/2008/6/19/98

so i've added both this and the MAXAPICS patch to tip/x86/uv, and will test it some more. Lets hope it goes all well this time :-)

btw., it would be nice to have an ftrace plugin that prints out the worst-case stack footprint and generates an assert if we overflow the stack. -rt's kernel/latency_trace.c used to have that feature. That way incidents like this would be detected on the spot by -tip's auto-testing. The code in question is in kernel/trace/ftrace.c (and other nearby code).

Ingo

Ingo Molnar

2008-06-24 10:24 UTC #3 lore raw

Quoted 7 lines · Ingo Molnar

Quoted 4 lines · Jack Steiner
physid_mask_of_physid() causes a huge stack (12k) to be created if the number of APICS is large. Replace physid_mask_of_physid() with a new function that does not create large stacks. This is a problem only on large x86_64 systems.

Quoted 6 lines

this indeed fixes the crash i reported here:
   http://lkml.org/lkml/2008/6/19/98
so i've added both this and the MAXAPICS patch to tip/x86/uv, and will test it some more. Lets hope it goes all well this time :-)

-tip auto-testing found a new boot failure on x86 which happens if NR_CPUS is changed from 8 to 4096. The hang goes like this:

Linux version 2.6.26-rc7-tip (mingo@dione) (gcc version 4.2.3) #10233 SMP Tue Jun 24 12:13:46 CEST 2008
[...]
initcall init_mnt_writers+0x0/0x8c returned 0 after 0 msecs calling eventpoll_init+0x0/0x9a
initcall eventpoll_init+0x0/0x9a returned 0 after 0 msecs calling anon_inode_init+0x0/0x11a
initcall anon_inode_init+0x0/0x11a returned 0 after 0 msecs calling pcie_aspm_init+0x0/0x27
initcall pcie_aspm_init+0x0/0x27 returned 0 after 0 msecs calling acpi_event_init+0x0/0x57
[... hard hang ...]

on a good bootup, it would continue like this:

initcall acpi_event_init+0x0/0x57 returned 0 after 38 msecs calling pnp_system_init+0x0/0x17
[...]

the config, full bootlog and reproducer bzImage is at:

http://redhat.com/~mingo/misc/config-Tue_Jun_24_07_44_17_CEST_2008.bad
http://redhat.com/~mingo/misc/log-Tue_Jun_24_07_44_17_CEST_2008.bad
http://redhat.com/~mingo/misc/bzImage-Tue_Jun_24_07_44_17_CEST_2008.bad

changing CONFIG_NR_CPUS from 4096 to 8 causes the system to boot up fine.

Ingo

Jack Steiner

author

2008-06-24 22:03 UTC #4 lore raw

Quoted 12 lines · Ingo Molnar

Quoted 9 lines · Ingo Molnar
Quoted 4 lines · Jack Steiner
physid_mask_of_physid() causes a huge stack (12k) to be created if the number of APICS is large. Replace physid_mask_of_physid() with a new function that does not create large stacks. This is a problem only on large x86_64 systems.
this indeed fixes the crash i reported here:

Quoted 8 lines

Quoted 4 lines
   http://lkml.org/lkml/2008/6/19/98
so i've added both this and the MAXAPICS patch to tip/x86/uv, and will test it some more. Lets hope it goes all well this time :-)
-tip auto-testing found a new boot failure on x86 which happens if NR_CPUS is changed from 8 to 4096. The hang goes like this:

Still looking but here is what I have found so far.

The most obvious change was to revert the patch that changed MAX_APICS to 32k. With this patch reverted, the system still hangs at the same spot.

I noticed that the hang is random. It usually occurs at acpi_event_init() but sometimes it hangs at a different place.

I also observed that the hang does not always occur. The system will boot to the point of mounting /root, then panics because the mount fails. I expect that this is a different failure due to missing drivers. I'll chase that down later.

I added trace code & isolated the hang to a call to synchronize_rcu(). Usually from netlink_change_ngroups().

If I boot with "maxcpus=1, it never hangs (obviously) but always fails to mount /root.

Next I changed NR_CPUS to 128. I still see random hangs at the call to acpi_event_init().

I'll chase this more tomorrow. Has anyone else seen any failures that might be related???

Quoted 21 lines

Linux version 2.6.26-rc7-tip (mingo@dione) (gcc version 4.2.3) #10233 SMP Tue Jun 24 12:13:46 CEST 2008
[...]
initcall init_mnt_writers+0x0/0x8c returned 0 after 0 msecs calling eventpoll_init+0x0/0x9a
initcall eventpoll_init+0x0/0x9a returned 0 after 0 msecs calling anon_inode_init+0x0/0x11a
initcall anon_inode_init+0x0/0x11a returned 0 after 0 msecs calling pcie_aspm_init+0x0/0x27
initcall pcie_aspm_init+0x0/0x27 returned 0 after 0 msecs calling acpi_event_init+0x0/0x57
[... hard hang ...]
on a good bootup, it would continue like this:
initcall acpi_event_init+0x0/0x57 returned 0 after 38 msecs calling pnp_system_init+0x0/0x17
[...]
the config, full bootlog and reproducer bzImage is at:

Quoted 8 lines

http://redhat.com/~mingo/misc/config-Tue_Jun_24_07_44_17_CEST_2008.bad
http://redhat.com/~mingo/misc/log-Tue_Jun_24_07_44_17_CEST_2008.bad
http://redhat.com/~mingo/misc/bzImage-Tue_Jun_24_07_44_17_CEST_2008.bad
changing CONFIG_NR_CPUS from 4096 to 8 causes the system to boot up fine.
Ingo

Jack Steiner

author

2008-06-25 20:56 UTC #5 lore raw

In reply to Ingo Molnar

Quoted 25 lines

Quoted 25 lines
Quoted 4 lines
-tip auto-testing found a new boot failure on x86 which happens if NR_CPUS is changed from 8 to 4096. The hang goes like this:
Still looking but here is what I have found so far.
The most obvious change was to revert the patch that changed MAX_APICS to 32k. With this patch reverted, the system still hangs at the same spot.
I also noticed that the hang is random. It usually occurs at acpi_event_init() but sometimes it hangs at a different place.
I also observed that the failure sometimes does not occur. The system boots to the point that mounting /root fails, then panics because the mount fails. I expect that this is a different failure due to missing drivers. I'll chase that down later.
I added trace code & isolated the hang to a call to synchronize_rcu(). Usually from netlink_change_ngroups().
If I boot with "maxcpus=1, it never hangs (obviously) but always fails to mount /root.

Quoted 7 lines

Quoted 7 lines
Next I changed NR_CPUS to 128. I still see random hangs.
I'll chase this more tomorrow. Has anyone else seen any failures that might be related???

Is this already fixed? I see a number of patches to this area have been merged since the failure occurred.

I added enough hacks to get backtraces on threads at the time a hang occurs. show_state() shows 79 "kstopmachine" tasks. Most have one of the following backtraces:

	<6>kstopmachine  R  running task     6400   375    369
	 ffff8101ad28bd80 ffffffff8068c5c6 ffff8101ad28bb20 0000000000000002
	 0000000000000046 0000000000000000 0000000000002f42 ffff8101ad28c8b8
	 ffff8101ad28bb90 ffffffff80254fac 0000000100000000 0000000000000000
	Call Trace:
	   [<ffffffff8068c5c6>] ? thread_return+0x4d/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8022cf41>] ? update_curr_rt+0x111/0x11a
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c806>] wait_for_common+0x150/0x160
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8023422b>] ? sys_sched_yield+0x0/0x6e
	   [<ffffffff8026736d>] ? stopmachine+0xaf/0xda
	   [<ffffffff8020d558>] ? child_rip+0xa/0x12
	   [<ffffffff802672be>] ? stopmachine+0x0/0xda
	   [<ffffffff8020d54e>] ? child_rip+0x0/0x12

	<6>kstopmachine  ? 0000000000000000  6400   367      1
	  ffff8101af9b9ee0 0000000000000046 0000000000000000 0000000000000000
	  0000000000000000 ffff8101af9b4000 ffff8101afdc0000 ffff8101af9b4540
	  0000000600000000 00000000ffff909f ffffffffffffffff ffffffffffffffff
	Call Trace:
	     [<ffffffff8023be98>] do_exit+0x6fe/0x702
	     [<ffffffff8020d55f>] child_rip+0x11/0x12
	     [<ffffffff802672be>] ? stopmachine+0x0/0xda
	     [<ffffffff8020d54e>] ? child_rip+0x0/0x12

The boot thread shows:

	 <6>swapper       D 0000000000000002  2640     1      0
	  ffff8101afc3fcd0 0000000000000046 ffffffff807d8341 0000000000000200
	  ffffffff807d8335 ffff8101afc40000 ffff8101ad284000 ffff8101afc40540
	  00000005afc3faa0 ffffffff8021e837 ffff8101afc3fab0 ffff8101afc3fd50

	 [<ffffffff8068c961>] schedule_timeout+0x27/0xb9
	 [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	 [<ffffffff8068c79c>] wait_for_common+0xe6/0x160
	 [<ffffffff8022d88a>] ? default_wake_function+0x0/0xf
	 [<ffffffff8068c8a0>] wait_for_completion+0x18/0x1a
	 [<ffffffff8024981a>] synchronize_rcu+0x3a/0x41
	 [<ffffffff802498a3>] ? wakeme_after_rcu+0x0/0x15
	 [<ffffffff805d8e1b>] netlink_change_ngroups+0xce/0xfc
	 [<ffffffff805da2c9>] genl_register_mc_group+0xfd/0x160
	 [<ffffffff80ac6d5d>] ? acpi_event_init+0x0/0x57
	 [<ffffffff80ac6d92>] acpi_event_init+0x35/0x57
	 [<ffffffff80aaca8c>] kernel_init+0x1c5/0x31f

Is this hang already fixed or should I dig deeper?

--- jack

Ingo Molnar

2008-06-26 12:32 UTC #6 lore raw

Quoted 77 lines · Jack Steiner

Quoted 6 lines

Quoted 6 lines
I added trace code & isolated the hang to a call to synchronize_rcu(). Usually from netlink_change_ngroups().
If I boot with "maxcpus=1, it never hangs (obviously) but always fails to mount /root.

Quoted 7 lines

Quoted 7 lines
Next I changed NR_CPUS to 128. I still see random hangs.
I'll chase this more tomorrow. Has anyone else seen any failures that might be related???

Is this already fixed? I see a number of patches to this area have been merged since the failure occurred.

I added enough hacks to get backtraces on threads at the time a hang occurs. show_state() shows 79 "kstopmachine" tasks. Most have one of the following backtraces:

	<6>kstopmachine  R  running task     6400   375    369
	 ffff8101ad28bd80 ffffffff8068c5c6 ffff8101ad28bb20 0000000000000002
	 0000000000000046 0000000000000000 0000000000002f42 ffff8101ad28c8b8
	 ffff8101ad28bb90 ffffffff80254fac 0000000100000000 0000000000000000
	Call Trace:
	   [<ffffffff8068c5c6>] ? thread_return+0x4d/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8022cf41>] ? update_curr_rt+0x111/0x11a
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c806>] wait_for_common+0x150/0x160
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8023422b>] ? sys_sched_yield+0x0/0x6e
	   [<ffffffff8026736d>] ? stopmachine+0xaf/0xda
	   [<ffffffff8020d558>] ? child_rip+0xa/0x12
	   [<ffffffff802672be>] ? stopmachine+0x0/0xda
	   [<ffffffff8020d54e>] ? child_rip+0x0/0x12

	<6>kstopmachine  ? 0000000000000000  6400   367      1
	  ffff8101af9b9ee0 0000000000000046 0000000000000000 0000000000000000
	  0000000000000000 ffff8101af9b4000 ffff8101afdc0000 ffff8101af9b4540
	  0000000600000000 00000000ffff909f ffffffffffffffff ffffffffffffffff
	Call Trace:
	     [<ffffffff8023be98>] do_exit+0x6fe/0x702
	     [<ffffffff8020d55f>] child_rip+0x11/0x12
	     [<ffffffff802672be>] ? stopmachine+0x0/0xda
	     [<ffffffff8020d54e>] ? child_rip+0x0/0x12

The boot thread shows:

	 <6>swapper       D 0000000000000002  2640     1      0
	  ffff8101afc3fcd0 0000000000000046 ffffffff807d8341 0000000000000200
	  ffffffff807d8335 ffff8101afc40000 ffff8101ad284000 ffff8101afc40540
	  00000005afc3faa0 ffffffff8021e837 ffff8101afc3fab0 ffff8101afc3fd50

	 [<ffffffff8068c961>] schedule_timeout+0x27/0xb9
	 [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	 [<ffffffff8068c79c>] wait_for_common+0xe6/0x160
	 [<ffffffff8022d88a>] ? default_wake_function+0x0/0xf
	 [<ffffffff8068c8a0>] wait_for_completion+0x18/0x1a
	 [<ffffffff8024981a>] synchronize_rcu+0x3a/0x41
	 [<ffffffff802498a3>] ? wakeme_after_rcu+0x0/0x15
	 [<ffffffff805d8e1b>] netlink_change_ngroups+0xce/0xfc
	 [<ffffffff805da2c9>] genl_register_mc_group+0xfd/0x160
	 [<ffffffff80ac6d5d>] ? acpi_event_init+0x0/0x57
	 [<ffffffff80ac6d92>] acpi_event_init+0x35/0x57
	 [<ffffffff80aaca8c>] kernel_init+0x1c5/0x31f

Quoted 1 line

Is this hang already fixed or should I dig deeper?

there's no known hang in tip/master. I.e. removing your MAX_APICS patch clearly resolved that crash.

Ingo

Jack Steiner

author

2008-06-26 12:41 UTC #7 lore raw

Quoted 80 lines · Ingo Molnar

Quoted 77 lines · Jack Steiner

Quoted 6 lines

Quoted 6 lines
I added trace code & isolated the hang to a call to synchronize_rcu(). Usually from netlink_change_ngroups().
If I boot with "maxcpus=1, it never hangs (obviously) but always fails to mount /root.

Quoted 7 lines

Quoted 7 lines
Next I changed NR_CPUS to 128. I still see random hangs.
I'll chase this more tomorrow. Has anyone else seen any failures that might be related???

Is this already fixed? I see a number of patches to this area have been merged since the failure occurred.

I added enough hacks to get backtraces on threads at the time a hang occurs. show_state() shows 79 "kstopmachine" tasks. Most have one of the following backtraces:

	<6>kstopmachine  R  running task     6400   375    369
	 ffff8101ad28bd80 ffffffff8068c5c6 ffff8101ad28bb20 0000000000000002
	 0000000000000046 0000000000000000 0000000000002f42 ffff8101ad28c8b8
	 ffff8101ad28bb90 ffffffff80254fac 0000000100000000 0000000000000000
	Call Trace:
	   [<ffffffff8068c5c6>] ? thread_return+0x4d/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8022cf41>] ? update_curr_rt+0x111/0x11a
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c806>] wait_for_common+0x150/0x160
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8023422b>] ? sys_sched_yield+0x0/0x6e
	   [<ffffffff8026736d>] ? stopmachine+0xaf/0xda
	   [<ffffffff8020d558>] ? child_rip+0xa/0x12
	   [<ffffffff802672be>] ? stopmachine+0x0/0xda
	   [<ffffffff8020d54e>] ? child_rip+0x0/0x12

	<6>kstopmachine  ? 0000000000000000  6400   367      1
	  ffff8101af9b9ee0 0000000000000046 0000000000000000 0000000000000000
	  0000000000000000 ffff8101af9b4000 ffff8101afdc0000 ffff8101af9b4540
	  0000000600000000 00000000ffff909f ffffffffffffffff ffffffffffffffff
	Call Trace:
	     [<ffffffff8023be98>] do_exit+0x6fe/0x702
	     [<ffffffff8020d55f>] child_rip+0x11/0x12
	     [<ffffffff802672be>] ? stopmachine+0x0/0xda
	     [<ffffffff8020d54e>] ? child_rip+0x0/0x12

The boot thread shows:

	 <6>swapper       D 0000000000000002  2640     1      0
	  ffff8101afc3fcd0 0000000000000046 ffffffff807d8341 0000000000000200
	  ffffffff807d8335 ffff8101afc40000 ffff8101ad284000 ffff8101afc40540
	  00000005afc3faa0 ffffffff8021e837 ffff8101afc3fab0 ffff8101afc3fd50

	 [<ffffffff8068c961>] schedule_timeout+0x27/0xb9
	 [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	 [<ffffffff8068c79c>] wait_for_common+0xe6/0x160
	 [<ffffffff8022d88a>] ? default_wake_function+0x0/0xf
	 [<ffffffff8068c8a0>] wait_for_completion+0x18/0x1a
	 [<ffffffff8024981a>] synchronize_rcu+0x3a/0x41
	 [<ffffffff802498a3>] ? wakeme_after_rcu+0x0/0x15
	 [<ffffffff805d8e1b>] netlink_change_ngroups+0xce/0xfc
	 [<ffffffff805da2c9>] genl_register_mc_group+0xfd/0x160
	 [<ffffffff80ac6d5d>] ? acpi_event_init+0x0/0x57
	 [<ffffffff80ac6d92>] acpi_event_init+0x35/0x57
	 [<ffffffff80aaca8c>] kernel_init+0x1c5/0x31f

Quoted 4 lines

Quoted 1 line
Is this hang already fixed or should I dig deeper?
there's no known hang in tip/master. I.e. removing your MAX_APICS patch clearly resolved that crash.

Hmmm. I'm puzzled. With the tip/master tree that I built earlier this week, I was able to get hangs both with & without the MAX_APICS patch. Although less frequent, I also got hangs with NR_CPUS=128 & without the MAX_APICS patch. I'm not certain that all hangs were identical to the above backtraces, but they all hung at about the same spot.

I'll build a new tip/master tree, apply the MAX_APICS patch and retest using your random config & boot options that caused the problem.

--- jack

Paul E. McKenney

2008-06-26 22:39 UTC #8 lore raw

Quoted 86 lines · Jack Steiner

Quoted 80 lines · Ingo Molnar

Quoted 77 lines · Jack Steiner

Quoted 6 lines

Quoted 6 lines
I added trace code & isolated the hang to a call to synchronize_rcu(). Usually from netlink_change_ngroups().
If I boot with "maxcpus=1, it never hangs (obviously) but always fails to mount /root.

Quoted 7 lines

Quoted 7 lines
Next I changed NR_CPUS to 128. I still see random hangs.
I'll chase this more tomorrow. Has anyone else seen any failures that might be related???

Is this already fixed? I see a number of patches to this area have been merged since the failure occurred.

I added enough hacks to get backtraces on threads at the time a hang occurs. show_state() shows 79 "kstopmachine" tasks. Most have one of the following backtraces:

	<6>kstopmachine  R  running task     6400   375    369
	 ffff8101ad28bd80 ffffffff8068c5c6 ffff8101ad28bb20 0000000000000002
	 0000000000000046 0000000000000000 0000000000002f42 ffff8101ad28c8b8
	 ffff8101ad28bb90 ffffffff80254fac 0000000100000000 0000000000000000
	Call Trace:
	   [<ffffffff8068c5c6>] ? thread_return+0x4d/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8022cf41>] ? update_curr_rt+0x111/0x11a
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c806>] wait_for_common+0x150/0x160
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8023422b>] ? sys_sched_yield+0x0/0x6e
	   [<ffffffff8026736d>] ? stopmachine+0xaf/0xda
	   [<ffffffff8020d558>] ? child_rip+0xa/0x12
	   [<ffffffff802672be>] ? stopmachine+0x0/0xda
	   [<ffffffff8020d54e>] ? child_rip+0x0/0x12

	<6>kstopmachine  ? 0000000000000000  6400   367      1
	  ffff8101af9b9ee0 0000000000000046 0000000000000000 0000000000000000
	  0000000000000000 ffff8101af9b4000 ffff8101afdc0000 ffff8101af9b4540
	  0000000600000000 00000000ffff909f ffffffffffffffff ffffffffffffffff
	Call Trace:
	     [<ffffffff8023be98>] do_exit+0x6fe/0x702
	     [<ffffffff8020d55f>] child_rip+0x11/0x12
	     [<ffffffff802672be>] ? stopmachine+0x0/0xda
	     [<ffffffff8020d54e>] ? child_rip+0x0/0x12

The boot thread shows:

	 <6>swapper       D 0000000000000002  2640     1      0
	  ffff8101afc3fcd0 0000000000000046 ffffffff807d8341 0000000000000200
	  ffffffff807d8335 ffff8101afc40000 ffff8101ad284000 ffff8101afc40540
	  00000005afc3faa0 ffffffff8021e837 ffff8101afc3fab0 ffff8101afc3fd50

	 [<ffffffff8068c961>] schedule_timeout+0x27/0xb9
	 [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	 [<ffffffff8068c79c>] wait_for_common+0xe6/0x160
	 [<ffffffff8022d88a>] ? default_wake_function+0x0/0xf
	 [<ffffffff8068c8a0>] wait_for_completion+0x18/0x1a
	 [<ffffffff8024981a>] synchronize_rcu+0x3a/0x41
	 [<ffffffff802498a3>] ? wakeme_after_rcu+0x0/0x15
	 [<ffffffff805d8e1b>] netlink_change_ngroups+0xce/0xfc
	 [<ffffffff805da2c9>] genl_register_mc_group+0xfd/0x160
	 [<ffffffff80ac6d5d>] ? acpi_event_init+0x0/0x57
	 [<ffffffff80ac6d92>] acpi_event_init+0x35/0x57
	 [<ffffffff80aaca8c>] kernel_init+0x1c5/0x31f

Quoted 4 lines

Quoted 1 line
Is this hang already fixed or should I dig deeper?
there's no known hang in tip/master. I.e. removing your MAX_APICS patch clearly resolved that crash.

Quoted 8 lines

Hmmm. I'm puzzled. With the tip/master tree that I built earlier this week, I was able to get hangs both with & without the MAX_APICS patch. Although less frequent, I also got hangs with NR_CPUS=128 & without the MAX_APICS patch. I'm not certain that all hangs were identical to the above backtraces, but they all hung at about the same spot.
I'll build a new tip/master tree, apply the MAX_APICS patch and retest using your random config & boot options that caused the problem.

Is the kstopmachine related to the synchronize_rcu()? A task that is running in a tight loop with irqs disabled (as stopmachine() seems to do, judging from the source code) will absolutely prevent RCU grace periods from completing.

So if the stop_machine() sequence gets stuck for whatever reason, RCU grace periods will get stuck as well.

Thanx, Paul

Jack Steiner

author

2008-06-26 22:58 UTC #9 lore raw

Quoted 96 lines · Paul E. McKenney

Quoted 86 lines · Jack Steiner
Quoted 80 lines · Ingo Molnar
Quoted 77 lines · Jack Steiner
Quoted 6 lines
Quoted 6 lines
I added trace code & isolated the hang to a call to synchronize_rcu(). Usually from netlink_change_ngroups().
If I boot with "maxcpus=1, it never hangs (obviously) but always fails to mount /root.
Quoted 7 lines
Quoted 7 lines
Next I changed NR_CPUS to 128. I still see random hangs.
I'll chase this more tomorrow. Has anyone else seen any failures that might be related???
Is this already fixed? I see a number of patches to this area have been merged since the failure occurred.
I added enough hacks to get backtraces on threads at the time a hang occurs. show_state() shows 79 "kstopmachine" tasks. Most have one of the following backtraces:
	<6>kstopmachine  R  running task     6400   375    369
	 ffff8101ad28bd80 ffffffff8068c5c6 ffff8101ad28bb20 0000000000000002
	 0000000000000046 0000000000000000 0000000000002f42 ffff8101ad28c8b8
	 ffff8101ad28bb90 ffffffff80254fac 0000000100000000 0000000000000000
	Call Trace:
	   [<ffffffff8068c5c6>] ? thread_return+0x4d/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8022cf41>] ? update_curr_rt+0x111/0x11a
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff8068c5f2>] ? thread_return+0x79/0xbd
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8068c806>] wait_for_common+0x150/0x160
	   [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	   [<ffffffff80254fac>] ? __lock_acquire+0x643/0x6ad
	   [<ffffffff80212507>] ? sched_clock+0x9/0xc
	   [<ffffffff8023422b>] ? sys_sched_yield+0x0/0x6e
	   [<ffffffff8026736d>] ? stopmachine+0xaf/0xda
	   [<ffffffff8020d558>] ? child_rip+0xa/0x12
	   [<ffffffff802672be>] ? stopmachine+0x0/0xda
	   [<ffffffff8020d54e>] ? child_rip+0x0/0x12

	<6>kstopmachine  ? 0000000000000000  6400   367      1
	  ffff8101af9b9ee0 0000000000000046 0000000000000000 0000000000000000
	  0000000000000000 ffff8101af9b4000 ffff8101afdc0000 ffff8101af9b4540
	  0000000600000000 00000000ffff909f ffffffffffffffff ffffffffffffffff
	Call Trace:
	     [<ffffffff8023be98>] do_exit+0x6fe/0x702
	     [<ffffffff8020d55f>] child_rip+0x11/0x12
	     [<ffffffff802672be>] ? stopmachine+0x0/0xda
	     [<ffffffff8020d54e>] ? child_rip+0x0/0x12
The boot thread shows:
	 <6>swapper       D 0000000000000002  2640     1      0
	  ffff8101afc3fcd0 0000000000000046 ffffffff807d8341 0000000000000200
	  ffffffff807d8335 ffff8101afc40000 ffff8101ad284000 ffff8101afc40540
	  00000005afc3faa0 ffffffff8021e837 ffff8101afc3fab0 ffff8101afc3fd50

	 [<ffffffff8068c961>] schedule_timeout+0x27/0xb9
	 [<ffffffff8068ef48>] ? _spin_unlock_irq+0x2b/0x37
	 [<ffffffff8068c79c>] wait_for_common+0xe6/0x160
	 [<ffffffff8022d88a>] ? default_wake_function+0x0/0xf
	 [<ffffffff8068c8a0>] wait_for_completion+0x18/0x1a
	 [<ffffffff8024981a>] synchronize_rcu+0x3a/0x41
	 [<ffffffff802498a3>] ? wakeme_after_rcu+0x0/0x15
	 [<ffffffff805d8e1b>] netlink_change_ngroups+0xce/0xfc
	 [<ffffffff805da2c9>] genl_register_mc_group+0xfd/0x160
	 [<ffffffff80ac6d5d>] ? acpi_event_init+0x0/0x57
	 [<ffffffff80ac6d92>] acpi_event_init+0x35/0x57
	 [<ffffffff80aaca8c>] kernel_init+0x1c5/0x31f
Quoted 4 lines
Quoted 1 line
Is this hang already fixed or should I dig deeper?
there's no known hang in tip/master. I.e. removing your MAX_APICS patch clearly resolved that crash.
Quoted 8 lines
Hmmm. I'm puzzled. With the tip/master tree that I built earlier this week, I was able to get hangs both with & without the MAX_APICS patch. Although less frequent, I also got hangs with NR_CPUS=128 & without the MAX_APICS patch. I'm not certain that all hangs were identical to the above backtraces, but they all hung at about the same spot.
I'll build a new tip/master tree, apply the MAX_APICS patch and retest using your random config & boot options that caused the problem.

Quoted 7 lines

Is the kstopmachine related to the synchronize_rcu()? A task that is running in a tight loop with irqs disabled (as stopmachine() seems to do, judging from the source code) will absolutely prevent RCU grace periods from completing.
So if the stop_machine() sequence gets stuck for whatever reason, RCU grace periods will get stuck as well.

I'm still debugging. (I'm learning a lot about debugging x86 systems - up to now I've worked mostly with IA64). Stopmachine is definitely part of the problem.

The failure mode is not always the same. In the most recent failure, RCU is not involved. The hang in stopmachine().

I see the following task spinning on cpu 7 at the time of the hang:

HUNG: registers 7
CPU 7:

Modules linked in:
Pid: 259, comm: kstopmachine Not tainted 2.6.26-rc8-tip-bug3 #8
Stime: 31957, LastSwitch 0, SwitchCount 0
RIP: 0010:[<ffffffff80688368>]  [<ffffffff80688368>] _spin_unlock_irq+0x33/0x37
RSP: 0000:ffff8101af50dc40  EFLAGS: 00000282
RAX: 0000000000000007 RBX: ffff8101af50dc50 RCX: 0000000000000000
RDX: 000000000000dee9 RSI: 00000000000002c1 RDI: 0000000000000000
RBP: ffff8101af508870 R08: 0000000000000001 R09: 0000000000000001
R10: 0000000000000001 R11: 0000000000000000 R12: ffff8101af508870
R13: 0000000000000002 R14: ffff8101af50dbc0 R15: ffffffff8022ccb1
FS:  0000000000000000(0000) GS:ffff8101afd226e0(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 0000000000000000 CR3: 0000000000201000 CR4: 00000000000006a0
DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400

Call Trace:
 [<ffffffff80685a0a>] ? thread_return+0x79/0xbd
 [<ffffffff80254d74>] ? __lock_acquire+0x643/0x6ad
 [<ffffffff802125af>] ? sched_clock+0x9/0xc
 [<ffffffff80685c1e>] ? wait_for_common+0x150/0x160
 [<ffffffff80688360>] ? _spin_unlock_irq+0x2b/0x37
 [<ffffffff80254d74>] ? __lock_acquire+0x643/0x6ad
 [<ffffffff802125af>] ? sched_clock+0x9/0xc
 [<ffffffff80233f9f>] ? sys_sched_yield+0x0/0x6e
 [<ffffffff80234007>] ? sys_sched_yield+0x68/0x6e
 [<ffffffff80685cd1>] ? yield+0x17/0x19
 [<ffffffff80267133>] ? stopmachine+0xad/0xda
 [<ffffffff8020d618>] ? child_rip+0xa/0x12
 [<ffffffff80267086>] ? stopmachine+0x0/0xda
 [<ffffffff8020d60e>] ? child_rip+0x0/0x12

Another task is:

kstopmachine R running task 6016 251 2 2
ffff8101af53dec0 0000000000000046 00000000000000fd ffff8101af538870 ffff8101af53dcb0 ffff8101af538000 ffff8101afcac000 ffff8101af538548 0000000200000000 ffff8101af538000 ffff8101af53dc90 0000000000000046

Call Trace:
 [<ffffffff802125af>] ? sched_clock+0x9/0xc
 [<ffffffff8023523d>] ? wake_up_new_task+0xef/0xf8
 [<ffffffff8023523d>] ? wake_up_new_task+0xef/0xf8
 [<ffffffff80237301>] ? do_fork+0x1b8/0x284
 [<ffffffff80254d74>] ? __lock_acquire+0x643/0x6ad
 [<ffffffff802125af>] ? sched_clock+0x9/0xc
 [<ffffffff80233f9f>] ? sys_sched_yield+0x0/0x6e
 [<ffffffff80234007>] sys_sched_yield+0x68/0x6e
 [<ffffffff80685cd1>] yield+0x17/0x19
 [<ffffffff80266fd3>] do_stop+0x87/0x13a
 [<ffffffff80266f4c>] ? do_stop+0x0/0x13a
 [<ffffffff80266f4c>] ? do_stop+0x0/0x13a
 [<ffffffff8024b7fe>] kthread+0x4e/0x7c
 [<ffffffff8020d618>] child_rip+0xa/0x12
 [<ffffffff8024b7b0>] ? kthread+0x0/0x7c
 [<ffffffff8020d60e>] ? child_rip+0x0/0x12

AFAICT, it is spinning in stopmachine() in the following loop:

	while (stopmachine_state != STOPMACHINE_EXIT)

stopmachine_state = 0
stopmachine_num_threads = 8
stopmachine_thread_ack = 7

Still looking. Should know more tomorrow.

--- jack