Soft Lockups on 2.6.28-rc8 under netperf bulk receive workload

I have a 32-core, 1.6 GHz Montvale hp rx8640 with 128 GB of RAM (64x2GB DIMMS) configured as ILM (interleave memory on a cacheline boundary) rather than cell local memory. HyperThreading is disabled. The system has four AD386A PCIe 10G Ethernet interfaces each in a separate PCIe x8 slot. The AD386A is a single-port card based on the Chelsio T3C chip. The interrupts of the 8 queues on each card are spread across the 32 cores - 8 queues of card one to cores 0-7 one to one, those of card two to cores 8-15, etc etc. The NICs are in turn connected to an HP ProCurve 5406 with a number of 10G modules, which then connect to four, 4P/16C, 2.3 GHz Opteron 8356 HP DL585 G5's each with two AD386As also in x8 slots or better. I configure four subnets - 192.168.[2345]/24, set arp_ignore to one (since they are all carried on the same switch) and all five systems are in all four subnets (two IP's per interface on the DL585s.

The MTU on all interfaces is 1500 bytes. cxgb3 driver settings are default. net.core.[rw]mem_max is set to 4194304 and netperf is making explicit setsockopt calls asking for 1MB SO_[SND|RCV]BUF values.

I then launch 64 concurrent netperf TCP_MAERTS tests (actually the "omni" test equivalent which does the same thing) from the rx8640. This causes each of the DL585 G5's to start sending data to the rx8640.

I was first running a not-yet-released distro based on an old 2.6 kernel and the 1.1.022 out-of-tree cxgb3 driver and saw soft lockups. I then moved on to a Debian Lenny 2.6.26 kernel, still with the same out-of-tree driver and saw soft lockups.

Presently, the system is running a 2.6.28-rc8 kernel from kernel.org with the in-tree cxgb3 driver and I still see soft lockups which look like:

