LinuxLists.cc - [2.6.30-rc1] RCU detected CPU 1 stall

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Wed, Apr 08, 2009 at 09:57:35AM +0900, Tetsuo Handa wrote:
> Hello.
>
> I got this.
>
> [ 161.653269] INFO: RCU detected CPU 1 stall (t=4294932711/32565 jiffies)
> [ 161.655376] Pid: 3487, comm: khelper Tainted: G W 2.6.30-rc1 #1
> [ 161.655376] Call Trace:
> [ 161.659680] [<c015949d>] ? printk+0x1d/0x30
> [ 161.659680] [<c01b38b5>] print_cpu_stall+0x45/0xa0
> [ 161.663377] [<c01b39f8>] check_cpu_stall+0xe8/0x190
> [ 161.667409] [<c01ad59d>] ? get_timestamp+0xd/0x20
> [ 161.667409] [<c01b43ab>] __rcu_pending+0x1b/0x160
> [ 161.671679] [<c01b451e>] rcu_pending+0x2e/0x70
> [ 161.675680] [<c01692ab>] update_process_times+0x3b/0x80
> [ 161.675680] [<c018bcf0>] tick_periodic+0x40/0x90
> [ 161.679710] [<c018bd5e>] tick_handle_periodic+0x1e/0xa0
> [ 161.679710] [<c01045e0>] ? apic_timer_interrupt+0x28/0x34
> [ 161.683721] [<c012215f>] local_apic_timer_interrupt+0x6f/0x80
> [ 161.687390] [<c0161184>] ? irq_enter+0x14/0x60
> [ 161.691702] [<c05e7d83>] smp_apic_timer_interrupt+0x33/0x42
> [ 161.691702] [<c01045e7>] apic_timer_interrupt+0x2f/0x34
> [ 161.695378] [<c0225da4>] ? __bprm_mm_init+0xe4/0x120
> [ 161.699377] [<c0379c3d>] ? __get_user_4+0x11/0x17
> [ 161.699377] [<c0225f4e>] ? count+0x3e/0xb0
> [ 161.703696] [<c0228554>] do_execve+0x5f4/0x890
> [ 161.707390] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 161.707390] [<c010237e>] sys_execve+0x5e/0xb0
> [ 161.711705] [<c0103d19>] syscall_call+0x7/0xb
> [ 161.711705] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 161.715395] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 161.719736] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 161.723726] [<c0104707>] ? kernel_thread_helper+0x7/0x10
>
> Config is at http://I-love.SAKURA.ne.jp/tmp/config-2.6.30-rc1
> Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc1.txt

CONFIG_PREEMPT_NONE=y
CONFIG_CLASSIC_RCU=y
CONFIG_HZ_250=y

Hmmmm... This indicates that CPU 1 was spinning in the kernel for
a long time. At 250 HZ, 32,565 jiffies is 130 seconds, or just over
two -minutes-. Ouch!!!

The interrupt happened on the stalled CPU, so we know that interrupts
were enabled. Because we have CONFIG_PREEMPT_NONE=y, there is no
preemption, so preemption need not be disabled. This could be due
to lock contention, or even a simple infinite loop.

The timer interrupt (apic_timer_interrupt) occurred in either
__bprm_mm_init(), __get_user_4(), count(), or do_execve(). There
have been some recent changes around check_unsafe_exec() -- any
possibility that these introduced excessive lock contention or
an infinite loop? Ditto for the recent security fixes?

Thanx, Paul

2009-04-10 15:04:17

by Al Viro

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Fri, Apr 10, 2009 at 07:22:03AM -0700, Paul E. McKenney wrote:

> Hmmmm... This indicates that CPU 1 was spinning in the kernel for
> a long time. At 250 HZ, 32,565 jiffies is 130 seconds, or just over
> two -minutes-. Ouch!!!
>
> The interrupt happened on the stalled CPU, so we know that interrupts
> were enabled. Because we have CONFIG_PREEMPT_NONE=y, there is no
> preemption, so preemption need not be disabled. This could be due
> to lock contention, or even a simple infinite loop.
>
> The timer interrupt (apic_timer_interrupt) occurred in either
> __bprm_mm_init(), __get_user_4(), count(), or do_execve(). There
> have been some recent changes around check_unsafe_exec() -- any
> possibility that these introduced excessive lock contention or
> an infinite loop? Ditto for the recent security fixes?

Oh, joy... the loop in there is this:
for (t = next_thread(p); t != p; t = next_thread(t)) {
if (t->fs == p->fs)
n_fs++;
}
I find it hard to believe that it can take two minutes, though.

2009-04-10 15:32:49

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Fri, Apr 10, 2009 at 04:03:53PM +0100, Al Viro wrote:
> On Fri, Apr 10, 2009 at 07:22:03AM -0700, Paul E. McKenney wrote:
>
> > Hmmmm... This indicates that CPU 1 was spinning in the kernel for
> > a long time. At 250 HZ, 32,565 jiffies is 130 seconds, or just over
> > two -minutes-. Ouch!!!
> >
> > The interrupt happened on the stalled CPU, so we know that interrupts
> > were enabled. Because we have CONFIG_PREEMPT_NONE=y, there is no
> > preemption, so preemption need not be disabled. This could be due
> > to lock contention, or even a simple infinite loop.
> >
> > The timer interrupt (apic_timer_interrupt) occurred in either
> > __bprm_mm_init(), __get_user_4(), count(), or do_execve(). There
> > have been some recent changes around check_unsafe_exec() -- any
> > possibility that these introduced excessive lock contention or
> > an infinite loop? Ditto for the recent security fixes?
>
> Oh, joy... the loop in there is this:
> for (t = next_thread(p); t != p; t = next_thread(t)) {
> if (t->fs == p->fs)
> n_fs++;
> }
> I find it hard to believe that it can take two minutes, though.

Tetsuo, how many tasks did you have on this machine?

Though I too find it hard to believe that there were enough to chew up
two minutes. Maybe the list got corrupted so that it has a loop?

Thanx, Paul

2009-04-10 21:09:15

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

