Bug 706414 - Adding slave to balance-tlb bond device results in soft lockup
Summary: Adding slave to balance-tlb bond device results in soft lockup
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 5
Classification: Red Hat
Component: kernel
Version: 5.6
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: rc
: ---
Assignee: Neil Horman
QA Contact: Jan Tluka
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2011-05-20 13:56 UTC by Jan Tluka
Modified: 2011-07-21 10:21 UTC (History)
4 users (show)

Fixed In Version: kernel-2.6.18-266.el5
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2011-07-21 10:21:49 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
patch to prevent enslaving NICS when bond isn't up. (511 bytes, patch)
2011-05-23 19:38 UTC, Neil Horman
no flags Details | Diff


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2011:1065 0 normal SHIPPED_LIVE Important: Red Hat Enterprise Linux 5.7 kernel security and bug fix update 2011-07-21 09:21:37 UTC

Description Jan Tluka 2011-05-20 13:56:51 UTC
Description of problem:

Using balance-tlb mode of bond device results in hang (soft lockup) of the system. It happens immediately after adding slave device to a bond device.

I'm using a KVM virtual guest with following network setup,

    <interface type='bridge'>
      <mac address='52:54:00:70:4b:07'/>
      <source bridge='br0'/>
      <model type='virtio'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x03' function='0x0'/>
    </interface>
    <interface type='network'>
      <mac address='52:54:00:87:83:25'/>
      <source network='default'/>
      <model type='e1000'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x08' function='0x0'/>
    </interface>
    <interface type='network'>
      <mac address='52:54:00:d5:62:96'/>
      <source network='default'/>
      <model type='e1000'/>
      <address type='pci' domain='0x0000' bus='0x00' slot='0x09' function='0x0'/>

I'm using two last interfaces for bonding first one is not involved.

Version-Release number of selected component (if applicable):

I've tried all of these kernels with the same result
-262.el5
-256.el5 
-238.el5

How reproducible:
Everytime

Steps to Reproduce:
1. echo +bond5 > /sys/class/net/bonding_masters
2. echo +eth1 > /sys/class/net/bond5/bonding/slaves
3. system stops responding, wait for lockup message on console
  
Actual results:

