Bug 498024

Summary: "CPU#foo stuck for 10s!" when using bonding with use_carrier=0
Product: Red Hat Enterprise Linux 5 Reporter: Veaceslav Falico <vfalico>
Component: kernelAssignee: Andy Gospodarek <agospoda>
Status: CLOSED INSUFFICIENT_DATA QA Contact: Red Hat Kernel QE team <kernel-qe>
Severity: medium Docs Contact:
Priority: low    
Version: 5.2CC: anton, fbijlsma, jpirko, nhorman, peterm, tao, vincent.leriche, xiaobao623
Target Milestone: rc   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2009-08-07 19:31:49 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Veaceslav Falico 2009-04-28 14:28:03 UTC
Description of problem:
When network cards are bonded (mode 0) system eventually locks up with "CPU#foo stuck for 10s!" messages in logs.

How reproducible:
Always, but sometimes takes days for it to occur

Steps to Reproduce:
1) Setup DELL PE1950 server, installed an Intel PT1000 M dual port NIC adapter into the server riser slot.

2) Boot up the server, installed RH5.2  2.6.18-92.el5.
No external drivers installed for NIC devices, all NIC drivers are RH native no matter for Intel PT1000 or Broadcom 5708 LOM on DELL PE1950.

3) After OS installation, setup NIC bonding under mode1.
It is either a Broadcom 5708+ Intel PT1000 Port combination,  or a Broadcom5708+Broadcom 5708 combination.

Actual results:
System eventually locks up after some random period of time.

Expected results:
System does not lock up when nics are bonded

Additional info:

1. HW configurations:
DELL PE1950 Server
5310 Intel Quad Core processors X  2pcs
FBDIMM 1GB X4
SAS 5i Hard Drive Adapter RAID1
Lan on motherboard Boradcom 5708 LAN 2 ports
Intel PT1000M Gigabit Adapter 2 ports

2.  The first error happened on Jun,15th, 2008.
After that, this issue continuously happened.

3.  The current workaround is not bonding the NICs or using use_carrier=1.

4.  We also tried bond the broadcom + braodcom LAN ports and
Intel+ Intel ports, same error.

5.  Below is some details on the system log:
As off about two weeks ago i've started putting a bit of load across  
the active node, and found that after about 3-4 days at least one node  
will fail. The errors i get are in two forms

The short one which just has a soft lockup, and the long kind that  
includes an oom_killer message.

First the short kind:

