-   Linux - Server (
-   -   BUG: soft lockup - CPU#3 stuck for 10s! (

chakkerz 06-12-2008 07:35 PM

BUG: soft lockup - CPU#3 stuck for 10s!
Hello there

I'm running CentOS 5.2 x86_64 on a PowerEdge 1950 (two CPU, two Core)

I'm getting the following error every 10 seconds:


2008-06-12T23:38:02.736413+10:00 fact kernel:<3>BUG: soft lockup - CPU#3 stuck for 10s! [bond0:2895]
2008-06-12T23:38:02.736441+10:00 fact kernel:<4>CPU 3:
2008-06-12T23:38:02.736479+10:00 fact kernel:<4>Modules linked in: ip_conntrack_netbios_ns xt_state ip_conntrack nfnetlink iptable_filter ip_tables nfs fscache nfsd exportfs lockd nfs_acl auth_rpcgss autofs4 lock_dlm gfs2 dlm configfs
sunrpc bonding ipt_REJECT ipt_LOG xt_limit xt_tcpudp ip6_tables x_tables dm_round_robin dm_multipath video sbs backlight i2c_ec i2c_core button battery asus_acpi acpi_memhotplug ac parport_pc lp parport joydev sr_mod e1000e i5000_edac
ide_cd edac_mc pcspkr bnx2 sg shpchp serio_raw cdrom dm_snapshot dm_zero dm_mirror dm_mod usb_storage qla2xxx scsi_transport_fc ata_piix libata megaraid_sas sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd
2008-06-12T23:38:02.736484+10:00 fact kernel:<4>Pid: 2895, comm: bond0 Not tainted 2.6.18-92.1.1.el5 #1
2008-06-12T23:38:02.747848+10:00 fact kernel:<4>RIP: 0010:[.text.lock.spinlock+38/48]  [.text.lock.spinlock+38/48] .text.lock.spinlock+0x26/0x30
2008-06-12T23:38:02.747856+10:00 fact kernel:<4>RSP: 0018:ffff81012ca4bd20  EFLAGS: 00000286
2008-06-12T23:38:02.747861+10:00 fact kernel:<4>RAX: ffff81012ca4bfd8 RBX: ffff81012d95c000 RCX: ffff81012ca4bd80
2008-06-12T23:38:02.747866+10:00 fact kernel:<4>RDX: 0000000000008948 RSI: ffff81012ca4bd70 RDI: ffff81012d95c714
2008-06-12T23:38:02.747870+10:00 fact kernel:<4>RBP: ffffffff8014333e R08: ffff81012ca4bd50 R09: 000000000000003d
2008-06-12T23:38:02.747875+10:00 fact kernel:<4>R10: ffff81012fc5c008 R11: 0000000000000008 R12: 0000000000000002
2008-06-12T23:38:02.747879+10:00 fact kernel:<4>R13: ffff81012ca4bd70 R14: ffff81012d95c000 R15: ffff81012e5b9040
2008-06-12T23:38:02.747883+10:00 fact kernel:<4>FS:  0000000000000000(0000) GS:ffff81010439c640(0000) knlGS:0000000000000000
2008-06-12T23:38:02.747887+10:00 fact kernel:<4>CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
2008-06-12T23:38:02.747891+10:00 fact kernel:<4>CR2: 00000000133180d8 CR3: 0000000000201000 CR4: 00000000000006e0
2008-06-12T23:38:02.747894+10:00 fact kernel:<4>
2008-06-12T23:38:02.747898+10:00 fact kernel:<4>Call Trace:
2008-06-12T23:38:02.749702+10:00 fact kernel:<4> [bnx2:bnx2_ioctl+105/255] :bnx2:bnx2_ioctl+0x69/0xff
2008-06-12T23:38:02.749877+10:00 fact kernel:<4> [bonding:bond_check_dev_link+211/441] :bonding:bond_check_dev_link+0xd3/0x1b9
2008-06-12T23:38:02.749900+10:00 fact kernel:<4> [thread_return+0/223] thread_return+0x0/0xdf
2008-06-12T23:38:02.750024+10:00 fact kernel:<4> [bonding:__bond_mii_monitor+136/1092] :bonding:__bond_mii_monitor+0x88/0x444
2008-06-12T23:38:02.750140+10:00 fact kernel:<4> [bonding:bond_mii_monitor+0/140] :bonding:bond_mii_monitor+0x0/0x8c
2008-06-12T23:38:02.750257+10:00 fact kernel:<4> [bonding:bond_mii_monitor+45/140] :bonding:bond_mii_monitor+0x2d/0x8c
2008-06-12T23:38:02.750282+10:00 fact kernel:<4> [run_workqueue+148/228] run_workqueue+0x94/0xe4
2008-06-12T23:38:02.750301+10:00 fact kernel:<4> [worker_thread+0/290] worker_thread+0x0/0x122
2008-06-12T23:38:02.750331+10:00 fact kernel:<4> [keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-12T23:38:02.750347+10:00 fact kernel:<4> [worker_thread+240/290] worker_thread+0xf0/0x122
2008-06-12T23:38:02.750369+10:00 fact kernel:<4> [<ffffffff8008ad26>] default_wake_function+0x0/0xe
2008-06-12T23:38:02.750395+10:00 fact kernel:<4> [keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-12T23:38:02.750420+10:00 fact kernel:<4> [keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-12T23:38:02.750439+10:00 fact kernel:<4> [kthread+254/306] kthread+0xfe/0x132
2008-06-12T23:38:02.750459+10:00 fact kernel:<4> [child_rip+10/17] child_rip+0xa/0x11
2008-06-12T23:38:02.750483+10:00 fact kernel:<4> [keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-12T23:38:02.750499+10:00 fact kernel:<4> [kthread+0/306] kthread+0x0/0x132
2008-06-12T23:38:02.750521+10:00 fact kernel:<4> [child_rip+0/17] child_rip+0x0/0x11
2008-06-12T23:38:02.750525+10:00 fact kernel:<4>

I thought the following is not always following this error, but i seem to maybe have been imagining things, and the following is always straight after:


2008-06-12T23:38:02.999079+10:00 fact kernel:<4> invoked oom-killer: gfp_mask=0xd0, order=1, oomkilladj=0
2008-06-12T23:38:02.999087+10:00 fact kernel:<4>
2008-06-12T23:38:02.999091+10:00 fact kernel:<4>Call Trace:
2008-06-12T23:38:03.000397+10:00 fact kernel:<4> [out_of_memory+142/757] out_of_memory+0x8e/0x2f5
2008-06-12T23:38:03.000427+10:00 fact kernel:<4> [__alloc_pages+581/718] __alloc_pages+0x245/0x2ce
2008-06-12T23:38:03.000448+10:00 fact kernel:<4> [nfs:__get_free_pages+14/1513] __get_free_pages+0xe/0x71
2008-06-12T23:38:03.000605+10:00 fact kernel:<4> [copy_process+198/5445] copy_process+0xc6/0x1545
2008-06-12T23:38:03.000926+10:00 fact kernel:<4> [alloc_pid+494/650] alloc_pid+0x1ee/0x28a
2008-06-12T23:38:03.001413+10:00 fact kernel:<4> [do_fork+104/391] do_fork+0x68/0x187
2008-06-12T23:38:03.001709+10:00 fact kernel:<4> [tracesys+213/224] tracesys+0xd5/0xe0
2008-06-12T23:38:03.001736+10:00 fact kernel:<4> [ptregscall_common+103/172] ptregscall_common+0x67/0xac
2008-06-12T23:38:03.001739+10:00 fact kernel:<4>
2008-06-12T23:38:03.001743+10:00 fact kernel:<6>Mem-info:
2008-06-12T23:38:03.001747+10:00 fact kernel:<4>Node 0 DMA per-cpu:
2008-06-12T23:38:03.001751+10:00 fact kernel:<4>cpu 0 hot: high 0, batch 1 used:0
2008-06-12T23:38:03.001755+10:00 fact kernel:<4>cpu 0 cold: high 0, batch 1 used:0
2008-06-12T23:38:03.001759+10:00 fact kernel:<4>cpu 1 hot: high 0, batch 1 used:0
2008-06-12T23:38:03.001763+10:00 fact kernel:<4>cpu 1 cold: high 0, batch 1 used:0
2008-06-12T23:38:03.001768+10:00 fact kernel:<4>cpu 2 hot: high 0, batch 1 used:0
2008-06-12T23:38:03.001773+10:00 fact kernel:<4>cpu 2 cold: high 0, batch 1 used:0
2008-06-12T23:38:03.001778+10:00 fact kernel:<4>cpu 3 hot: high 0, batch 1 used:0
2008-06-12T23:38:03.001782+10:00 fact kernel:<4>cpu 3 cold: high 0, batch 1 used:0
2008-06-12T23:38:03.001786+10:00 fact kernel:<4>Node 0 DMA32 per-cpu:
2008-06-12T23:38:03.001791+10:00 fact kernel:<4>cpu 0 hot: high 186, batch 31 used:29
2008-06-12T23:38:03.001795+10:00 fact kernel:<4>cpu 0 cold: high 62, batch 15 used:29
2008-06-12T23:38:03.001799+10:00 fact kernel:<4>cpu 1 hot: high 186, batch 31 used:185
2008-06-12T23:38:03.001803+10:00 fact kernel:<4>cpu 1 cold: high 62, batch 15 used:1
2008-06-12T23:38:03.001807+10:00 fact kernel:<4>cpu 2 hot: high 186, batch 31 used:26
2008-06-12T23:38:03.001811+10:00 fact kernel:<4>cpu 2 cold: high 62, batch 15 used:52
2008-06-12T23:38:03.001815+10:00 fact kernel:<4>cpu 3 hot: high 186, batch 31 used:5
2008-06-12T23:38:03.001819+10:00 fact kernel:<4>cpu 3 cold: high 62, batch 15 used:12
2008-06-12T23:38:03.001823+10:00 fact kernel:<4>Node 0 Normal per-cpu:
2008-06-12T23:38:03.001827+10:00 fact kernel:<4>cpu 0 hot: high 186, batch 31 used:9
2008-06-12T23:38:03.001831+10:00 fact kernel:<4>cpu 0 cold: high 62, batch 15 used:59
2008-06-12T23:38:03.001835+10:00 fact kernel:<4>cpu 1 hot: high 186, batch 31 used:174
2008-06-12T23:38:03.001840+10:00 fact kernel:<4>cpu 1 cold: high 62, batch 15 used:49
2008-06-12T23:38:03.001844+10:00 fact kernel:<4>cpu 2 hot: high 186, batch 31 used:16
2008-06-12T23:38:03.001848+10:00 fact kernel:<4>cpu 2 cold: high 62, batch 15 used:55
2008-06-12T23:38:03.001852+10:00 fact kernel:<4>cpu 3 hot: high 186, batch 31 used:183
2008-06-12T23:38:03.001856+10:00 fact kernel:<4>cpu 3 cold: high 62, batch 15 used:10
2008-06-12T23:38:03.002011+10:00 fact kernel:<4>Node 0 HighMem per-cpu: empty
2008-06-12T23:38:03.002017+10:00 fact kernel:<4>Free pages:      179200kB (0kB HighMem)
2008-06-12T23:38:03.002023+10:00 fact kernel:<4>Active:5100 inactive:5852 dirty:0 writeback:0 unstable:0 free:44800 slab:343788 mapped-file:1619 mapped-anon:7606 pagetables:4241
2008-06-12T23:38:03.002029+10:00 fact kernel:<4>Node 0 DMA free:11120kB min:20kB low:24kB high:28kB active:0kB inactive:0kB present:10768kB pages_scanned:0 all_unreclaimable? yes
2008-06-12T23:38:03.002036+10:00 fact kernel:<4>lowmem_reserve[]: 0 3255 4013 4013
2008-06-12T23:38:03.002042+10:00 fact kernel:<4>Node 0 DMA32 free:165944kB min:6564kB low:8204kB high:9844kB active:1960kB inactive:2920kB present:3334016kB pages_scanned:5110 all_unreclaimable? yes
2008-06-12T23:38:03.002046+10:00 fact kernel:<4>lowmem_reserve[]: 0 0 757 757
2008-06-12T23:38:03.002051+10:00 fact kernel:<4>Node 0 Normal free:2136kB min:1524kB low:1904kB high:2284kB active:18440kB inactive:20488kB present:775680kB pages_scanned:59370 all_unreclaimable? yes
2008-06-12T23:38:03.002055+10:00 fact kernel:<4>lowmem_reserve[]: 0 0 0 0
2008-06-12T23:38:03.002062+10:00 fact kernel:<4>Node 0 HighMem free:0kB min:128kB low:128kB high:128kB active:0kB inactive:0kB present:0kB pages_scanned:0 all_unreclaimable? no
2008-06-12T23:38:03.002066+10:00 fact kernel:<4>lowmem_reserve[]: 0 0 0 0
2008-06-12T23:38:03.002072+10:00 fact kernel:<4>Node 0 DMA: 2*4kB 5*8kB 6*16kB 5*32kB 3*64kB 3*128kB 0*256kB 0*512kB 2*1024kB 0*2048kB 2*4096kB = 11120kB
2008-06-12T23:38:03.002077+10:00 fact kernel:<4>Node 0 DMA32: 40686*4kB 42*8kB 1*16kB 1*32kB 0*64kB 0*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 0*4096kB = 165944kB
2008-06-12T23:38:03.002145+10:00 fact kernel:<4>Node 0 Normal: 406*4kB 2*8kB 1*16kB 1*32kB 1*64kB 1*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 2136kB
2008-06-12T23:38:03.002151+10:00 fact kernel:<4>Node 0 HighMem: empty
2008-06-12T23:38:03.002155+10:00 fact kernel:<4>10896 pagecache pages
2008-06-12T23:38:03.002159+10:00 fact kernel:<4>Swap cache: add 1972663, delete 1964989, find 753238/1100874, race 0+14
2008-06-12T23:38:03.002163+10:00 fact kernel:<4>Free swap  = 1919752kB
2008-06-12T23:38:03.002229+10:00 fact kernel:<4>Total swap = 2040212kB
2008-06-12T23:38:03.002234+10:00 fact kernel:<6>Free swap:      1919752kB
2008-06-12T23:38:03.027474+10:00 fact kernel:<6>1245184 pages of RAM
2008-06-12T23:38:03.027493+10:00 fact kernel:<6>233218 reserved pages
2008-06-12T23:38:03.027497+10:00 fact kernel:<6>27929 pages shared
2008-06-12T23:38:03.027501+10:00 fact kernel:<6>7783 pages swap cached

The next like will be another BUG: soft lockup... I believe the Out of Memory is slightly misleading as i don't appear to get all that much swap space being activated.

When this happens the systems is ping able, telnet able (so telnet indicates ports are open and responsive) but dead at the console, not ssh able and generally not very interactive...

I should mention it does not appear to affect the same process everytime, rather it is the CPU (core) that's the consistent factor. I'm going out on a limb and thinking i may have a dodgy CPU / the CPU is over heating, but i've only just started investigating it.

Anyone seen this before? My google was rather fruitless. Any help would be appreciated.

any help appreciated

Zyglow 06-12-2008 08:42 PM

If it's always with the same core, then I would agree that you have a dodgy CPU. I have not seen that same exact error, but I have come across hardware issues that normal diagnostics are unable to catch.

chakkerz 06-16-2008 05:34 PM

Some more research on the issue indicates that the message itself (BUG: soft lockup - CPU#3 stuck for 10s!) indicates that there is a kernel bug.

From the error message it would appear that there is either an issue with the bnx2 module (odd since i've got it working on 30+ other systems), bonding (or bonding using bnx2) or the kernel (or the kernel using bonding [possibly with regards to bnx2 or not]).

Anyone else have any thoughts? I should probably mention that my kernel is not tainted, and i have the same issue on two hosts (both cluster nodes).


All times are GMT -5. The time now is 08:31 PM.