BUG: soft lockup - CPU#0 stuck for 60s! [bash:2252]
CPU 0:
Modules linked in: bonding autofs4 hidp rfcomm l2cap bluetooth lockd sunrpc ip6t_REJECT xt_tcpudp ip6table_filter ip6_tables x_tables ipv6 xfrm_nalgo crypto_api loop dm_multipath scsi_dh video backlight sbs power_meter hwmon i2c_ec dell_wmi wmi button battery asus_acpi acpi_memhotplug ac parport_pc lp parport floppy snd_intel8x0 snd_ac97_codec ac97_bus snd_seq_dummy snd_seq_oss pcspkr snd_seq_midi_event snd_seq snd_seq_device e1000 snd_pcm_oss snd_mixer_oss snd_pcm virtio_net virtio_balloon snd_timer snd tpm_tis i2c_piix4 soundcore i2c_core tpm serio_raw snd_page_alloc tpm_bios dm_raid45 dm_message dm_region_hash dm_mem_cache dm_snapshot dm_zero dm_mirror dm_log dm_mod ata_piix libata sd_mod scsi_mod virtio_blk virtio_pci virtio_ring virtio ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Pid: 2252, comm: bash Not tainted 2.6.18-262.el5 #1
RIP: 0010:[<ffffffff80064bf3>]  [<ffffffff80064bf3>] .text.lock.spinlock+0x29/0x30
RSP: 0018:ffff810012fa3d18  EFLAGS: 00000286
RAX: ffff810012fa3fd8 RBX: ffff81001ceaa000 RCX: 0000000000000000
RDX: 0000000000000001 RSI: ffff81001ceaa000 RDI: ffff81001cd756f8
RBP: 0000000000000000 R08: ffffffff8031df28 R09: 000000000000003e
R10: ffff810012fa3a38 R11: 0000000000000080 R12: ffff81001cd75500
R13: ffff81001cd75500 R14: 0000000000000000 R15: 0000000000000000
FS:  00002b2fcb796f50(0000) GS:ffffffff8042a000(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00002b2fcef86000 CR3: 000000001c94b000 CR4: 00000000000006e0

Call Trace:
 [<ffffffff80064af9>] _spin_lock_bh+0x9/0x14
 [<ffffffff885f27d7>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff885f3f84>] :bonding:bond_alb_handle_active_change+0xc3/0x192
 [<ffffffff885ec555>] :bonding:bond_change_active_slave+0x1e2/0x4bc
 [<ffffffff885ecbc4>] :bonding:bond_select_active_slave+0xca/0xf8
 [<ffffffff885edb70>] :bonding:bond_enslave+0x907/0xa77
 [<ffffffff8006457b>] __down_write_nested+0x12/0x92
 [<ffffffff885f5a3e>] :bonding:bonding_store_slaves+0x1b6/0x2f7
 [<ffffffff801106f7>] sysfs_write_file+0xb9/0xe8
 [<ffffffff80016b87>] vfs_write+0xce/0x174
 [<ffffffff80017450>] sys_write+0x45/0x6e
 [<ffffffff8005d28d>] tracesys+0xd5/0xe0

Expected results:
No soft lockup.

Additional info:

Comment 1 Jan Tluka 2011-05-20 14:18:06 UTC
I tried this on a real hardware to check if this is just virt issue.

Adding an interface with no link present passed without an issue. But removing it from bond gave similar soft lockup trace:

[root@dell-per715-01 ~]# echo +bond5 > /sys/class/net/bonding_masters
[root@dell-per715-01 ~]# echo +eth1 > /sys/class/net/bond5/bonding/slaves
bonding: bond5: doing slave updates when interface is down.
bonding bond5: master_dev is not up in bond_enslave
[root@dell-per715-01 ~]# echo -eth1 > /sys/class/net/bond5/bonding/slaves
bonding: bond5: doing slave updates when interface is down.

BUG: soft lockup - CPU#12 stuck for 60s! [bash:6444]
CPU 12:
Modules linked in: bonding autofs4 hidp rfcomm l2cap bluetooth lockd sunrpc be2d
Pid: 6444, comm: bash Not tainted 2.6.18-262.el5 #1
RIP: 0010:[<ffffffff80064bf0>]  [<ffffffff80064bf0>] .text.lock.spinlock+0x26/00
RSP: 0018:ffff810113167da8  EFLAGS: 00000286
RAX: ffff810113167fd8 RBX: ffff810123a47800 RCX: 0000000000ff1025
RDX: 0000000000000000 RSI: ffff810123a47800 RDI: ffff81021b57f6f8
RBP: ffff81021b57f500 R08: 0000000000000000 R09: 000000000000000c
R10: 00000000ffffffff R11: ffff81011d41c000 R12: ffff81021b57f000
R13: 0000000000000000 R14: 0000000000000282 R15: 0000000000000282
FS:  00002b3b41ef3f50(0000) GS:ffff810123b27940(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00002b3b456dd000 CR3: 000000031fc60000 CR4: 00000000000006e0

Call Trace:
 [<ffffffff80064af9>] _spin_lock_bh+0x9/0x14
 [<ffffffff886937d7>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff8869423c>] :bonding:bond_alb_deinit_slave+0xba/0xf0
 [<ffffffff8868dda6>] :bonding:bond_release+0x1b4/0x450
 [<ffffffff8006457b>] __down_write_nested+0x12/0x92
 [<ffffffff88696ae4>] :bonding:bonding_store_slaves+0x25c/0x2f7
 [<ffffffff801106f7>] sysfs_write_file+0xb9/0xe8
 [<ffffffff80016b87>] vfs_write+0xce/0x174
 [<ffffffff80017450>] sys_write+0x45/0x6e
 [<ffffffff8005d28d>] tracesys+0xd5/0xe0

Comment 2 Jan Tluka 2011-05-20 14:28:14 UTC
Further observations: 

Changing the model type in __guest__ configuration does not have an impact on the result.

On bare metal, I've tried to put an interface with link present into bond and this made no difference against device with no link present but soft lockup was present after removing the device from bond (same as in comment #2).

So there seem to be two bugs present in bonding driver.

The original is affecting virt setups only and second one (removing slave from balance-tlb bond) affecting bare metal.

Should we treat them separately?

Comment 3 Andy Gospodarek 2011-05-20 14:44:13 UTC
Looks like contention over the tx_hashtbl lock.  Requested on IRC that the reporter run with the debug kernel to see if lock debug gives us any insight.

Comment 4 Andy Gospodarek 2011-05-20 14:50:23 UTC
(In reply to comment #2)
> 
> So there seem to be two bugs present in bonding driver.
> 
> The original is affecting virt setups only and second one (removing slave from
> balance-tlb bond) affecting bare metal.
> 
> Should we treat them separately?

The same fix will probably resolve both bugs, so we can just use one bug for this.

Comment 5 Jan Tluka 2011-05-20 14:56:50 UTC
Running on kernel-debug (-262.el5) I get following output:

[root@dhcp-26-104 ~]# echo +bond5 > /sys/class/net/bonding_masters
[root@dhcp-26-104 ~]# echo +eth1 > /sys/class/net/bond5/bonding/slaves
bonding: bond5: doing slave updates when interface is down.
bonding bond5: master_dev is not up in bond_enslave
INFO: trying to register non-static key.
the code is fine but needs lockdep annotation.
turning off the locking correctness validator.

Call Trace:
 [<ffffffff800ac54f>] __lock_acquire+0x9a/0xa9e
 [<ffffffff800acfa8>] lock_acquire+0x55/0x6f
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff800684b5>] _spin_lock_bh+0x2b/0x57
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff8860559c>] :bonding:bond_alb_handle_active_change+0xc3/0x195
 [<ffffffff885fe830>] :bonding:bond_change_active_slave+0x1e2/0x4ce
 [<ffffffff88600286>] :bonding:bond_enslave+0x79f/0xa7d
 [<ffffffff885feeb9>] :bonding:bond_select_active_slave+0xd2/0x100
 [<ffffffff886003f1>] :bonding:bond_enslave+0x90a/0xa7d
 [<ffffffff800aa4bb>] lock_release_holdtime+0x27/0x48
 [<ffffffff88607af7>] :bonding:bonding_store_slaves+0x1b8/0x2fb
 [<ffffffff8011d2ba>] sysfs_write_file+0xca/0xf9
 [<ffffffff8001788b>] vfs_write+0xce/0x174
 [<ffffffff8001817f>] sys_write+0x45/0x6e
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

BUG: spinlock lockup on CPU#0, bash/2573, ffff81001b9bd8e0 (Not tainted)

Call Trace:
 [<ffffffff800079e5>] _raw_spin_lock+0xcd/0xeb
 [<ffffffff800684d6>] _spin_lock_bh+0x4c/0x57
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff8860559c>] :bonding:bond_alb_handle_active_change+0xc3/0x195
 [<ffffffff885fe830>] :bonding:bond_change_active_slave+0x1e2/0x4ce
 [<ffffffff88600286>] :bonding:bond_enslave+0x79f/0xa7d
 [<ffffffff885feeb9>] :bonding:bond_select_active_slave+0xd2/0x100
 [<ffffffff886003f1>] :bonding:bond_enslave+0x90a/0xa7d
 [<ffffffff800aa4bb>] lock_release_holdtime+0x27/0x48
 [<ffffffff88607af7>] :bonding:bonding_store_slaves+0x1b8/0x2fb
 [<ffffffff8011d2ba>] sysfs_write_file+0xca/0xf9
 [<ffffffff8001788b>] vfs_write+0xce/0x174
 [<ffffffff8001817f>] sys_write+0x45/0x6e
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