Hello.

Paul E. McKenney wrote:
> Tetsuo, how many tasks did you have on this machine?
I didn't count how many tasks were running on this machine.
But the number of tasks should be very low, for this happened during
the boot stage of Debian Sarge.

30 seconds ago from the first stalled message

[ 41.415158] INFO: RCU detected CPU 1 stall (t=4294902646/2500 jiffies)
[ 41.417332] Pid: 3487, comm: khelper Tainted: G W 2.6.30-rc1 #1
[ 41.417332] Call Trace:

the system was doing

[ 10.555521] kjournald starting. Commit interval 5 seconds
[ 10.556727] EXT3 FS on sdb1, internal journal
[ 10.556727] EXT3-fs: recovery complete.
[ 10.557585] EXT3-fs: mounted filesystem with writeback data mode.
/dev/sdb1 on /usr/src/all type ext3 (rw,noatime,nodiratime)
Detecting hardware: agpgart pcnet32 piix BusLogic ide_scsi
Skipping unavailable/built-in agpgart module.
pcnet32 disabled in configuration.
Skipping unavailable/built-in piix module.
Skipping unavailable/built-in BusLogic module.
Skipping unavailable/built-in ide_scsi module.
Running 0dns-down to make sure resolv.conf is ok...done.
Setting up networking...done.
Starting hotplug subsystem:
pci
ignoring pci display device 00:0f.0
[ 16.727603] ------------[ cut here ]------------
[ 16.729910] WARNING: at security/security.c:217 security_vm_enough_memory+0xa0/0xb0()

> Though I too find it hard to believe that there were enough to chew up
> two minutes. Maybe the list got corrupted so that it has a loop?

I powered off the machine after two minutes, for I thought the loop
was infinite.

2009-04-10 23:12:56

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Sat, Apr 11, 2009 at 06:08:54AM +0900, Tetsuo Handa wrote:
> Hello.
>
> Paul E. McKenney wrote:
> > Tetsuo, how many tasks did you have on this machine?
> I didn't count how many tasks were running on this machine.
> But the number of tasks should be very low, for this happened during
> the boot stage of Debian Sarge.
>
> 30 seconds ago from the first stalled message
>
> [ 41.415158] INFO: RCU detected CPU 1 stall (t=4294902646/2500 jiffies)
> [ 41.417332] Pid: 3487, comm: khelper Tainted: G W 2.6.30-rc1 #1
> [ 41.417332] Call Trace:
>
> the system was doing
>
> [ 10.555521] kjournald starting. Commit interval 5 seconds
> [ 10.556727] EXT3 FS on sdb1, internal journal
> [ 10.556727] EXT3-fs: recovery complete.
> [ 10.557585] EXT3-fs: mounted filesystem with writeback data mode.
> /dev/sdb1 on /usr/src/all type ext3 (rw,noatime,nodiratime)
> Detecting hardware: agpgart pcnet32 piix BusLogic ide_scsi
> Skipping unavailable/built-in agpgart module.
> pcnet32 disabled in configuration.
> Skipping unavailable/built-in piix module.
> Skipping unavailable/built-in BusLogic module.
> Skipping unavailable/built-in ide_scsi module.
> Running 0dns-down to make sure resolv.conf is ok...done.
> Setting up networking...done.
> Starting hotplug subsystem:
> pci
> ignoring pci display device 00:0f.0
> [ 16.727603] ------------[ cut here ]------------
> [ 16.729910] WARNING: at security/security.c:217 security_vm_enough_memory+0xa0/0xb0()
>
> > Though I too find it hard to believe that there were enough to chew up
> > two minutes. Maybe the list got corrupted so that it has a loop?
>
> I powered off the machine after two minutes, for I thought the loop
> was infinite.

Is this reproducible? If so, any chance you could try bisecting?

Thanx, Paul

2009-04-10 23:39:37

by Al Viro

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Fri, Apr 10, 2009 at 04:12:45PM -0700, Paul E. McKenney wrote:
> On Sat, Apr 11, 2009 at 06:08:54AM +0900, Tetsuo Handa wrote:
> > Hello.
> >
> > Paul E. McKenney wrote:
> > > Tetsuo, how many tasks did you have on this machine?
> > I didn't count how many tasks were running on this machine.
> > But the number of tasks should be very low, for this happened during
> > the boot stage of Debian Sarge.
> >
> > 30 seconds ago from the first stalled message
> >
> > [ 41.415158] INFO: RCU detected CPU 1 stall (t=4294902646/2500 jiffies)
> > [ 41.417332] Pid: 3487, comm: khelper Tainted: G W 2.6.30-rc1 #1
> > [ 41.417332] Call Trace:
> >
> > the system was doing
> >
> > [ 10.555521] kjournald starting. Commit interval 5 seconds
> > [ 10.556727] EXT3 FS on sdb1, internal journal
> > [ 10.556727] EXT3-fs: recovery complete.
> > [ 10.557585] EXT3-fs: mounted filesystem with writeback data mode.
> > /dev/sdb1 on /usr/src/all type ext3 (rw,noatime,nodiratime)
> > Detecting hardware: agpgart pcnet32 piix BusLogic ide_scsi
> > Skipping unavailable/built-in agpgart module.
> > pcnet32 disabled in configuration.
> > Skipping unavailable/built-in piix module.
> > Skipping unavailable/built-in BusLogic module.
> > Skipping unavailable/built-in ide_scsi module.
> > Running 0dns-down to make sure resolv.conf is ok...done.
> > Setting up networking...done.
> > Starting hotplug subsystem:
> > pci
> > ignoring pci display device 00:0f.0
> > [ 16.727603] ------------[ cut here ]------------
> > [ 16.729910] WARNING: at security/security.c:217 security_vm_enough_memory+0xa0/0xb0()
> >
> > > Though I too find it hard to believe that there were enough to chew up
> > > two minutes. Maybe the list got corrupted so that it has a loop?
> >
> > I powered off the machine after two minutes, for I thought the loop
> > was infinite.
>
> Is this reproducible? If so, any chance you could try bisecting?

