Re: 2.6.30-rc2 soft lockups: ACPI? clock source problem?

[Andrew Morton <akpm@linux-foundation.org>]

(Is jstultz@us.ibm.com correct?)

On Tue, 21 Apr 2009 10:30:38 -0700 Dave Hansen <dave@sr71.net> wrote:

> This was during my first boot of 2.6.30-rc2.

Did it ever happen again?

I assume this is a post-2.6.29 regression?  (Yet another.  We've been
extra bad this time)

>  At the end of all this,
> there's a "Clocksource tsc unstable (delta = -222703151079 ns)" which
> makes me think this probably wasn't a real soft lockup.  Maybe just a
> bad guess since the clock source changed.  It seems really odd that both
> CPUs would do this at precisely the same time, but in different code.
> 
> I'm including the ACPI folks since there was some ACPI stuff in here
> that is way beyond me. :)
> 
> [   76.657737] ACPI: SSDT bf6e1b32 002C4 (v01  PmRef  Cpu0Ist 00000100 INTL 20050513)
> [   76.676235] ACPI: SSDT bf6e1e7b 0085E (v01  PmRef  Cpu0Cst 00000100 INTL 20050513)
> [   76.695503] Monitor-Mwait will be used to enter C-1 state
> [   76.695531] Monitor-Mwait will be used to enter C-2 state
> [   76.695557] Monitor-Mwait will be used to enter C-3 state
> [  299.485576] BUG: soft lockup - CPU#1 stuck for 207s! [udevd:3994]

we got a softlockup

> [  299.485639] ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
> [  299.485680] processor ACPI_CPU:00: registered as cooling_device0
> [  299.485684] ACPI: Processor [CPU0] (supports 8 throttling states)

then a bunch of acpi messages which are probably unrelated.

> [  299.485576] Modules linked in: processor(+) ohci1394 ehci_hcd uhci_hcd ieee1394 usbcore thermal fan fuse
> [  299.485576] 
> [  299.485576] Pid: 3994, comm: udevd Not tainted (2.6.30-rc2 #304) 7659A71
> [  299.485576] EIP: 0060:[<c014d0f5>] EFLAGS: 00000202 CPU: 1
> [  299.485576] EIP is at current_kernel_time+0x35/0x40
> [  299.485576] EAX: 00009529 EBX: f75cf400 ECX: 00000000 EDX: f7687480
> [  299.485576] ESI: f70a49a0 EDI: f765ac80 EBP: f749de38 ESP: f749de2c
> [  299.485576]  DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068
> [  299.485576] CR0: 8005003b CR2: b7f09078 CR3: 36db7000 CR4: 000006b0
> [  299.485576] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> [  299.485576] DR6: ffff0ff0 DR7: 00000400
> [  299.485576] Call Trace:
> [  299.485576]  [<c013629b>] current_fs_time+0xb/0x20
> [  299.485576]  [<c01ba7b8>] file_update_time+0x48/0xc0
> [  299.485576]  [<c01af03f>] pipe_write+0x2ff/0x410
> [  299.485576]  [<c013f2a6>] ? get_signal_to_deliver+0x276/0x380
> [  299.485576]  [<c01a7bed>] do_sync_write+0xcd/0x110
> [  299.485576]  [<c0145cd0>] ? autoremove_wake_function+0x0/0x40
> [  299.485576]  [<c0191d89>] ? remove_vma+0x49/0x60
> [  299.485576]  [<c01a8436>] vfs_write+0x96/0x160
> [  299.485576]  [<c01a7b20>] ? do_sync_write+0x0/0x110
> [  299.485576]  [<c01a8afd>] sys_write+0x3d/0x70
> [  299.485576]  [<c0102e18>] sysenter_do_call+0x12/0x2c

then the softlockup backtrace.  current_kernel_time() got stuck.