Comment 6 Jan Tluka 2011-05-20 15:17:15 UTC
This might be more useful ...

[root@dhcp-26-104 ~]# echo +eth1 > /sys/class/net/bond5/bonding/slaves
bonding: bond5: doing slave updates when interface is down.
bonding bond5: master_dev is not up in bond_enslave
INFO: trying to register non-static key.
the code is fine but needs lockdep annotation.
turning off the locking correctness validator.

Call Trace:
 [<ffffffff800ac54f>] __lock_acquire+0x9a/0xa9e
 [<ffffffff800acfa8>] lock_acquire+0x55/0x6f
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff800684b5>] _spin_lock_bh+0x2b/0x57
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff8860559c>] :bonding:bond_alb_handle_active_change+0xc3/0x195
 [<ffffffff885fe830>] :bonding:bond_change_active_slave+0x1e2/0x4ce
 [<ffffffff88600286>] :bonding:bond_enslave+0x79f/0xa7d
 [<ffffffff885feeb9>] :bonding:bond_select_active_slave+0xd2/0x100
 [<ffffffff886003f1>] :bonding:bond_enslave+0x90a/0xa7d
 [<ffffffff800aa4bb>] lock_release_holdtime+0x27/0x48
 [<ffffffff88607af7>] :bonding:bonding_store_slaves+0x1b8/0x2fb
 [<ffffffff8011d2ba>] sysfs_write_file+0xca/0xf9
 [<ffffffff8001788b>] vfs_write+0xce/0x174
 [<ffffffff8001817f>] sys_write+0x45/0x6e
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