[ 1564.448850] BUG: soft lockup - CPU#31 stuck for 61s! [netperf:4094]
[ 1564.449062] Modules linked in: ipv6 loop evdev ext3 jbd mbcache 
dm_mirror dm_region_hash dm_log dm_snapshot dm_mod sg sr_mod cdrom 
sd_mod mptspi mptscsih mptbase cxgb3 scsi_transport_spi e1000 inet_lro 
tg3 scsi_mod libphy
[ 1564.449828] Modules linked in: ipv6 loop evdev ext3 jbd mbcache 
dm_mirror dm_region_hash dm_log dm_snapshot dm_mod sg sr_mod cdrom 
sd_mod mptspi mptscsih mptbase cxgb3 scsi_transport_spi e1000 inet_lro 
tg3 scsi_mod libphy
[ 1564.450575]
[ 1564.450576] Pid: 4094, CPU 31, comm:              netperf
[ 1564.450803] psr : 0000121008026018 ifs : 800000000000040b ip  : 
[<a000000100190121>]    Not tainted (2.6.28-rc8-raj)
[ 1564.451156] ip is at kmem_cache_alloc_node+0x201/0x280
[ 1564.451322] unat: 0000000000000000 pfs : 000000000000040b rsc : 
0000000000000003
[ 1564.451559] rnat: 0000000000003200 bsps: e000001e4f4a8008 pr  : 
a6144659159a6665
[ 1564.451796] ldrs: 0000000000000000 ccv : 0000000000000000 fpsr: 
0009804c8a70033f
[ 1564.452033] csd : 0000000000000000 ssd : 0000000000000000
[ 1564.452208] b0  : a0000001001900f0 b6  : a00000010060f240 b7  : 
a000000100494f40
[ 1564.452445] f6  : 1003e0000000000002c00 f7  : 1003e000000000000002c
[ 1564.452646] f8  : 1003e0000000000000100 f9  : 1003efffffffffffffa58
[ 1564.452848] f10 : 1003e0000000000000015 f11 : 1003ecf3cf3cf3cf3cf3d
[ 1564.453050] r1  : a000000100b377d0 r2  : 0000000000000691 r3  : 
0000000000000004
[ 1564.453287] r8  : e000001e4d8d2d80 r9  : 000000000000003e r10 : 
e00000408c243718
[ 1564.454333] r11 : 0000000000041200 r12 : e000001f803479b0 r13 : 
e000001f80340000
[ 1564.454570] r14 : 0000000000000000 r15 : e00000408c243508 r16 : 
0000000000002c00
[ 1564.454807] r17 : 0000000000002c00 r18 : e000001e8db6c000 r19 : 
e00000408d248490
[ 1564.455044] r20 : e000001e4d8d0000 r21 : e000001e4d8d0008 r22 : 
e000001e4d8d0180
[ 1564.455281] r23 : 0000000000000100 r24 : e000001e8db6c008 r25 : 
0000000000100100
[ 1564.455519] r26 : 0000000000004000 r27 : 0000000000004000 r28 : 
e000001e06408000
[ 1564.455755] r29 : 0000000000000bd2 r30 : e00000408d2484b0 r31 : 
0000000000000bd3
[ 1564.456002]
[ 1564.456003] Call Trace:
[ 1564.456148]  [<a000000100014c30>] show_stack+0x50/0xa0
[ 1564.456149]                                 spà00001f80347610 
bspà00001f80341bc8
[ 1564.456564]  [<a0000001000154a0>] show_regs+0x820/0x860
[ 1564.456566]                                 spà00001f803477e0 
bspà00001f80341b70
[ 1564.515003]  [<a000000100119710>] softlockup_tick+0x350/0x400
[ 1564.515004]                                 spà00001f803477e0 
bspà00001f80341b28
[ 1564.515445]  [<a0000001000ad040>] run_local_timers+0x40/0x60
[ 1564.515447]                                 spà00001f803477e0 
bspà00001f80341b10
[ 1564.516443]  [<a0000001000ad140>] update_process_times+0x40/0xc0
[ 1564.516445]                                 spà00001f803477e0 
bspà00001f80341ae0
[ 1564.516891]  [<a000000100039a60>] timer_interrupt+0x1c0/0x3e0
[ 1564.516892]                                 spà00001f803477e0 
bspà00001f80341a78
[ 1564.517325]  [<a00000010011a340>] handle_IRQ_event+0x80/0x120
[ 1564.517326]                                 spà00001f803477e0 
bspà00001f80341a40
[ 1564.517759]  [<a00000010011a560>] __do_IRQ+0x180/0x4c0
[ 1564.517760]                                 spà00001f803477e0 
bspà00001f803419d0
[ 1564.577929]  [<a000000100011130>] ia64_handle_irq+0x290/0x340
[ 1564.577931]                                 spà00001f803477e0 
bspà00001f80341958
[ 1564.578365]  [<a00000010000bf40>] ia64_native_leave_kernel+0x0/0x270
[ 1564.578366]                                 spà00001f803477e0 
bspà00001f80341958
[ 1564.579299]  [<a000000100190120>] kmem_cache_alloc_node+0x200/0x280
[ 1564.579300]                                 spà00001f803479b0 
bspà00001f80341900
[ 1564.579863]  [<a0000001004cd210>] __alloc_skb+0x50/0x220
[ 1564.579864]                                 spà00001f803479b0 
bspà00001f803418b0
[ 1564.581319]  [<a00000020ecc9850>] process_responses+0xc50/0x2080 [cxgb3]
[ 1564.581321]                                 spà00001f803479b0 
bspà00001f80341610
[ 1564.581793]  [<a00000020eccacc0>] napi_rx_handler+0x40/0x200 [cxgb3]
[ 1564.581794]                                 spà00001f803479f0 
bspà00001f803415d0
[ 1564.582250]  [<a0000001004d76f0>] net_rx_action+0x210/0x560
[ 1564.582251]                                 spà00001f803479f0 
bspà00001f80341538
[ 1564.642479]  [<a0000001000a1760>] __do_softirq+0x120/0x2e0
[ 1564.642481]                                 spà00001f803479f0 
bspà00001f80341498
[ 1564.643364]  [<a0000001000a1990>] do_softirq+0x70/0xc0
[ 1564.643366]                                 spà00001f803479f0 
bspà00001f80341438
[ 1564.643780]  [<a0000001000a1c50>] irq_exit+0x70/0xa0
[ 1564.643781]                                 spà00001f803479f0 
bspà00001f80341420
[ 1564.644190]  [<a0000001000111a0>] ia64_handle_irq+0x300/0x340
[ 1564.644191]                                 spà00001f803479f0 
bspà00001f803413a0
[ 1564.644623]  [<a00000010000bf40>] ia64_native_leave_kernel+0x0/0x270
[ 1564.644625]                                 spà00001f803479f0 
bspà00001f803413a0
[ 1564.645077]  [<a000000100192720>] kmem_cache_free+0x580/0x5c0
[ 1564.645079]                                 spà00001f80347bc0 
bspà00001f80341328
[ 1564.703103]  [<a0000001004cb0a0>] __kfree_skb+0x180/0x1a0
[ 1564.703104]                                 spà00001f80347bd0 
bspà00001f80341308
[ 1564.703537]  [<a000000100556150>] tcp_recvmsg+0xcd0/0x1180
[ 1564.703538]                                 spà00001f80347bd0 
bspà00001f80341180
[ 1564.704667]  [<a0000001004beab0>] sock_common_recvmsg+0x90/0xe0
[ 1564.704668]                                 spà00001f80347be0 
bspà00001f80341140
[ 1564.705112]  [<a0000001004bb090>] sock_recvmsg+0x1d0/0x220
[ 1564.705114]                                 spà00001f80347bf0 
bspà00001f80341108
[ 1564.705538]  [<a0000001004bd590>] sys_recvfrom+0x110/0x220
[ 1564.705540]                                 spà00001f80347d60 
bspà00001f80341088
[ 1564.705965]  [<a0000001004bd6e0>] sys_recv+0x40/0x60
[ 1564.705966]                                 spà00001f80347e30 
bspà00001f80341030
[ 1564.706376]  [<a00000010000bda0>] ia64_ret_from_syscall+0x0/0x20
[ 1564.706377]                                 spà00001f80347e30 
bspà00001f80341030
[ 1564.755966]  [<a000000000010720>] 
__start_ivt_text+0xffffffff00010720/0x400
[ 1564.755967]                                 spà00001f80348000 