2008-06-15T04:25:58.134710+10:00 fiction kernel:<3>BUG: soft lockup -  
CPU#3 stuck for 10s! [bond1:3095]
2008-06-15T04:25:58.134718+10:00 fiction kernel:<4>CPU 3:
2008-06-15T04:25:58.134923+10:00 fiction kernel:<4>Modules linked in:  
nfsd exportfs lockd nfs_acl auth_rpcgss autofs4 lock_dlm gfs2 dlm  
configfs sunrpc bonding ip_conntrack_netbios_ns ipt_REJECT ipt_LOG  
xt_limit xt_tcpudp xt_state ip_c
onntrack nfnetlink iptable_filter ip_tables 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  
ide_cd shpchp sr_mod e1000e cdrom
i5000_edac bnx2 edac_mc pcspkr serio_raw sg 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-15T04:25:58.134927+10:00 fiction kernel:<4>Pid: 3095, comm:  
bond1 Not tainted 2.6.18-92.1.1.el5 #1
2008-06-15T04:25:58.135186+10:00 fiction kernel:<4>RIP: 0010:
[.text.lock.spinlock+41/48]  [.text.lock.spinlock
+41/48] .text.lock.spinlock+0x29/0x30
2008-06-15T04:25:58.135191+10:00 fiction kernel:<4>RSP:  
0018:ffff81012c7cdd20  EFLAGS: 00000286
2008-06-15T04:25:58.135195+10:00 fiction kernel:<4>RAX:  
ffff81012c7cdfd8 RBX: ffff81012b138000 RCX: ffff81012c7cdd80
2008-06-15T04:25:58.135199+10:00 fiction kernel:<4>RDX:  
0000000000008948 RSI: ffff81012c7cdd70 RDI: ffff81012b138714
2008-06-15T04:25:58.135203+10:00 fiction kernel:<4>RBP:  
ffff81012d921a20 R08: ffff81012c7cdd50 R09: 000000000000003d
2008-06-15T04:25:58.135207+10:00 fiction kernel:<4>R10:  
ffff81012fc5c008 R11: 0000000000000003 R12: 000000000000000c
2008-06-15T04:25:58.135212+10:00 fiction kernel:<4>R13:  
ffff81012c7cdd70 R14: ffff81012b138000 R15: ffff81012fa64100
2008-06-15T04:25:58.135216+10:00 fiction kernel:<4>FS:   
0000000000000000(0000) GS:ffff81010439c640(0000) knlGS:0000000000000000
2008-06-15T04:25:58.135221+10:00 fiction kernel:<4>CS:  0010 DS: 0018  
ES: 0018 CR0: 000000008005003b
2008-06-15T04:25:58.135225+10:00 fiction kernel:<4>CR2:  
0000000011a4e388 CR3: 0000000000201000 CR4: 00000000000006e0
2008-06-15T04:25:58.135228+10:00 fiction kernel:<4>
2008-06-15T04:25:58.135232+10:00 fiction kernel:<4>Call Trace:
2008-06-15T04:25:58.135457+10:00 fiction kernel:<4> [bnx2:bnx2_ioctl
+105/255] :bnx2:bnx2_ioctl+0x69/0xff
2008-06-15T04:25:58.135574+10:00 fiction kernel:<4>  
[bonding:bond_check_dev_link+211/441] :bonding:bond_check_dev_link
+0xd3/0x1b9
2008-06-15T04:25:58.135596+10:00 fiction kernel:<4> [thread_return
+0/223] thread_return+0x0/0xdf
2008-06-15T04:25:58.135707+10:00 fiction kernel:<4>  
[bonding:__bond_mii_monitor+136/1092] :bonding:__bond_mii_monitor
+0x88/0x444
2008-06-15T04:25:58.135815+10:00 fiction kernel:<4>  
[bonding:bond_mii_monitor+0/140] :bonding:bond_mii_monitor+0x0/0x8c
2008-06-15T04:25:58.135922+10:00 fiction kernel:<4>  
[bonding:bond_mii_monitor+45/140] :bonding:bond_mii_monitor+0x2d/0x8c
2008-06-15T04:25:58.135981+10:00 fiction kernel:<4> [run_workqueue
+148/228] run_workqueue+0x94/0xe4
2008-06-15T04:25:58.135999+10:00 fiction kernel:<4> [worker_thread
+0/290] worker_thread+0x0/0x122
2008-06-15T04:25:58.136025+10:00 fiction kernel:<4>  
[keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-15T04:25:58.136042+10:00 fiction kernel:<4> [worker_thread
+240/290] worker_thread+0xf0/0x122
2008-06-15T04:25:58.136064+10:00 fiction kernel:<4>  
[<ffffffff8008ad26>] default_wake_function+0x0/0xe
2008-06-15T04:25:58.136088+10:00 fiction kernel:<4>  
[keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-15T04:25:58.136117+10:00 fiction kernel:<4>  
[keventd_create_kthread+0/196] keventd_create_kthread+0x0/0xc4
2008-06-15T04:25:58.136133+10:00 fiction kernel:<4> [kthread+254/306]  
kthread+0xfe/0x132
2008-06-15T04:25:58.136151+10:00 fiction kernel:<4> [child_rip+10/17]  
child_rip+0xa/0x11
2008-06-15T04:25:58.136176+10:00 fiction kernel:<4>

Comment 1 Veaceslav Falico 2009-04-28 14:29:18 UTC
As a shot, I think commit f0c76d61779b153dbfb955db3f144c62d02173c2 from upstream (http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=f0c76d61779b153dbfb955db3f144c62d02173c2 ) should fix the issue, however, still didn't manage to test it.

Comment 2 Jiri Pirko 2009-04-29 13:28:33 UTC
Hi Veaceslav.

Can you please try if this issue appears with Andy's upgrade patch posted here:

http://post-office.corp.redhat.com/archives/rhkernel-list/2009-April/msg01231.html

Thanks

Comment 3 Andy Gospodarek 2009-04-30 15:44:56 UTC
Veaceslav, use_carrier=1 works around this issue because bond_check_dev_link looks if use_carrier is set and just calls netif_carrier_ok rather than actually calling down to the driver and checking the hardware.

What other applications or commands are running when this happens?

Do you also notice anything in the logs that the interface goes down right before this happens?

__bond_mii_monitor is called once with rtnl locked and if a change is needed, is called again with it locked.  I'm not currently aware of any possible contention over the bnx2 driver's phy_lock and rtnl, but that was the first thing that came to my mind.  Did you say you have a longer message with more information?  If so, please attach it to the bug.

You should also consider testing 5.3 as well as my test kernels here:

http://people.redhat.com/agospoda/#rhel5

Thanks!

Comment 4 Andy Gospodarek 2009-05-12 15:29:52 UTC
*** Bug 499109 has been marked as a duplicate of this bug. ***

Comment 6 Andy Gospodarek 2009-05-27 16:33:26 UTC
Veaceslav were you able to test with the latest RHEL5 kernels from here:

http://people.redhat.com/agospoda/#rhel5

or

http://people.redhat.com/dzickus/el5 

Thanks!

Comment 8 Andy Gospodarek 2009-06-23 13:15:19 UTC
Veaceslav, any feedback on your testing?

Comment 9 Veaceslav Falico 2009-06-23 14:10:12 UTC
Nope :(, customer with the reproducer is unreachable. From my pov, this BZ can be closed cause of insufficient data...

Thank you!

Comment 10 York Zhang 2009-06-30 06:48:42 UTC
I also have same error log.
OS: RHEL 5.2 x86_64
kernel: Linux DZGZ001.shbank.net 2.6.18-128.el5 #1 SMP Wed Dec 17 11:41:38 EST 2008 x86_64 x86_64 x86_64 GNU/Linux

Hardware HP DL580G5 (6 core Intel 7450 CPU) ,32GB,
05:00.0 PCI bridge: Broadcom EPB PCI-Express to PCI-X Bridge (rev c3)
06:00.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM5708 Gigabit Ethernet (rev 12)
07:00.0 PCI bridge: Broadcom EPB PCI-Express to PCI-X Bridge (rev c3)
08:00.0 Ethernet controller: Broadcom Corporation NetXtreme II BCM5708 Gigabit Ethernet (rev 12)
0d:00.0 Ethernet controller: Intel Corporation 82571EB Gigabit Ethernet Controller (rev 06)
0d:00.1 Ethernet controller: Intel Corporation 82571EB Gigabit Ethernet Controller (rev 06)

log messages

Jun 30 13:18:58 DZGZ001 kernel: BUG: soft lockup - CPU#15 stuck for 10s! [bond0:4167]
Jun 30 13:18:58 DZGZ001 kernel: CPU 15:
Jun 30 13:18:58 DZGZ001 kernel: Modules linked in: lock_dlm gfs2 dlm configfs mptctl mptbase sg ipmi_si(U) ipmi_devintf(U) ip
mi_msghandler(U) autofs4 hidp l2cap bluetooth sunrpc bonding ip_conntrack_ftp ip_conntrack_netbios_ns ipt_REJECT xt_state ip_
conntrack nfnetlink xt_tcpudp iptable_filter ip_tables x_tables dm_mirror dm_log dm_multipath scsi_dh dm_mod video hwmon back
light sbs i2c_ec i2c_core button battery asus_acpi acpi_memhotplug ac ipv6 xfrm_nalgo crypto_api parport_pc lp parport e1000e
 bnx2(U) serio_raw shpchp hpilo pcspkr qla2xxx(FU) qla2xxx_conf(FU) intermodule(U) ata_piix libata cciss(U) sd_mod scsi_mod e
xt3 jbd ehci_hcd ohci_hcd uhci_hcd
Jun 30 13:18:58 DZGZ001 kernel: Pid: 4167, comm: bond0 Tainted: GF     2.6.18-128.el5 #1
Jun 30 13:18:58 DZGZ001 kernel: RIP: 0010:[<ffffffff80064cd8>]  [<ffffffff80064cd8>] .text.lock.spinlock+0x26/0x30
Jun 30 13:18:58 DZGZ001 kernel: RSP: 0018:ffff810822b27d20  EFLAGS: 00000286
Jun 30 13:18:58 DZGZ001 kernel: RAX: ffff810822b27fd8 RBX: ffff81082df60000 RCX: ffff810822b27d80
Jun 30 13:18:58 DZGZ001 kernel: RDX: 0000000000008948 RSI: ffff810822b27d70 RDI: ffff81082df637c0
Jun 30 13:18:58 DZGZ001 kernel: RBP: ffff810807155480 R08: ffff810822b27d50 R09: ffff81080404eac0
Jun 30 13:18:58 DZGZ001 kernel: R10: ffff8107f4290b40 R11: 0000000000000246 R12: ffff81081d360bc0
Jun 30 13:18:58 DZGZ001 kernel: R13: 0000000000000246 R14: 0000000000000001 R15: 0000000000000000
Jun 30 13:18:58 DZGZ001 kernel: FS:  0000000000000000(0000) GS:ffff81082fcccc40(0000) knlGS:0000000000000000
Jun 30 13:18:58 DZGZ001 kernel: CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
Jun 30 13:18:58 DZGZ001 kernel: CR2: 00002aaaaacd5000 CR3: 0000000000201000 CR4: 00000000000006e0
Jun 30 13:18:58 DZGZ001 kernel: 
Jun 30 13:18:58 DZGZ001 kernel: Call Trace:
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff882c84ee>] :bnx2:bnx2_ioctl+0x69/0xff
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff88500f1f>] :bonding:bond_check_dev_link+0xd3/0x1b9
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff80063097>] thread_return+0x62/0xfe
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff885025c9>] :bonding:__bond_mii_monitor+0x88/0x444
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8850399a>] :bonding:bond_mii_monitor+0x0/0x8c
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff885039c7>] :bonding:bond_mii_monitor+0x2d/0x8c
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8004d139>] run_workqueue+0x94/0xe4
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff800499ba>] worker_thread+0x0/0x122
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8009d909>] keventd_create_kthread+0x0/0xc4
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff80049aaa>] worker_thread+0xf0/0x122
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8008a461>] default_wake_function+0x0/0xe
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8009d909>] keventd_create_kthread+0x0/0xc4
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8009d909>] keventd_create_kthread+0x0/0xc4
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff80032360>] kthread+0xfe/0x132
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8005dfb1>] child_rip+0xa/0x11
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8009d909>] keventd_create_kthread+0x0/0xc4
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff80032262>] kthread+0x0/0x132
Jun 30 13:18:58 DZGZ001 kernel:  [<ffffffff8005dfa7>] child_rip+0x0/0x11
Jun 30 13:18:58 DZGZ001 kernel:

Comment 11 York Zhang 2009-06-30 06:56:05 UTC
I have two bonding, bnx2+intel . I have install RHEL 5.1 before, but s the system orfen no respond or reboot, and no error log message in syslog. 
So, I update to RHEL 5.3 now.  But I saw the BUG soft lockup message, and the system still no respond or reboot some time.

Comment 12 Andy Gospodarek 2009-06-30 13:25:21 UTC
York, were you able to test with the latest RHEL5 kernels from here:

http://people.redhat.com/agospoda/#rhel5

or

http://people.redhat.com/dzickus/el5 

Thanks!

Comment 13 York Zhang 2009-07-02 05:07:55 UTC
I have try not  using parameter "use_carrier=1", the error messages not comes . So I will try add again to confirm this parameter and monitor syslog.

Comment 14 York Zhang 2009-07-02 05:52:13 UTC
Sorry, I use " use_carrier=0" , not 1 .