BUG: spinlock lockup on CPU#1, bash/2593, ffff8100100128e0 (Not tainted)

Call Trace:
 [<ffffffff800079e5>] _raw_spin_lock+0xcd/0xeb
 [<ffffffff800684d6>] _spin_lock_bh+0x4c/0x57
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff8860559c>] :bonding:bond_alb_handle_active_change+0xc3/0x195
 [<ffffffff885fe830>] :bonding:bond_change_active_slave+0x1e2/0x4ce
 [<ffffffff88600286>] :bonding:bond_enslave+0x79f/0xa7d
 [<ffffffff885feeb9>] :bonding:bond_select_active_slave+0xd2/0x100
 [<ffffffff886003f1>] :bonding:bond_enslave+0x90a/0xa7d
 [<ffffffff800aa4bb>] lock_release_holdtime+0x27/0x48
 [<ffffffff88607af7>] :bonding:bonding_store_slaves+0x1b8/0x2fb
 [<ffffffff8011d2ba>] sysfs_write_file+0xca/0xf9
 [<ffffffff8001788b>] vfs_write+0xce/0x174
 [<ffffffff8001817f>] sys_write+0x45/0x6e
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

INFO: task events/0:8 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
events/0      D ffff81001fa11108     0     8      1             9     7 (L-TLB)
 ffff81001ff4bda0 0000000000000046 ffff81001cb9c000 0000000000000001
 0000000000000002 000000000000000a ffff81001ff48240 ffffffff8032bd40
 0000003d65e2a868 00000000001f0ffd ffff81001ff48428 0000000000000046
Call Trace:
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff80067233>] mutex_lock_nested+0x16f/0x27c
 [<ffffffff8024dd48>] linkwatch_event+0x0/0x30
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff8004fbab>] run_workqueue+0xa4/0x107
 [<ffffffff8004c319>] worker_thread+0x0/0x122
 [<ffffffff8004c409>] worker_thread+0xf0/0x122
 [<ffffffff80092da9>] default_wake_function+0x0/0xe
 [<ffffffff800ac160>] trace_hardirqs_on+0x102/0x126
 [<ffffffff800347ca>] kthread+0xfe/0x132
 [<ffffffff80067f71>] trace_hardirqs_on_thunk+0x35/0x37
 [<ffffffff80061079>] child_rip+0xa/0x11
 [<ffffffff80068875>] _spin_unlock_irq+0x24/0x27
 [<ffffffff800606a8>] restore_args+0x0/0x30
 [<ffffffff800346cc>] kthread+0x0/0x132
 [<ffffffff8006106f>] child_rip+0x0/0x11

1 lock held by events/0/8:
 #0:  (&adapter->stats_lock){....}, at: [<ffffffff882016bb>] e1000_update_stats+0x3d/0x5f4 [e1000]
INFO: task events/0:8 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
events/0      D ffff81001fa11108     0     8      1             9     7 (L-TLB)
 ffff81001ff4bda0 0000000000000046 ffff81001cb9c000 0000000000000001
 0000000000000002 000000000000000a ffff81001ff48240 ffffffff8032bd40
 0000003d65e2a868 00000000001f0ffd ffff81001ff48428 0000000000000046