If that's execve() hang, we probably have something->fs->lock stuck.
I don't see any likely candidates, but...

I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
to see where was it actually spinning.

2009-04-11 00:48:25

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Sat, Apr 11, 2009 at 12:39:20AM +0100, Al Viro wrote:
> On Fri, Apr 10, 2009 at 04:12:45PM -0700, Paul E. McKenney wrote:
> > On Sat, Apr 11, 2009 at 06:08:54AM +0900, Tetsuo Handa wrote:
> > > Hello.
> > >
> > > Paul E. McKenney wrote:
> > > > Tetsuo, how many tasks did you have on this machine?
> > > I didn't count how many tasks were running on this machine.
> > > But the number of tasks should be very low, for this happened during
> > > the boot stage of Debian Sarge.
> > >
> > > 30 seconds ago from the first stalled message
> > >
> > > [ 41.415158] INFO: RCU detected CPU 1 stall (t=4294902646/2500 jiffies)
> > > [ 41.417332] Pid: 3487, comm: khelper Tainted: G W 2.6.30-rc1 #1
> > > [ 41.417332] Call Trace:
> > >
> > > the system was doing
> > >
> > > [ 10.555521] kjournald starting. Commit interval 5 seconds
> > > [ 10.556727] EXT3 FS on sdb1, internal journal
> > > [ 10.556727] EXT3-fs: recovery complete.
> > > [ 10.557585] EXT3-fs: mounted filesystem with writeback data mode.
> > > /dev/sdb1 on /usr/src/all type ext3 (rw,noatime,nodiratime)
> > > Detecting hardware: agpgart pcnet32 piix BusLogic ide_scsi
> > > Skipping unavailable/built-in agpgart module.
> > > pcnet32 disabled in configuration.
> > > Skipping unavailable/built-in piix module.
> > > Skipping unavailable/built-in BusLogic module.
> > > Skipping unavailable/built-in ide_scsi module.
> > > Running 0dns-down to make sure resolv.conf is ok...done.
> > > Setting up networking...done.
> > > Starting hotplug subsystem:
> > > pci
> > > ignoring pci display device 00:0f.0
> > > [ 16.727603] ------------[ cut here ]------------
> > > [ 16.729910] WARNING: at security/security.c:217 security_vm_enough_memory+0xa0/0xb0()
> > >
> > > > Though I too find it hard to believe that there were enough to chew up
> > > > two minutes. Maybe the list got corrupted so that it has a loop?
> > >
> > > I powered off the machine after two minutes, for I thought the loop
> > > was infinite.
> >
> > Is this reproducible? If so, any chance you could try bisecting?
>
> If that's execve() hang, we probably have something->fs->lock stuck.
> I don't see any likely candidates, but...
>
> I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
> to see where was it actually spinning.

Even better!!! ;-)

Thanx, Paul

2009-04-13 00:51:16

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

Hello.

Paul E. McKenney wrote:
> Is this reproducible?
Not always, but it is reproducible.

Al Viro wrote:
> I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
> to see where was it actually spinning.
Below is sysrq message.
Maybe something related to khelper's current->mm == NULL warning problem.
Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc1-200904130930.txt .