bspà00001f80341030

I have also taken Caliper (http://www.hp.com/go/caliper - uses the perfmon interface present in ia64 kernels) cycles and scgprof profiles.

The cycles profile uses the Itanium PMU to gather samples via the PMU so interrupts on/off is a don't care. The profile for one of the netperf processes looks like this:

----------------------------------------------------
Run Summary (50 of 50 for netperf, Collection Run 1)
----------------------------------------------------

Target Application
Program: /opt/netperf2/bin/netperf
Invocation: netperf -P 0 -t omni -c -C -H 192.168.5.3 -l 30
-i 30 30 -- -o tmpfoo -H 192.168.5.3 -s 1M -S 1M -M 64K -u 868b6602-cbd0-11dd-aa0c-45ce53e6b179

   Process ID:         4022 (unknown start)
   Start time:         12:20:36 AM
   End time:           12:27:16 AM
   Termination Status: n/a
   Last modified:      December 15, 2008 at 08:15 PM
   Memory model:       LP64
   Hyperthreading:     disabled in firmware

Sampling Specification
Number of samples: 478
Data sampled: ETB

Load Module Summary
---------------------------------------------
% Total
IP Cumulat IP
Samples % of Samples
(ETB) Total (ETB) Load Module
---------------------------------------------

   99.05    99.05        822136    vmlinux
    0.90    99.95          7447    cxgb3.ko
    0.04    99.98           296    libc-2.7.so
    0.01    99.99           108    netperf
    0.00   100.00            30    *kernel gateway*
    0.00   100.00            10    inet_lro.ko
    0.00   100.00             2    ld-2.7.so
    0.00   100.00             1    mptscsih.ko

---------------------------------------------
100.00 100.00 830030 Total
---------------------------------------------

Function Summary
-----------------------------------------------------------------------
% Total
IP Cumulat IP
Samples % of Samples
(ETB) Total (ETB) Function File
-----------------------------------------------------------------------

   75.45    75.45        626273   vmlinux::ia64_spinlock_contention
    4.42    79.87         36683   vmlinux::_spin_lock
    4.08    83.95         33848   vmlinux::free_block
    3.24    87.18         26856   vmlinux::____cache_alloc_node
    2.09    89.27         17334   vmlinux::__copy_user
    1.75    91.03         14554   vmlinux::fallback_alloc
    0.99    92.01          8180   vmlinux::kfree
    0.79    92.80          6540   vmlinux::kmem_cache_free
    0.61    93.41          5026   cxgb3.ko::process_responses
    0.41    93.82          3423   vmlinux::__alloc_skb
    0.36    94.18          2971   vmlinux::skb_pull
    0.26    94.43          2142   vmlinux::dst_release
    0.25    94.68          2034   vmlinux::tcp_v4_do_rcv
    0.24    94.92          2033   vmlinux::tcp_recvmsg
    0.23    95.15          1886   vmlinux::tcp_parse_md5sig_option
    0.22    95.37          1789   vmlinux::tcp_v4_rcv
    0.21    95.57          1729   vmlinux::cache_alloc_refill
    0.20    95.78          1699   vmlinux::ip_route_input
    0.20    95.98          1657   vmlinux::eth_type_trans
    0.20    96.18          1655   vmlinux::tcp_event_data_recv
    0.18    96.36          1476   vmlinux::skb_copy_datagram_iovec
    0.17    96.53          1425   vmlinux::__inet_lookup_established
    0.15    96.67          1217   vmlinux::tcp_rcv_established
    0.14    96.82          1196   cxgb3.ko::refill_fl
    0.13    96.95          1098   vmlinux::netif_receive_skb
    0.13    97.08          1040   vmlinux::cache_grow
    0.12    97.20          1036   cxgb3.ko::t3_eth_xmit
    0.11    97.31           942   vmlinux::memset

(being one of the cobbler's children I don't yet know how to use the tools to produce one combined cycles profile across the whole kernel, but each netperf looks pretty much like that).

The scgprof profile is a sampled call graph profile. I believe that it will be sensitive to whether interrupts are enabled/disabled and that may be why it looks rather different.

All three - cycles, scgprof and dmesg output, along with the config for the kernel build can be found under:

ftp://ftp.netperf.org/lockup

At this point I'm open to suggestion for next steps. My linux kernel debugging experience is close to epsilon but I can follow explicit direction pretty well.

FWIW an outbound test (from the rx8640 to the dl585's) does not appear to generate soft lockup messages.

rick jones

Hi Rick,

Can you please reconfigure your kernel with the following kernel hacking options enabled, and run your tests again?

Kernel hacking
Kernel debugging
Detect soft lockups
RT mutex debugging
Spinlock and rw-lock debugging: basic checks Mutex debugging: basic checks
Lock debugging: detect incorrect freeing of live locks Lock debugging: prove locking correctness Spinlock debugging: sleep-inside-spinlock checking Compile the kernel with debug info
Compile the kernel with frame pointers

Cheers,
Divy

Got the above

I don't see those two above in a make menuconfig

Got those above.

That doesn't appear in make menuconfig in kernel hacking either.

I built a kernel with those I could find enabled, and I think it invoked the spirit of Heisenberg - no more soft lockups appearing on the console. I think it has also _significantly_ dropped the throughput.

I've since learned how to tell caliper one doesn't care about the per-process stuff and just lump it all together. The cycles and cgprof profiles for the debug run can be found under the same URL as before:

ftp://ftp.netperf.org/lockup

with what I hope are obvious names.

rick jones