Call Trace:
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff80067233>] mutex_lock_nested+0x16f/0x27c
 [<ffffffff8024dd48>] linkwatch_event+0x0/0x30
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff8004fbab>] run_workqueue+0xa4/0x107
 [<ffffffff8004c319>] worker_thread+0x0/0x122
 [<ffffffff8004c409>] worker_thread+0xf0/0x122
 [<ffffffff80092da9>] default_wake_function+0x0/0xe
 [<ffffffff800ac160>] trace_hardirqs_on+0x102/0x126
 [<ffffffff800347ca>] kthread+0xfe/0x132
 [<ffffffff80067f71>] trace_hardirqs_on_thunk+0x35/0x37
 [<ffffffff80061079>] child_rip+0xa/0x11
 [<ffffffff80068875>] _spin_unlock_irq+0x24/0x27
 [<ffffffff800606a8>] restore_args+0x0/0x30
 [<ffffffff800346cc>] kthread+0x0/0x132
 [<ffffffff8006106f>] child_rip+0x0/0x11

1 lock held by events/0/8:
 #0:  (&adapter->stats_lock){....}, at: [<ffffffff882016bb>] e1000_update_stats+0x3d/0x5f4 [e1000]
INFO: task irqbalance:2193 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
irqbalance    D ffff81001f5d3148     0  2193      1          2203  2125 (NOTLB)
 ffff81001bc11d58 0000000000000046 ffff81001f5d31b8 0000000000000296
 0000000000000002 0000000000000007 ffff810013eb6440 ffffffff8032bd40
 0000005e74725fb2 00000000000b44e1 ffff810013eb6628 000000001f5d31b8
Call Trace:
 [<ffffffff80246856>] dev_ioctl+0x309/0x474
 [<ffffffff80067233>] mutex_lock_nested+0x16f/0x27c
 [<ffffffff80246856>] dev_ioctl+0x309/0x474
 [<ffffffff8023ba65>] sock_ioctl+0x1da/0x1eb
 [<ffffffff80044499>] do_ioctl+0x21/0x6b
 [<ffffffff80031c22>] vfs_ioctl+0x45d/0x4bf
 [<ffffffff8004eac6>] sys_ioctl+0x59/0x78
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

no locks held by irqbalance/2193.
BUG: soft lockup - CPU#1 stuck for 60s! [bash:2593]
CPU 1:
Modules linked in: bonding autofs4 hidp rfcomm l2cap bluetooth lockd sunrpc ip6t_REJECT xt_tcpudp ip6table_filter ip6_tables x_tables ipv6 xfrm_nalgo crypto_api loop dm_multipath scsi_dh video backlight sbs power_meter hwmon i2c_ec dell_wmi wmi button battery asus_acpi acpi_memhotplug ac parport_pc lp parport floppy virtio_balloon pcspkr snd_intel8x0 snd_ac97_codec serio_raw ac97_bus snd_seq_dummy snd_seq_oss snd_seq_midi_event snd_seq snd_seq_device i2c_piix4 snd_pcm_oss i2c_core snd_mixer_oss snd_pcm snd_timer snd e1000 soundcore snd_page_alloc virtio_net tpm_tis tpm tpm_bios dm_raid45 dm_message dm_region_hash dm_mem_cache dm_snapshot dm_zero dm_mirror dm_log dm_mod ata_piix libata sd_mod scsi_mod virtio_blk virtio_pci virtio_ring virtio ext3 jbd uhci_hcd ohci_hcd ehci_hcd
Pid: 2593, comm: bash Not tainted 2.6.18-262.el5debug #1
RIP: 0010:[<ffffffff80007985>]  [<ffffffff80007985>] _raw_spin_lock+0x6d/0xeb
RSP: 0018:ffff8100180e3cf8  EFLAGS: 00000246
RAX: 0000000000000000 RBX: ffff8100100128e0 RCX: 0000000000000000
RDX: 00000000097928c2 RSI: 0000000000000000 RDI: ffffffff803368e0
RBP: ffff810012b1ee80 R08: 0000000000000002 R09: ffffffff80017f4d
R10: ffffffff80567e01 R11: ffffffff800b24fe R12: 000000000000097c
R13: 0000000000000000 R14: ffff8100180e2000 R15: 0000000000000200
FS:  00002b085d324f50(0000) GS:ffff81001fc964c8(0000) knlGS:0000000000000000
CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
CR2: 00002b0860b13000 CR3: 0000000011a7b000 CR4: 00000000000006e0