[ 47.412519] SysRq : Show Regs
[ 47.413986]
[ 47.414584] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
[ 47.415804] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
[ 47.415804] EIP is at __get_user_4+0x11/0x17
[ 47.415804] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
[ 47.415804] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
[ 47.415804] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 47.415804] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
[ 47.415804] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 47.415804] DR6: ffff0ff0 DR7: 00000400
[ 47.415804] Call Trace:
[ 47.415804] [<c0225f4e>] ? count+0x3e/0xb0
[ 47.415804] [<c0228581>] do_execve+0x621/0x890
[ 47.415804] [<c022bd8b>] ? getname+0x6b/0xa0
[ 47.415804] [<c010237e>] sys_execve+0x5e/0xb0
[ 47.415804] [<c0103d19>] syscall_call+0x7/0xb
[ 47.415804] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 47.415804] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 47.415804] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 47.415804] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 52.551469] SysRq : Show backtrace of all active CPUs
[ 52.551803] CPU0:
[ 52.551803]
[ 52.551803] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
[ 52.551803] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
[ 52.551803] EIP is at __get_user_4+0x11/0x17
[ 52.551803] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
[ 52.551803] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
[ 52.551803] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 52.551803] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
[ 52.551803] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 52.551803] DR6: ffff0ff0 DR7: 00000400
[ 52.551803] Call Trace:
[ 52.551803] [<c0225f4e>] ? count+0x3e/0xb0
[ 52.551803] [<c0228581>] do_execve+0x621/0x890
[ 52.551803] [<c022bd8b>] ? getname+0x6b/0xa0
[ 52.551803] [<c010237e>] sys_execve+0x5e/0xb0
[ 52.551803] [<c0103d19>] syscall_call+0x7/0xb
[ 52.551803] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 52.551803] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 52.551803] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 52.551803] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 60.956967] SysRq : Show Regs
[ 60.958362]
[ 60.958896] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
[ 60.959802] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
[ 60.959802] EIP is at __get_user_4+0x11/0x17
[ 60.959802] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
[ 60.959802] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
[ 60.959802] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 60.959802] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
[ 60.959802] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 60.959802] DR6: ffff0ff0 DR7: 00000400
[ 60.959802] Call Trace:
[ 60.959802] [<c0225f4e>] ? count+0x3e/0xb0
[ 60.959802] [<c0228581>] do_execve+0x621/0x890
[ 60.959802] [<c022bd8b>] ? getname+0x6b/0xa0
[ 60.959802] [<c010237e>] sys_execve+0x5e/0xb0
[ 60.959802] [<c0103d19>] syscall_call+0x7/0xb
[ 60.959802] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 60.959802] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 60.959802] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 60.959802] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 69.014489] SysRq : Show backtrace of all active CPUs
[ 69.015802] CPU0:
[ 69.015802]
[ 69.015802] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
[ 69.015802] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
[ 69.015802] EIP is at __get_user_4+0x11/0x17
[ 69.015802] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
[ 69.015802] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
[ 69.015802] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 69.015802] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
[ 69.015802] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 69.015802] DR6: ffff0ff0 DR7: 00000400
[ 69.015802] Call Trace:
[ 69.015802] [<c0225f4e>] ? count+0x3e/0xb0
[ 69.015802] [<c0228581>] do_execve+0x621/0x890
[ 69.015802] [<c022bd8b>] ? getname+0x6b/0xa0
[ 69.015802] [<c010237e>] sys_execve+0x5e/0xb0
[ 69.015802] [<c0103d19>] syscall_call+0x7/0xb
[ 69.015802] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 69.015802] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 69.015802] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 69.015802] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 73.695801] INFO: RCU detected CPU 0 stall (t=4294910558/10000 jiffies)
[ 73.695801] Pid: 3655, comm: khelper Tainted: G W 2.6.30-rc1 #1
[ 73.695801] Call Trace:
[ 73.695801] [<c015949d>] ? printk+0x1d/0x30
[ 73.695801] [<c01b38b5>] print_cpu_stall+0x45/0xa0
[ 73.695801] [<c01b39f8>] check_cpu_stall+0xe8/0x190
[ 73.695801] [<c01ad59d>] ? get_timestamp+0xd/0x20
[ 73.695801] [<c01b43ab>] __rcu_pending+0x1b/0x160
[ 73.695801] [<c01b451e>] rcu_pending+0x2e/0x70
[ 73.695801] [<c01692ab>] update_process_times+0x3b/0x80
[ 73.695801] [<c018bcf0>] tick_periodic+0x40/0x90
[ 73.695801] [<c018bd5e>] tick_handle_periodic+0x1e/0xa0
[ 73.695801] [<c01045e0>] ? apic_timer_interrupt+0x28/0x34
[ 73.695801] [<c012215f>] local_apic_timer_interrupt+0x6f/0x80
[ 73.695801] [<c0161184>] ? irq_enter+0x14/0x60
[ 73.695801] [<c05e7d83>] smp_apic_timer_interrupt+0x33/0x42
[ 73.695801] [<c01045e7>] apic_timer_interrupt+0x2f/0x34
[ 73.695801] [<c0379c3d>] ? __get_user_4+0x11/0x17
[ 73.695801] [<c0225f4e>] ? count+0x3e/0xb0
[ 73.695801] [<c0228581>] do_execve+0x621/0x890
[ 73.695801] [<c022bd8b>] ? getname+0x6b/0xa0
[ 73.695801] [<c010237e>] sys_execve+0x5e/0xb0
[ 73.695801] [<c0103d19>] syscall_call+0x7/0xb
[ 73.695801] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 73.695801] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 73.695801] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 73.695801] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 79.029887] SysRq : Show Regs
[ 79.030975]
[ 79.031578] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
[ 79.031800] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
[ 79.031800] EIP is at __get_user_4+0x11/0x17
[ 79.031800] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
[ 79.031800] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
[ 79.031800] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 79.031800] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
[ 79.031800] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 79.031800] DR6: ffff0ff0 DR7: 00000400
[ 79.031800] Call Trace:
[ 79.031800] [<c0225f4e>] ? count+0x3e/0xb0
[ 79.031800] [<c0228581>] do_execve+0x621/0x890
[ 79.031800] [<c022bd8b>] ? getname+0x6b/0xa0
[ 79.031800] [<c010237e>] sys_execve+0x5e/0xb0
[ 79.031800] [<c0103d19>] syscall_call+0x7/0xb
[ 79.031800] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 79.031800] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 79.031800] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 79.031800] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 87.925907] SysRq : Show backtrace of all active CPUs
[ 87.927799] CPU0:
[ 87.927799]
[ 87.927799] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
[ 87.927799] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
[ 87.927799] EIP is at __get_user_4+0x11/0x17
[ 87.927799] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
[ 87.927799] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
[ 87.927799] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[ 87.927799] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
[ 87.927799] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 87.927799] DR6: ffff0ff0 DR7: 00000400
[ 87.927799] Call Trace:
[ 87.927799] [<c0225f4e>] ? count+0x3e/0xb0
[ 87.927799] [<c0228581>] do_execve+0x621/0x890
[ 87.927799] [<c022bd8b>] ? getname+0x6b/0xa0
[ 87.927799] [<c010237e>] sys_execve+0x5e/0xb0
[ 87.927799] [<c0103d19>] syscall_call+0x7/0xb
[ 87.927799] [<c010aee4>] ? kernel_execve+0x24/0x30
[ 87.927799] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
[ 87.927799] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
[ 87.927799] [<c0104707>] ? kernel_thread_helper+0x7/0x10
[ 98.785592] BUG: soft lockup - CPU#1 stuck for 61s! [khelper:3657]
[ 98.785592] Modules linked in: ipv6 pcnet32 crc32
[ 98.785592] irq event stamp: 0
[ 98.785592] hardirqs last enabled at (0): [<(null)>] (null)
[ 98.785592] hardirqs last disabled at (0): [<c0155bcb>] copy_process+0x2ab/0x11a0
[ 98.785592] softirqs last enabled at (0): [<c0155bcb>] copy_process+0x2ab/0x11a0
[ 98.785592] softirqs last disabled at (0): [<(null)>] (null)
[ 98.785592]

Regards.

2009-04-13 19:55:27

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Mon, Apr 13, 2009 at 09:48:58AM +0900, Tetsuo Handa wrote:
> Hello.
>
> Paul E. McKenney wrote:
> > Is this reproducible?
> Not always, but it is reproducible.

Does it reproduce well enough to bisect?

> Al Viro wrote:
> > I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
> > to see where was it actually spinning.
> Below is sysrq message.
> Maybe something related to khelper's current->mm == NULL warning problem.
> Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc1-200904130930.txt .

I have to defer to the mm guys on this one.

Thanx, Paul

