[2.6.30-rc1] RCU detected CPU 1 stall

[2.6.30-rc1] RCU detected CPU 1 stall

[Tetsuo Handa]

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

Regards.

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

[Paul E. McKenney]

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

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

[Al Viro]

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.

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

[Paul E. McKenney]

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

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

[Tetsuo Handa]

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.

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

[Paul E. McKenney]

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

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

[Al Viro]

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.

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

[Paul E. McKenney]

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

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

[Tetsuo Handa]

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.

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

[Paul E. McKenney]

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.

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

[Tetsuo Handa]

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.

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

[Paul E. McKenney]

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

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

[Hugh Dickins]

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

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

[Tetsuo Handa]

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.

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

[Hugh Dickins]

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 <hugh@veritas.com>
---

 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 */

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

[Tetsuo Handa]

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.

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

[Hugh Dickins]

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

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

[Tetsuo Handa]

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.

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

[Greg KH]

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

Please revert kobject_uevent UMH_NO_WAIT

[Hugh Dickins]

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 <penguin-kernel@i-love.sakura.ne.jp>
Signed-off-by: Hugh Dickins <hugh@veritas.com>
---

 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:

[PATCH] mm: pass correct mm when growing stack

[Hugh Dickins]

Tetsuo Handa reports seeing the WARN_ON(current->mm == NULL) in
security_vm_enough_memory(), when do_execve() is touching the
target mm's stack, to set up its args and environment.

Yes, a UMH_NO_WAIT or UMH_WAIT_PROC call_usermodehelper() spawns
an mm-less kernel thread to do the exec.  And in any case, that
vm_enough_memory check when growing stack ought to be done on the
target mm, not on the execer's mm (though apart from the warning,
it only makes a slight tweak to OVERCOMMIT_NEVER behaviour).

Reported-by: Tetsuo Handa <penguin-kernel@i-love.sakura.ne.jp>
Signed-off-by: Hugh Dickins <hugh@veritas.com>
Cc: stable@kernel.org
---
Commoner in 2.6.30-rc, but needs fixing in 2.6.28.N and 2.6.29.N too.

 mm/mmap.c |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

--- 2.6.30-rc2/mm/mmap.c	2009-04-08 18:20:25.000000000 +0100
+++ linux/mm/mmap.c	2009-04-16 20:31:17.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 */

Re: Please revert kobject_uevent UMH_NO_WAIT

[Greg KH]

On Thu, Apr 16, 2009 at 09:55:29PM +0100, Hugh Dickins wrote:
> 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 <penguin-kernel@i-love.sakura.ne.jp>
> Signed-off-by: Hugh Dickins <hugh@veritas.com>

Acked-by: Greg Kroah-Hartman <gregkh@suse.de>

Linus, I can do this in a tree of patches to send to you or you can do it
yourself, which ever is easier.

thanks,

greg k-h

Re: Please revert kobject_uevent UMH_NO_WAIT

[Arjan van de Ven]

Greg KH wrote:
> On Thu, Apr 16, 2009 at 09:55:29PM +0100, Hugh Dickins wrote:
>> 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 <penguin-kernel@i-love.sakura.ne.jp>
>> Signed-off-by: Hugh Dickins <hugh@veritas.com>
> 
> Acked-by: Greg Kroah-Hartman <gregkh@suse.de>

Acked-by: Arjan van de Ven <arjan@linux.intel.com>
as well

not worth the hassle if this breaks too much

Re: Please revert kobject_uevent UMH_NO_WAIT

[Will Newton]

On Thu, Apr 16, 2009 at 10:30 PM, Arjan van de Ven
<arjan@linux.intel.com> wrote:
> Greg KH wrote:
>>
>> On Thu, Apr 16, 2009 at 09:55:29PM +0100, Hugh Dickins wrote:
>>>
>>> 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 <penguin-kernel@i-love.sakura.ne.jp>
>>> Signed-off-by: Hugh Dickins <hugh@veritas.com>
>>
>> Acked-by: Greg Kroah-Hartman <gregkh@suse.de>
>
> Acked-by: Arjan van de Ven <arjan@linux.intel.com>
> as well
>
> not worth the hassle if this breaks too much

Acked-by: Will Newton <will.newton@gmail.com>

It's causing crashes for me too (reported 10 days ago).

> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/
>