Call Trace:
 [<ffffffff800079e5>] _raw_spin_lock+0xcd/0xeb
 [<ffffffff800684d6>] _spin_lock_bh+0x4c/0x57
 [<ffffffff88604a5f>] :bonding:tlb_clear_slave+0x22/0xa1
 [<ffffffff8860559c>] :bonding:bond_alb_handle_active_change+0xc3/0x195
 [<ffffffff885fe830>] :bonding:bond_change_active_slave+0x1e2/0x4ce
 [<ffffffff88600286>] :bonding:bond_enslave+0x79f/0xa7d
 [<ffffffff885feeb9>] :bonding:bond_select_active_slave+0xd2/0x100
 [<ffffffff886003f1>] :bonding:bond_enslave+0x90a/0xa7d
 [<ffffffff800aa4bb>] lock_release_holdtime+0x27/0x48
 [<ffffffff88607af7>] :bonding:bonding_store_slaves+0x1b8/0x2fb
 [<ffffffff8011d2ba>] sysfs_write_file+0xca/0xf9
 [<ffffffff8001788b>] vfs_write+0xce/0x174
 [<ffffffff8001817f>] sys_write+0x45/0x6e
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

INFO: task events/0:8 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
events/0      D ffff81001fa11108     0     8      1             9     7 (L-TLB)
 ffff81001ff4bda0 0000000000000046 ffff81001cb9c000 0000000000000001
 0000000000000002 000000000000000a ffff81001ff48240 ffffffff8032bd40
 0000003d65e2a868 00000000001f0ffd ffff81001ff48428 0000000000000046
Call Trace:
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff80067233>] mutex_lock_nested+0x16f/0x27c
 [<ffffffff8024dd48>] linkwatch_event+0x0/0x30
 [<ffffffff8024dd51>] linkwatch_event+0x9/0x30
 [<ffffffff8004fbab>] run_workqueue+0xa4/0x107
 [<ffffffff8004c319>] worker_thread+0x0/0x122
 [<ffffffff8004c409>] worker_thread+0xf0/0x122
 [<ffffffff80092da9>] default_wake_function+0x0/0xe
 [<ffffffff800ac160>] trace_hardirqs_on+0x102/0x126
 [<ffffffff800347ca>] kthread+0xfe/0x132
 [<ffffffff80067f71>] trace_hardirqs_on_thunk+0x35/0x37
 [<ffffffff80061079>] child_rip+0xa/0x11
 [<ffffffff80068875>] _spin_unlock_irq+0x24/0x27
 [<ffffffff800606a8>] restore_args+0x0/0x30
 [<ffffffff800346cc>] kthread+0x0/0x132
 [<ffffffff8006106f>] child_rip+0x0/0x11

1 lock held by events/0/8:
 #0:  (&adapter->stats_lock){....}, at: [<ffffffff882016bb>] e1000_update_stats+0x3d/0x5f4 [e1000]
INFO: task irqbalance:2193 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
irqbalance    D ffff81001f5d3148     0  2193      1          2203  2125 (NOTLB)
 ffff81001bc11d58 0000000000000046 ffff81001f5d31b8 0000000000000296
 0000000000000002 0000000000000007 ffff810013eb6440 ffffffff8032bd40
 0000005e74725fb2 00000000000b44e1 ffff810013eb6628 000000001f5d31b8
Call Trace:
 [<ffffffff80246856>] dev_ioctl+0x309/0x474
 [<ffffffff80067233>] mutex_lock_nested+0x16f/0x27c
 [<ffffffff80246856>] dev_ioctl+0x309/0x474
 [<ffffffff8023ba65>] sock_ioctl+0x1da/0x1eb
 [<ffffffff80044499>] do_ioctl+0x21/0x6b
 [<ffffffff80031c22>] vfs_ioctl+0x45d/0x4bf
 [<ffffffff8004eac6>] sys_ioctl+0x59/0x78
 [<ffffffff800602a6>] tracesys+0xd5/0xdf

no locks held by irqbalance/2193.

Comment 7 Neil Horman 2011-05-23 19:07:57 UTC
Judging by the description, I would venture a guess that you're trying to lock the hashtable lock before its initalized.  The bond_alb_info.tx_hashtbl_lock gets initalized when bond_open is called, and I don't see anything in the description indicating that you issued an ifup or other event to it that would cause the bond_open path to get called.  As such the tx_hashtbl_lock is likely garbage, and that results in possible/likely taking of what appears to be a locked spinlock when we store slaves to it.  I'll work up a patch.  In the interim, I would suggest that you change your setup, so that you do the following:

