Comment 13 for bug 316187

Let's look at these error messages. The following:

[ 554.116802] BUG: soft lockup - CPU#1 stuck for 11s! [stress:4618]
[ 557.606750] CPU 1:
[ 557.607150] Modules linked in: iptable_filter ip_tables x_tables ipv6 lp loop af_packet serio_raw intel_agp container evdev button shpchp parport_pc parport ac i2c_piix4 pci_hotplug i2c_core pcspkr psmouse ext3 jbd mbcache sd_mod sg sr_mod cdrom floppy pata_acpi e1000 mptspi mptscsih mptbase scsi_transport_spi ata_piix ata_generic libata scsi_mod thermal processor fan fbcon tileblit font bitblit softcursor fuse
[ 592.791355] Pid: 4618, comm: stress Not tainted 2.6.24-22-server #1
[ 592.797376] RIP: 0033:[<00000000004032db>] [<00000000004032db>]
[ 594.408565] RSP: 002b:00007fff2a2e0200 EFLAGS: 00000202
[ 594.408959] RAX: 000000002fcd9fdc RBX: 00007fff2a2e0210 RCX: 00007f3021e3c0d4
[ 594.409443] RDX: 00007f3021e3c0e4 RSI: 00007fff2a2e01e4 RDI: 00007f3021e3c4c0
[ 594.409880] RBP: ffffffff8020c907 R08: 00007f3021e3c084 R09: 00007f3021e3c100
[ 594.410314] R10: 0000000000000000 R11: 00007f3021b15e80 R12: 00007fff2a2e0210
[ 594.410738] R13: 0000000000000000 R14: 0000000000000000 R15: 00007fff2a2e06a0
[ 594.411187] FS: 00007f30222d86e0(0000) GS:ffff81001f001700(0000) knlGS:0000000000000000
[ 594.411838] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 594.412227] CR2: 00007fff2a216000 CR3: 000000001b9f7000 CR4: 00000000000006e0
[ 594.412663] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 594.431287] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 594.464652]
[ 594.464656] Call Trace:

..with no call trace occurs because the user space stress process is hogging all the CPU and the watchdog eventually gets some processing time and thinks the CPU is locked up.

1. The stress process is indeed consuming all the available cycles on this CPU - that's what it was designed to test
2. The watch dog which should wake up about every second eventually gets run and falsely thinks there is a soft lock up.
3. There is NO call trace - this is because the watchdog detects the problem in user space - i.e. the stress process and not because of any kernel related bug causing the CPU to lock up.

And now look at the next message:

[ 594.465954] BUG: soft lockup - CPU#3 stuck for 11s! [stress:4623]
[ 594.467024] CPU 3:
[ 594.467416] Modules linked in: iptable_filter ip_tables x_tables ipv6 lp loop af_packet serio_raw intel_agp container evdev button shpchp parport_pc parport ac i2c_piix4 pci_hotplug i2c_core pcspkr psmouse ext3 jbd mbcache sd_mod sg sr_mod cdrom floppy pata_acpi e1000 mptspi mptscsih mptbase scsi_transport_spi ata_piix ata_generic libata scsi_mod thermal processor fan fbcon tileblit font bitblit softcursor fuse
[ 594.467482] Pid: 4623, comm: stress Not tainted 2.6.24-22-server #1
[ 594.467539] RIP: 0010:[<ffffffff8027fcc9>] [<ffffffff8027fcc9>] handle_IRQ_event+0x19/0x70
[ 594.732355] RSP: 0018:ffff81001d15bf38 EFLAGS: 00000246
[ 594.732745] RAX: 0000000000004100 RBX: 0000000000000000 RCX: ffff81001d150000
[ 594.733180] RDX: 0000000000000012 RSI: ffff81001f489340 RDI: 0000000000000012
[ 594.734110] RBP: ffff81001d15beb0 R08: 0000000000000000 R09: ffff81001f508058
[ 594.734681] R10: ffff810001027880 R11: 0000000000000001 R12: ffffffff8020cfb6
[ 594.735114] R13: 0000000000000012 R14: ffff81001f489340 R15: ffff81001d148000
[ 594.735590] FS: 00007f30222d86e0(0000) GS:ffff81001f001d00(0000) knlGS:0000000000000000
[ 594.735708] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 594.735708] CR2: 00007f3021e3c090 CR3: 000000001c55c000 CR4: 00000000000006e0
[ 594.735708] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 594.735708] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 594.735708]
[ 594.735708] Call Trace:
[ 594.735708] <IRQ> [<ffffffff8028181a>] handle_fasteoi_irq+0x8a/0x110
[ 597.205321] [<ffffffff8020ef6b>] do_IRQ+0x7b/0x100
[ 597.205735] [<ffffffff8020c891>] ret_from_intr+0x0/0xa
[ 597.206129] <EOI> [<ffffffff80471377>] _spin_lock+0x7/0x10
[ 601.702669] [<ffffffff802d60c9>] sync_inodes_sb+0x89/0xb0
[ 601.702669] [<ffffffff802d6169>] __sync_inodes+0x79/0xc0
[ 602.683258] [<ffffffff802d61c1>] sync_inodes+0x11/0x30
[ 602.683646] [<ffffffff802d9272>] do_sync+0x12/0x70
[ 602.684015] [<ffffffff802d92de>] sys_sync+0xe/0x20
[ 603.138204] [<ffffffff8020c3e8>] sysret_careful+0xd/0x10
[ 603.238563] [<ffffffff8020c37e>] system_call+0x7e/0x83
[ 603.238990]

Again, the user space stress process is hogging up the processor (doing what it was designed to do). This type we get a kernel stack dump to show us where the watch dog thinks the offending hog is. However, this again I believe is a false hit. It just so happens that this time the CPU was in kernel space when the watch dog gets some scheduling time rather than in user space (as the first case was).

I've analysed this with a 2.6.27 kernel and I don't see this occuring since the scheduler has been improved, hence the watch dog gets scheduled more evenly. Also, in 2.6.27 the watch dog kicks off a warning after ~60 seconds rather than around 10 seconds in 2.6.24. Hence I believe it's more likely to get scheduled in a 60 second CPU hogging slot than a 10 second slot on 2.6.24 (which also probably has a less fair scheduler).

My conclusion is as follows:

1. The CPU hogging process is doing what it was deigned to do - hog CPU cycles
2. The kernel watchdog does detect that a user space process is hogging the CPU and hence dumps out these kernel messages
3. Perhaps we can conclude that the watch dog is producing some false hits - but the stack dumps are not a critical error - just warning messages with some debug to provide context to the CPU hog

How do we progress?:

1) Now we either look at tweaking the scheduler to make things more fair and to reduce the softlock messages
2) Or we just note that the kernel is doing what it is supposed to do and we acknowledge that these are legitimate warnings that a CPU hogging process is indeed hogging the CPU and the kernel has identified this.