> [ 47.412519] SysRq : Show Regs
> [ 47.413986]
> [ 47.414584] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 47.415804] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 47.415804] EIP is at __get_user_4+0x11/0x17
> [ 47.415804] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 47.415804] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 47.415804] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 47.415804] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 47.415804] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 47.415804] DR6: ffff0ff0 DR7: 00000400
> [ 47.415804] Call Trace:
> [ 47.415804] [<c0225f4e>] ? count+0x3e/0xb0
> [ 47.415804] [<c0228581>] do_execve+0x621/0x890
> [ 47.415804] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 47.415804] [<c010237e>] sys_execve+0x5e/0xb0
> [ 47.415804] [<c0103d19>] syscall_call+0x7/0xb
> [ 47.415804] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 47.415804] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 47.415804] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 47.415804] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 52.551469] SysRq : Show backtrace of all active CPUs
> [ 52.551803] CPU0:
> [ 52.551803]
> [ 52.551803] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 52.551803] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 52.551803] EIP is at __get_user_4+0x11/0x17
> [ 52.551803] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 52.551803] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 52.551803] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 52.551803] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 52.551803] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 52.551803] DR6: ffff0ff0 DR7: 00000400
> [ 52.551803] Call Trace:
> [ 52.551803] [<c0225f4e>] ? count+0x3e/0xb0
> [ 52.551803] [<c0228581>] do_execve+0x621/0x890
> [ 52.551803] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 52.551803] [<c010237e>] sys_execve+0x5e/0xb0
> [ 52.551803] [<c0103d19>] syscall_call+0x7/0xb
> [ 52.551803] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 52.551803] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 52.551803] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 52.551803] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 60.956967] SysRq : Show Regs
> [ 60.958362]
> [ 60.958896] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 60.959802] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 60.959802] EIP is at __get_user_4+0x11/0x17
> [ 60.959802] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 60.959802] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 60.959802] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 60.959802] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 60.959802] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 60.959802] DR6: ffff0ff0 DR7: 00000400
> [ 60.959802] Call Trace:
> [ 60.959802] [<c0225f4e>] ? count+0x3e/0xb0
> [ 60.959802] [<c0228581>] do_execve+0x621/0x890
> [ 60.959802] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 60.959802] [<c010237e>] sys_execve+0x5e/0xb0
> [ 60.959802] [<c0103d19>] syscall_call+0x7/0xb
> [ 60.959802] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 60.959802] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 60.959802] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 60.959802] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 69.014489] SysRq : Show backtrace of all active CPUs
> [ 69.015802] CPU0:
> [ 69.015802]
> [ 69.015802] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 69.015802] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 69.015802] EIP is at __get_user_4+0x11/0x17
> [ 69.015802] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 69.015802] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 69.015802] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 69.015802] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 69.015802] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 69.015802] DR6: ffff0ff0 DR7: 00000400
> [ 69.015802] Call Trace:
> [ 69.015802] [<c0225f4e>] ? count+0x3e/0xb0
> [ 69.015802] [<c0228581>] do_execve+0x621/0x890
> [ 69.015802] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 69.015802] [<c010237e>] sys_execve+0x5e/0xb0
> [ 69.015802] [<c0103d19>] syscall_call+0x7/0xb
> [ 69.015802] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 69.015802] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 69.015802] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 69.015802] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 73.695801] INFO: RCU detected CPU 0 stall (t=4294910558/10000 jiffies)
> [ 73.695801] Pid: 3655, comm: khelper Tainted: G W 2.6.30-rc1 #1
> [ 73.695801] Call Trace:
> [ 73.695801] [<c015949d>] ? printk+0x1d/0x30
> [ 73.695801] [<c01b38b5>] print_cpu_stall+0x45/0xa0
> [ 73.695801] [<c01b39f8>] check_cpu_stall+0xe8/0x190
> [ 73.695801] [<c01ad59d>] ? get_timestamp+0xd/0x20
> [ 73.695801] [<c01b43ab>] __rcu_pending+0x1b/0x160
> [ 73.695801] [<c01b451e>] rcu_pending+0x2e/0x70
> [ 73.695801] [<c01692ab>] update_process_times+0x3b/0x80
> [ 73.695801] [<c018bcf0>] tick_periodic+0x40/0x90
> [ 73.695801] [<c018bd5e>] tick_handle_periodic+0x1e/0xa0
> [ 73.695801] [<c01045e0>] ? apic_timer_interrupt+0x28/0x34
> [ 73.695801] [<c012215f>] local_apic_timer_interrupt+0x6f/0x80
> [ 73.695801] [<c0161184>] ? irq_enter+0x14/0x60
> [ 73.695801] [<c05e7d83>] smp_apic_timer_interrupt+0x33/0x42
> [ 73.695801] [<c01045e7>] apic_timer_interrupt+0x2f/0x34
> [ 73.695801] [<c0379c3d>] ? __get_user_4+0x11/0x17
> [ 73.695801] [<c0225f4e>] ? count+0x3e/0xb0
> [ 73.695801] [<c0228581>] do_execve+0x621/0x890
> [ 73.695801] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 73.695801] [<c010237e>] sys_execve+0x5e/0xb0
> [ 73.695801] [<c0103d19>] syscall_call+0x7/0xb
> [ 73.695801] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 73.695801] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 73.695801] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 73.695801] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 79.029887] SysRq : Show Regs
> [ 79.030975]
> [ 79.031578] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 79.031800] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 79.031800] EIP is at __get_user_4+0x11/0x17
> [ 79.031800] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 79.031800] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 79.031800] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 79.031800] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 79.031800] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 79.031800] DR6: ffff0ff0 DR7: 00000400
> [ 79.031800] Call Trace:
> [ 79.031800] [<c0225f4e>] ? count+0x3e/0xb0
> [ 79.031800] [<c0228581>] do_execve+0x621/0x890
> [ 79.031800] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 79.031800] [<c010237e>] sys_execve+0x5e/0xb0
> [ 79.031800] [<c0103d19>] syscall_call+0x7/0xb
> [ 79.031800] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 79.031800] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 79.031800] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 79.031800] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 87.925907] SysRq : Show backtrace of all active CPUs
> [ 87.927799] CPU0:
> [ 87.927799]
> [ 87.927799] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 87.927799] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 87.927799] EIP is at __get_user_4+0x11/0x17
> [ 87.927799] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 87.927799] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 87.927799] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 87.927799] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 87.927799] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 87.927799] DR6: ffff0ff0 DR7: 00000400
> [ 87.927799] Call Trace:
> [ 87.927799] [<c0225f4e>] ? count+0x3e/0xb0
> [ 87.927799] [<c0228581>] do_execve+0x621/0x890
> [ 87.927799] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 87.927799] [<c010237e>] sys_execve+0x5e/0xb0
> [ 87.927799] [<c0103d19>] syscall_call+0x7/0xb
> [ 87.927799] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 87.927799] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 87.927799] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 87.927799] [<c0104707>] ? kernel_thread_helper+0x7/0x10
> [ 98.785592] BUG: soft lockup - CPU#1 stuck for 61s! [khelper:3657]
> [ 98.785592] Modules linked in: ipv6 pcnet32 crc32
> [ 98.785592] irq event stamp: 0
> [ 98.785592] hardirqs last enabled at (0): [<(null)>] (null)
> [ 98.785592] hardirqs last disabled at (0): [<c0155bcb>] copy_process+0x2ab/0x11a0
> [ 98.785592] softirqs last enabled at (0): [<c0155bcb>] copy_process+0x2ab/0x11a0
> [ 98.785592] softirqs last disabled at (0): [<(null)>] (null)
> [ 98.785592]
>
> Regards.