echo +bond5 > /sys/class/net/bonding_masters
ifconfig bond5 up
echo +eth1 > /sys/class/net/bond5/bonding/slaves

If that makes the problem go away we'll know we're on the right track

Comment 8 Neil Horman 2011-05-23 19:11:32 UTC
In fact don't even bother with the above test, its clear that we're enslaving devices with the bond down from this error:
bonding: bond5: doing slave updates when interface is down.

And we just can't do that, since it will force us to access and use potentially uninitalized data.

I think the solution either needs to be returning an error along with that printk, so as to avoid the problem, or automatically bring up the bond.  I'm leaning toward the former, since user space nominally brings it up anyway, and we don't want to go doing things that userspace expects to do for itself.

Comment 9 Neil Horman 2011-05-23 19:38:08 UTC
Created attachment 500492 [details]
patch to prevent enslaving NICS when bond isn't up.

Here you go, this won't make what you're doing work, but it will result an error getting returned to user space if you don't ifconfig up the bond interface prior to enslaving.  This will ensure that no bond data structures are used prior to initalization.  If you can confirm this fixes the problem for you, I'll post this on rhkl and upstream.

Comment 10 Andy Gospodarek 2011-05-23 19:40:00 UTC
(In reply to comment #8)
> In fact don't even bother with the above test, its clear that we're enslaving
> devices with the bond down from this error:
> bonding: bond5: doing slave updates when interface is down.
> 
> And we just can't do that, since it will force us to access and use potentially
> uninitalized data.
> 
> I think the solution either needs to be returning an error along with that
> printk, so as to avoid the problem, or automatically bring up the bond.  I'm
> leaning toward the former, since user space nominally brings it up anyway, and
> we don't want to go doing things that userspace expects to do for itself.

Good catch, Neil.  I agree with you that we should just error out and not allow that path to be executed.

Comment 12 Jan Tluka 2011-05-24 12:18:51 UTC
I've checked the kernel with the patch applied. The patch in comment #9 fixed the problem.

# modprobe bonding mode=5
# echo +bond5 > /sys/class/net/bonding_masters
# echo +eth1 > /sys/class/net/bond5/bonding/slaves 
bonding: bond5: doing slave updates when interface is down.
-bash: echo: write error: Invalid argument

# ifconfig bond5 up
# echo +eth1 > /sys/class/net/bond5/bonding/slaves
# echo +eth2 > /sys/class/net/bond5/bonding/slaves

# ifconfig bond5 down
# echo -eth2 > /sys/class/net/bond5/bonding/slaves 
bonding: bond5: doing slave updates when interface is down.
-bash: echo: write error: Invalid argument
# echo +eth2 > /sys/class/net/bond5/bonding/slaves 
bonding: bond5: doing slave updates when interface is down.
-bash: echo: write error: Invalid argument
# ifconfig bond5 up
# echo -eth2 > /sys/class/net/bond5/bonding/slaves 
# echo -eth1 > /sys/class/net/bond5/bonding/slaves

Comment 13 RHEL Program Management 2011-06-02 14:20:03 UTC
This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux maintenance release.  Product Management has requested
further review of this request by Red Hat Engineering, for potential
inclusion in a Red Hat Enterprise Linux Update release for currently deployed
products.  This request is not yet committed for inclusion in an Update
release.

Comment 16 Jarod Wilson 2011-06-08 16:04:35 UTC
Patch(es) available in kernel-2.6.18-266.el5
You can download this test kernel (or newer) from http://people.redhat.com/jwilson/el5
Detailed testing feedback is always welcomed.

Comment 20 Jan Tluka 2011-06-28 12:20:51 UTC
Verified on -266.el5 kernel. With the patch applied soft lockups no more occur.

I've tested both virt setup and bare-metal. On bare metal no soft lockups are seen after removing enslaved interface from bond setup.

Comment 21 errata-xmlrpc 2011-07-21 10:21:49 UTC
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHSA-2011-1065.html


Note You need to log in before you can comment on or make changes to this bug.