2009-04-13 21:31:20

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

Paul E. McKenney wrote:
> > Hello.
> >
> > Paul E. McKenney wrote:
> > > Is this reproducible?
> > Not always, but it is reproducible.
>
> Does it reproduce well enough to bisect?
>
Not impossible, but difficult. This happens less than once on 10 trials.

> > Al Viro wrote:
> > > I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
> > > to see where was it actually spinning.
> > Below is sysrq message.
> > Maybe something related to khelper's current->mm == NULL warning problem.
> > Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc1-200904130930.txt .
>
> I have to defer to the mm guys on this one.

Latest info on khelper's current->mm == NULL warning problem is at
http://lkml.org/lkml/2009/4/13/85 .

Thanks.

2009-04-13 22:47:36

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Tue, Apr 14, 2009 at 06:31:05AM +0900, Tetsuo Handa wrote:
> Paul E. McKenney wrote:
> > > Hello.
> > >
> > > Paul E. McKenney wrote:
> > > > Is this reproducible?
> > > Not always, but it is reproducible.
> >
> > Does it reproduce well enough to bisect?
> >
> Not impossible, but difficult. This happens less than once on 10 trials.
>
> > > Al Viro wrote:
> > > > I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
> > > > to see where was it actually spinning.
> > > Below is sysrq message.
> > > Maybe something related to khelper's current->mm == NULL warning problem.
> > > Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc1-200904130930.txt .
> >
> > I have to defer to the mm guys on this one.
>
> Latest info on khelper's current->mm == NULL warning problem is at
> http://lkml.org/lkml/2009/4/13/85 .

Thank you for the pointer!

Thanx, Paul

2009-04-14 17:22:51

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Mon, 13 Apr 2009, Tetsuo Handa wrote:
> Paul E. McKenney wrote:
> > Is this reproducible?
> Not always, but it is reproducible.
>
> Al Viro wrote:
> > I'd really love to see results of repeated alt-sysrq-p/alt-sysrq-l, just
> > to see where was it actually spinning.
> Below is sysrq message.
> Maybe something related to khelper's current->mm == NULL warning problem.

Maybe, up to a point, and I'll post separately on those warnings.

> Full log is at http://I-love.SAKURA.ne.jp/tmp/dmesg-2.6.30-rc1-200904130930.txt .
>
> [ 47.412519] SysRq : Show Regs
> [ 47.413986]
> [ 47.414584] Pid: 3655, comm: khelper Tainted: G W (2.6.30-rc1 #1) VMware Virtual Platform
> [ 47.415804] EIP: 0060:[<c0379c3d>] EFLAGS: 00000293 CPU: 0
> [ 47.415804] EIP is at __get_user_4+0x11/0x17
> [ 47.415804] EAX: f7150003 EBX: f7150000 ECX: 00000000 EDX: f6744000
> [ 47.415804] ESI: 000007b8 EDI: 7fffffff EBP: f6744f20 ESP: f6744f10
> [ 47.415804] DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> [ 47.415804] CR0: 8005003b CR2: f7150000 CR3: 3599a000 CR4: 000006d0
> [ 47.415804] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [ 47.415804] DR6: ffff0ff0 DR7: 00000400
> [ 47.415804] Call Trace:
> [ 47.415804] [<c0225f4e>] ? count+0x3e/0xb0
> [ 47.415804] [<c0228581>] do_execve+0x621/0x890
> [ 47.415804] [<c022bd8b>] ? getname+0x6b/0xa0
> [ 47.415804] [<c010237e>] sys_execve+0x5e/0xb0
> [ 47.415804] [<c0103d19>] syscall_call+0x7/0xb
> [ 47.415804] [<c010aee4>] ? kernel_execve+0x24/0x30
> [ 47.415804] [<c0172b6f>] ? ____call_usermodehelper+0xff/0x170
> [ 47.415804] [<c0172a70>] ? ____call_usermodehelper+0x0/0x170
> [ 47.415804] [<c0104707>] ? kernel_thread_helper+0x7/0x10

I'm now thinking that this really is hitting in count(), despite
the ? on that in the backtrace, and is entirely unrelated to the
recent check_unsafe_exec() changes. Stuck in a loop scanning the
the kernelspace exec args without an mm.

But my compiler on your config gives quite different function
sizes: please would you post to the list or send me privately
the output of "objdump -trd fs/exec.o", so we can check that.

Thanks,
Hugh

2009-04-15 03:29:18

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

Hello.

Hugh Dickins wrote:
> But my compiler on your config gives quite different function
> sizes: please would you post to the list or send me privately
> the output of "objdump -trd fs/exec.o", so we can check that.
I uploaded it to http://I-love.SAKURA.ne.jp/tmp/dump-2.6.30-rc1-fs-exec.txt

# gcc --version
gcc (GCC) 3.3.5 (Debian 1:3.3.5-13)
Copyright (C) 2003 Free Software Foundation, Inc.
This is free software; see the source for copying conditions. There is NO
warranty; not even for MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.

Regards.

2009-04-15 20:36:16

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Wed, 15 Apr 2009, Tetsuo Handa wrote:
> Hugh Dickins wrote:
> > But my compiler on your config gives quite different function
> > sizes: please would you post to the list or send me privately
> > the output of "objdump -trd fs/exec.o", so we can check that.
> I uploaded it to http://I-love.SAKURA.ne.jp/tmp/dump-2.6.30-rc1-fs-exec.txt

Thanks, that confirmed that the problem indeed strikes in fs/exec.c's
count() function, where it's counting how many entries in the argv.

I've not worked out precisely why it gets stuck in that loop: apparently
the usual fixup_exception() isn't working here, so it just keeps retrying
the same instruction - I'm assuming it's an unwanted side-effect of your
CONFIG_DEBUG_PAGEALLOC=y, and I'm not going to worry too much about it.

I think I was quite wrong to dismiss the commit which you bisected to,
f520360d93cdc37de5d972dac4bf3bdef6a7f6a7 "kobject: don't block for
each kobject_uevent", as merely changing the timings: I now think
it's very much responsible for the problem. call_usermodehelper
with UMH_NO_WAIT, but with argv[3] on the local stack, seems risky
to me, and your CONFIG_DEBUG_PAGEALLOC has caught it.

Patch below attempts to fix that, but I wouldn't be a bit surprised
if it's inadequate, that the "argv[1] = subsystem" is also vulnerable
to subsystem getting freed before we're ready - Greg? If that's so,
then the best fix will probably be just to revert using UMH_NO_WAIT
there (other uses appear safe). As Greg noted in the commit log, you
probably want CONFIG_UEVENT_HELPER_PATH="" rather than "/sbin/hotplug"
anyway, in which case this bug would not occur and this speedup would
not be needed.

(I don't see an "/sbin/hotplug" on my systems, but if I recall, it was
impossible to remove that default using "make oldconfig", and I ended
up editing the .config to put "" instead - but now I notice some of
my configs have "\"\"" in there, which probably isn't what I want!)

But I'm glad you had CONFIG_UEVENT_HELPER_PATH="/sbin/hotplug" and
CONFIG_DEBUG_PAGEALLOC=y, they've shown us some bugs. Though it
should be separated out to a separate patch later, I've flung in
below what I believe is the right fix to your NULL mm warnings.

Alan was absolutely right to ask us to look deeper into those than
just undoing his work - acct_stack_growth()'s overcommit check
should be applied to the mm it's expanding, not to the current
task's mm (which in this UMH_NO_WAIT case ends up as the NULL
mm of a separate kernel helper thread).

Please let us know if this patch does indeed fix the bugs you've
found - the question of "subsystem" getting freed is, I imagine,
a case too unlikely to come up in your testing, so I'd expect the
patch to appear to work, even if Greg and Arjan decide that it's
really better just to revert UMH_NO_WAIT there.

Not-yet-signed-off-by: Hugh Dickins <[email protected]>
---

include/linux/kobject.h | 2 ++
lib/kobject_uevent.c | 10 ++++------
mm/mmap.c | 2 +-
3 files changed, 7 insertions(+), 7 deletions(-)

--- 2.6.30-rc1/include/linux/kobject.h 2009-04-08 18:20:17.000000000 +0100
+++ linux/include/linux/kobject.h 2009-04-15 19:56:42.000000000 +0100
@@ -27,6 +27,7 @@
#include <asm/atomic.h>

#define UEVENT_HELPER_PATH_LEN 256
+#define UEVENT_NUM_ARGV 3 /* if inside kobj_uevent_env */
#define UEVENT_NUM_ENVP 32 /* number of env pointers */
#define UEVENT_BUFFER_SIZE 2048 /* buffer for the variables */

@@ -111,6 +112,7 @@ struct kobj_type {
};

struct kobj_uevent_env {
+ char *argv[UEVENT_NUM_ARGV]; /* sometimes useful for UMH_NO_WAIT */
char *envp[UEVENT_NUM_ENVP];
int envp_idx;
char buf[UEVENT_BUFFER_SIZE];
--- 2.6.30-rc1/lib/kobject_uevent.c 2009-04-08 18:20:24.000000000 +0100
+++ linux/lib/kobject_uevent.c 2009-04-15 19:59:33.000000000 +0100
@@ -244,11 +244,9 @@ int kobject_uevent_env(struct kobject *k

/* call uevent_helper, usually only enabled during early boot */
if (uevent_helper[0]) {
- char *argv [3];
-
- argv [0] = uevent_helper;
- argv [1] = (char *)subsystem;
- argv [2] = NULL;
+ env->argv[0] = uevent_helper;
+ env->argv[1] = (char *)subsystem;
+ env->argv[2] = NULL;
retval = add_uevent_var(env, "HOME=/");
if (retval)
goto exit;
@@ -257,7 +255,7 @@ int kobject_uevent_env(struct kobject *k
if (retval)
goto exit;

- retval = call_usermodehelper(argv[0], argv,
+ retval = call_usermodehelper(env->argv[0], env->argv,
env->envp, UMH_NO_WAIT);
}

--- 2.6.30-rc1/mm/mmap.c 2009-04-08 18:20:25.000000000 +0100
+++ linux/mm/mmap.c 2009-04-15 20:28:33.000000000 +0100
@@ -1575,7 +1575,7 @@ static int acct_stack_growth(struct vm_a
* Overcommit.. This must be the final test, as it will
* update security statistics.
*/
- if (security_vm_enough_memory(grow))
+ if (security_vm_enough_memory_mm(mm, grow))
return -ENOMEM;

/* Ok, everything looks good - let it rip */

2009-04-16 00:48:16

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

Hello.

Hugh Dickins wrote:
> --- 2.6.30-rc1/lib/kobject_uevent.c 2009-04-08 18:20:24.000000000 +0100
> +++ linux/lib/kobject_uevent.c 2009-04-15 19:59:33.000000000 +0100
> @@ -244,11 +244,9 @@ int kobject_uevent_env(struct kobject *k
>
> /* call uevent_helper, usually only enabled during early boot */
> if (uevent_helper[0]) {
> - char *argv [3];
> -
> - argv [0] = uevent_helper;
> - argv [1] = (char *)subsystem;
> - argv [2] = NULL;
> + env->argv[0] = uevent_helper;
> + env->argv[1] = (char *)subsystem;
> + env->argv[2] = NULL;
> retval = add_uevent_var(env, "HOME=/");
> if (retval)
> goto exit;
> @@ -257,7 +255,7 @@ int kobject_uevent_env(struct kobject *k
> if (retval)
> goto exit;
>
> - retval = call_usermodehelper(argv[0], argv,
> + retval = call_usermodehelper(env->argv[0], env->argv,
> env->envp, UMH_NO_WAIT);
> }
>
Indeed, we can't use "argv" put on stack memory if we use "no wait" mode.
We need to ensure that memory region pointed by "argv" is valid until
do_execve() finishes. However,
|
| exit:
| kfree(devpath);
| kfree(env);
| return retval;
| }
"env" can be overwritten as well as "argv".
We need to ensure that memory region pointed by "env" is valid until
do_execve() finishes, don't we?

I think we need to use UMH_WAIT_EXEC instead of UMH_NO_WAIT.

Regards.

2009-04-16 05:22:25

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Thu, 16 Apr 2009, Tetsuo Handa wrote:
> Indeed, we can't use "argv" put on stack memory if we use "no wait" mode.
> We need to ensure that memory region pointed by "argv" is valid until
> do_execve() finishes. However,
> |
> | exit:
> | kfree(devpath);
> | kfree(env);
> | return retval;
> | }
> "env" can be overwritten as well as "argv".
> We need to ensure that memory region pointed by "env" is valid until
> do_execve() finishes, don't we?
>
> I think we need to use UMH_WAIT_EXEC instead of UMH_NO_WAIT.

Yes, of course you're right, silly me.

It could be worked around using call_usermodehelper_setcleanup()
to arrange for the freeing there instead of here in this case;
but if CONFIG_UEVENT_HELPER_PATH="" is the better answer anyway,
let's not waste any more time on this, just revert the broken patch
(which is what simply changing UMH_NO_WAIT to UMH_WAIT_EXEC does).

I'd hoped to get confirmation that the mmap.c part of the patch
was all the extra needed; but never mind, that's clearly good.

Thanks a lot: I'll send in a revert request,
and the acct_stack_growth patch, later today.

Hugh

2009-04-16 05:36:16

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

Hello.

Hugh Dickins wrote:
> I'd hoped to get confirmation that the mmap.c part of the patch
> was all the extra needed; but never mind, that's clearly good.
Yes. The mmap.c part solved khelper's current->mm == NULL warning.

> Thanks a lot: I'll send in a revert request,
> and the acct_stack_growth patch, later today.
Yes, please.

Thank you.

2009-04-16 20:49:54

by Greg KH

[permalink] [raw]

Subject: Re: [2.6.30-rc1] RCU detected CPU 1 stall

On Thu, Apr 16, 2009 at 02:35:11PM +0900, Tetsuo Handa wrote:
> Hello.
>
> Hugh Dickins wrote:
> > I'd hoped to get confirmation that the mmap.c part of the patch
> > was all the extra needed; but never mind, that's clearly good.
> Yes. The mmap.c part solved khelper's current->mm == NULL warning.
>
> > Thanks a lot: I'll send in a revert request,
> > and the acct_stack_growth patch, later today.
> Yes, please.

That's fine with me as well. If distros care about this, they can
change the config option to be "" for HOTPLUG.

thanks,

greg k-h

2009-04-16 20:57:31

[permalink] [raw]

Subject: Please revert kobject_uevent UMH_NO_WAIT

Please revert commit f520360d93cdc37de5d972dac4bf3bdef6a7f6a7
"kobject: don't block for each kobject_uevent".

Tetsuo Handa, running a kernel with CONFIG_DEBUG_PAGEALLOC=y
and CONFIG_UEVENT_HELPER_PATH=/sbin/hotplug, has been hitting RCU
detected CPU stalls: it's been spinning in the loop where do_execve()
counts up the args (but why wasn't fixup_exception working? dunno).

The recent change, switching kobject_uevent_env() from UMH_WAIT_EXEC
to UMH_NO_WAIT, is broken: the exec uses args on the local stack here,
and an env which is kfreed as soon as call_usermodehelper() returns.
It very much needs to wait for the exec to be done.

Or keep the UMH_NO_WAIT, and complicate the code to allocate and free
these resources correctly? No, as GregKH pointed out when making the
commit, CONFIG_UEVENT_HELPER_PATH="" is a much better optimization -
though some distros are still saying /sbin/hotplug in their .config,
yet with no such binary in their initrd or their root.

Or...

[PATCH] revert kobject_uevent UMH_NO_WAIT

Reported-by: Tetsuo Handa <[email protected]>
Signed-off-by: Hugh Dickins <[email protected]>
---

lib/kobject_uevent.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

--- 2.6.30-rc2/lib/kobject_uevent.c 2009-04-08 18:20:24.000000000 +0100
+++ linux/lib/kobject_uevent.c 2009-04-16 20:31:17.000000000 +0100
@@ -258,7 +258,7 @@ int kobject_uevent_env(struct kobject *k
goto exit;

retval = call_usermodehelper(argv[0], argv,
- env->envp, UMH_NO_WAIT);
+ env->envp, UMH_WAIT_EXEC);
}

exit:

2009-04-16 21:00:14