BUG: soft lockup detected on CPU#0! (2.6.18.2 plus hacks)

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem,
however.

Any ideas about what this could be? It seems to be reproducible every day or
two, but no known way to make it happen quickly...

Kernel is SMP, PREEMPT.

Dec 19 04:49:33 localhost kernel: BUG: soft lockup detected on CPU#0!
Dec 19 04:49:33 localhost kernel:  [<78104252>] show_trace+0x12/0x20
Dec 19 04:49:33 localhost kernel:  [<78104929>] dump_stack+0x19/0x20
Dec 19 04:49:33 localhost kernel:  [<7814c88b>] softlockup_tick+0x9b/0xd0
Dec 19 04:49:33 localhost kernel:  [<7812a992>] run_local_timers+0x12/0x20
Dec 19 04:49:33 localhost kernel:  [<7812ac08>] 
update_process_times+0x38/0x80
Dec 19 04:49:33 localhost kernel:  [<78112796>] 
smp_apic_timer_interrupt+0x66/0x70
Dec 19 04:49:33 localhost kernel:  [<78103baa>] 
apic_timer_interrupt+0x2a/0x30
Dec 19 04:49:33 localhost kernel:  [<78354e8c>] _read_lock+0x3c/0x50
Dec 19 04:49:33 localhost kernel:  [<78331f42>] ip_check_mc+0x22/0xb0
Dec 19 04:49:33 localhost kernel:  [<783068bf>] ip_route_input+0x17f/0xef0
Dec 19 04:49:33 localhost kernel:  [<78309c59>] ip_rcv+0x349/0x580

Quoted 7 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem,
however.

Any ideas about what this could be? It seems to be reproducible every day or

If it doesn't help, I hope lockdep will be more
precise when you'll upgrade to 2.6.19 or higher.

Quoted 5 lines · Jarek Poplawski

Quoted 4 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem,
however.

Quoted 1 line

Quoted 1 line

Any ideas about what this could be? It seems to be reproducible every day or

...

Quoted 2 lines

If it doesn't help, I hope lockdep will be more
precise when you'll upgrade to 2.6.19 or higher.

... or when you enable lockdep in 2.6.18 (I've
forgotten it's there alredy!).

Jarek P.

Quoted 5 lines · Jarek Poplawski

Quoted 4 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem,
however.

Quoted 1 line

Quoted 1 line

Any ideas about what this could be? It seems to be reproducible every day or

...

Quoted 2 lines

If it doesn't help, I hope lockdep will be more
precise when you'll upgrade to 2.6.19 or higher.

... or when you enable lockdep in 2.6.18 (I've
forgotten it's there alredy!).

Jarek P.

Quoted 7 lines · Jarek Poplawski

Quoted 6 lines · Jarek Poplawski

Quoted 5 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem, however.

Quoted 8 lines

Quoted 2 lines

Quoted 2 lines

Any ideas about what this could be? It seems to be reproducible every day or

...

Quoted 2 lines

If it doesn't help, I hope lockdep will be more
precise when you'll upgrade to 2.6.19 or higher.

... or when you enable lockdep in 2.6.18 (I've
forgotten it's there alredy!).

I got lucky..the system was available by ssh still. I see this in the boot logs..I assume
this means lockdep is enabled? Should I have expected to see a lockdep trace in the case of
his soft-lockup then?

.....

Dec 19 04:33:48 localhost kernel: Lock dependency validator: Copyright (c) 

2006 Red Hat, Inc., Ingo MolnarDec 19 04:33:48 localhost kernel: ...
MAX_LOCKDEP_SUBCLASSES: 8

Quoted 10 lines · Ben Greear

Quoted 9 lines · Jarek Poplawski

Quoted 5 lines · Jarek Poplawski

Quoted 4 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use. From the backtrace, I am thinking this might be a generic problem, however.

Any ideas about what this could be? It seems to be reproducible every day or

...

Quoted 2 lines

If it doesn't help, I hope lockdep will be more
precise when you'll upgrade to 2.6.19 or higher.

Quoted 8 lines

Quoted 2 lines

... or when you enable lockdep in 2.6.18 (I've
forgotten it's there alredy!).

I got lucky..the system was available by ssh still. I see this in the boot logs..I assume this means lockdep is enabled? Should I have expected to see a lockdep trace in the case of his soft-lockup then?

.....

Dec 19 04:33:48 localhost kernel: Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo MolnarDec 19 04:33:48 localhost kernel: ... MAX_LOCKDEP_SUBCLASSES:    8

Yes, you got it enabled in the config.

If there is no message later about validator turning off and no warnings which could point at lockdep then it is working.

But then, IMHO, there is rather small probability this bug is really from lockup. Another possibility is hardware irqs (timer in particular) are turned off by something (maybe those hacks?) for extremely long time (~10 sec.).

Regards,
Jarek P.

The system hangs and does not recover (well, a few processes continue on the other processor for a few minutes before they too deadlock...)

I am guessing this problem has been around for a while, but it is only triggered when interfaces are created, and probably only when UDP traffic is already running heavily on the system. Most systems w/out virtual devices will not trigger this sort of race.

Quoted 33 lines · Jarek Poplawski

Quoted 21 lines · Ben Greear

Quoted 7 lines · Jarek Poplawski

Quoted 6 lines · Jarek Poplawski

Quoted 5 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem, however.

Quoted 7 lines

Quoted 2 lines

Quoted 2 lines

Any ideas about what this could be? It seems to be reproducible every day or

...

Quoted 2 lines

If it doesn't help, I hope lockdep will be more
precise when you'll upgrade to 2.6.19 or higher.

... or when you enable lockdep in 2.6.18 (I've
forgotten it's there alredy!).

I got lucky..the system was available by ssh still. I see this in the boot logs..I assume
this means lockdep is enabled? Should I have expected to see a lockdep trace in the case of
his soft-lockup then?

Quoted 4 lines

.....

Dec 19 04:33:48 localhost kernel: Lock dependency validator: Copyright 

(c) 2006 Red Hat, Inc., Ingo MolnarDec 19 04:33:48 localhost kernel: ...
MAX_LOCKDEP_SUBCLASSES: 8

Yes, you got it enabled in the config.

If there is no message later about validator turning off and no warnings which could point at lockdep then it is working.

Quoted 5 lines

But then, IMHO, there is rather small probability this bug is really from lockup. Another possibility is hardware irqs (timer in particular) are turned off by something (maybe those hacks?) for extremely long time (~10 sec.).

The system hangs and does not recover (well, a few processes continue on the other processor for a few minutes before they too deadlock...)

I am guessing this problem has been around for a while, but it is only triggered when interfaces are created, and probably only when UDP traffic is already running heavily on the system. Most systems w/out virtual devices will not trigger this sort of race.

[PATCH] igmp: spin_lock_bh in timer

igmp_timer_expire() uses spin_lock(&im->lock)
but this lock is also taken by other igmp timers,
so it should be changed to bh version.

[PATCH] igmp: spin_lock_bh in timer

igmp_timer_expire() uses spin_lock(&im->lock)
but this lock is also taken by other igmp timers,
so it should be changed to bh version.

Quoted 6 lines · Jarek Poplawski

[PATCH] igmp: spin_lock_bh in timer

igmp_timer_expire() uses spin_lock(&im->lock)
but this lock is also taken by other igmp timers,
so it should be changed to bh version.

When you're in a timer BH is already disabled. So this patch is redundant.

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use. From the backtrace, I am thinking this might be a generic problem, however.

Any ideas about what this could be? It seems to be reproducible every day or two, but no known way to make it happen quickly...

Kernel is SMP, PREEMPT.

Dec 19 04:49:33 localhost kernel: BUG: soft lockup detected on CPU#0!
Dec 19 04:49:33 localhost kernel:  [<78104252>] show_trace+0x12/0x20
Dec 19 04:49:33 localhost kernel:  [<78104929>] dump_stack+0x19/0x20
Dec 19 04:49:33 localhost kernel:  [<7814c88b>] softlockup_tick+0x9b/0xd0
Dec 19 04:49:33 localhost kernel:  [<7812a992>] run_local_timers+0x12/0x20
Dec 19 04:49:33 localhost kernel:  [<7812ac08>] update_process_times+0x38/0x80
Dec 19 04:49:33 localhost kernel:  [<78112796>] smp_apic_timer_interrupt+0x66/0x70
Dec 19 04:49:33 localhost kernel:  [<78103baa>] apic_timer_interrupt+0x2a/0x30
Dec 19 04:49:33 localhost kernel:  [<78354e8c>] _read_lock+0x3c/0x50
Dec 19 04:49:33 localhost kernel:  [<78331f42>] ip_check_mc+0x22/0xb0

Dec 19 04:49:33 localhost kernel:  [<783068bf>] ip_route_input+0x17f/0xef0

Dec 19 04:49:33 localhost kernel:  [<78309c59>] ip_rcv+0x349/0x580

Dec 19 04:49:33 localhost kernel:  [<782ec98d>] netif_receive_skb+0x36d/0x3b0
Dec 19 04:49:33 localhost kernel:  [<782ee50c>] process_backlog+0x9c/0x130
Dec 19 04:49:33 localhost kernel:  [<782ee795>] net_rx_action+0xc5/0x1f0
Dec 19 04:49:33 localhost kernel:  [<78125e58>] __do_softirq+0x88/0x110
Dec 19 04:49:33 localhost kernel:  [<78125f59>] do_softirq+0x79/0x80
Dec 19 04:49:33 localhost kernel:  [<781260ed>] irq_exit+0x5d/0x60
Dec 19 04:49:33 localhost kernel:  [<78105a6d>] do_IRQ+0x4d/0xa0
Dec 19 04:49:33 localhost kernel:  [<78103ae9>] common_interrupt+0x25/0x2c

Dec 19 04:49:33 localhost kernel:  [<78354c45>] _spin_lock+0x35/0x50
Dec 19 04:49:33 localhost kernel:  [<781aab1d>] proc_register+0x2d/0x110
Dec 19 04:49:33 localhost kernel:  [<781ab23d>] create_proc_entry+0x5d/0xd0
Dec 19 04:49:33 localhost kernel:  [<7812873b>] register_proc_table+0x6b/0x110
Dec 19 04:49:33 localhost kernel:  [<78128771>] register_proc_table+0xa1/0x110
Dec 19 04:49:33 localhost last message repeated 3 times
Dec 19 04:49:33 localhost kernel:  [<7812886d>] register_sysctl_table+0x8d/0xc0
Dec 19 04:49:33 localhost kernel:  [<7832f0c9>] devinet_sysctl_register+0x109/0x150

Dec 19 04:49:33 localhost kernel:  [<7832f2ea>] inetdev_init+0xea/0x160
Dec 19 04:49:33 localhost kernel:  [<7832fa2e>] inet_rtm_newaddr+0x16e/0x190
Dec 19 04:49:33 localhost kernel:  [<782f58a9>] rtnetlink_rcv_msg+0x169/0x230
Dec 19 04:49:33 localhost kernel:  [<78300ed0>] netlink_run_queue+0x90/0x140
Dec 19 04:49:33 localhost kernel:  [<782f56dc>] rtnetlink_rcv+0x2c/0x50
Dec 19 04:49:33 localhost kernel:  [<783014a5>] netlink_data_ready+0x15/0x60
Dec 19 04:49:33 localhost kernel:  [<78300167>] netlink_sendskb+0x27/0x50
Dec 19 04:49:33 localhost kernel:  [<78300bab>] netlink_unicast+0x15b/0x1f0
Dec 19 04:49:33 localhost kernel:  [<783013ab>] netlink_sendmsg+0x20b/0x2f0
Dec 19 04:49:33 localhost kernel:  [<782e12bc>] sock_sendmsg+0xfc/0x120
Dec 19 04:49:33 localhost kernel:  [<782e1a5a>] sys_sendmsg+0x10a/0x220
Dec 19 04:49:33 localhost kernel:  [<782e3311>] sys_socketcall+0x261/0x290
Dec 19 04:49:33 localhost kernel:  [<7810307d>] sysenter_past_esp+0x56/0x8d
Dec 19 04:52:17 localhost sshd[32311]: gethostby*.getanswer: asked for "203.60.60.10.in-addr.arpa IN PTR", got type "A"

I finally had time to look through the code in this backtrace in detail. I think it *could*
be a race between ip_rcv and inetdev_init, but I am not certain. Other than that, I'm real
low on ideas. I found a few more stack trace debugging options to enable..perhaps that
will give a better backtrace if we can reproduce it again.

I do have lock-debugging enabled, so it should have caught this if was an un-initialized access
problem, however.

More details below inline.

Quoted 12 lines · Ben Greear

This is from 2.6.18.2 kernel with my patch set. The MAC-VLANs are in active use.
From the backtrace, I am thinking this might be a generic problem, however.

Any ideas about what this could be? It seems to be reproducible every day or
two, but no known way to make it happen quickly...

Kernel is SMP, PREEMPT.

Quoted 14 lines

Dec 19 04:49:33 localhost kernel: BUG: soft lockup detected on CPU#0!
Dec 19 04:49:33 localhost kernel:  [<78104252>] show_trace+0x12/0x20
Dec 19 04:49:33 localhost kernel:  [<78104929>] dump_stack+0x19/0x20
Dec 19 04:49:33 localhost kernel:  [<7814c88b>] softlockup_tick+0x9b/0xd0
Dec 19 04:49:33 localhost kernel:  [<7812a992>] 
run_local_timers+0x12/0x20
Dec 19 04:49:33 localhost kernel:  [<7812ac08>] 
update_process_times+0x38/0x80
Dec 19 04:49:33 localhost kernel:  [<78112796>] 
smp_apic_timer_interrupt+0x66/0x70
Dec 19 04:49:33 localhost kernel:  [<78103baa>] 
apic_timer_interrupt+0x2a/0x30
Dec 19 04:49:33 localhost kernel:  [<78354e8c>] _read_lock+0x3c/0x50
Dec 19 04:49:33 localhost kernel:  [<78331f42>] ip_check_mc+0x22/0xb0

This is blocked on:
igmp.c: read_lock(&in_dev->mc_list_lock);

Quoted 2 lines

Dec 19 04:49:33 localhost kernel:  [<783068bf>] 

ip_route_input+0x17f/0xef0

route.c: int our = ip_check_mc(in_dev, daddr, saddr,
skb->nh.iph->protocol);

Quoted 1 line

Dec 19 04:49:33 localhost kernel:  [<78309c59>] ip_rcv+0x349/0x580

?? Called by a macro maybe? Can't find an obvious call to the

ip_route_input.

Quoted 23 lines

Dec 19 04:49:33 localhost kernel:  [<782ec98d>] 
netif_receive_skb+0x36d/0x3b0
Dec 19 04:49:33 localhost kernel:  [<782ee50c>] 
process_backlog+0x9c/0x130
Dec 19 04:49:33 localhost kernel:  [<782ee795>] net_rx_action+0xc5/0x1f0
Dec 19 04:49:33 localhost kernel:  [<78125e58>] __do_softirq+0x88/0x110
Dec 19 04:49:33 localhost kernel:  [<78125f59>] do_softirq+0x79/0x80
Dec 19 04:49:33 localhost kernel:  [<781260ed>] irq_exit+0x5d/0x60
Dec 19 04:49:33 localhost kernel:  [<78105a6d>] do_IRQ+0x4d/0xa0
Dec 19 04:49:33 localhost kernel:  [<78103ae9>] 
common_interrupt+0x25/0x2c
Dec 19 04:49:33 localhost kernel:  [<78354c45>] _spin_lock+0x35/0x50
Dec 19 04:49:33 localhost kernel:  [<781aab1d>] proc_register+0x2d/0x110
Dec 19 04:49:33 localhost kernel:  [<781ab23d>] 
create_proc_entry+0x5d/0xd0
Dec 19 04:49:33 localhost kernel:  [<7812873b>] 
register_proc_table+0x6b/0x110
Dec 19 04:49:33 localhost kernel:  [<78128771>] 
register_proc_table+0xa1/0x110
Dec 19 04:49:33 localhost last message repeated 3 times
Dec 19 04:49:33 localhost kernel:  [<7812886d>] 
register_sysctl_table+0x8d/0xc0
Dec 19 04:49:33 localhost kernel:  [<7832f0c9>] 

Quoted 1 line

devinet_sysctl_register+0x109/0x150

This devinet_sysctl_register is called right before the ip_mc_init_dev call is made, and
that call is used to initialize the multicast lock that is blocked on at the top of this backtrace.
This *could* be the race, but only if the entities in question are the same thing. I don't see
any way to determine whether they are or not based on the backtrace.

I looked through all of the uses of the mc_list_lock, and the places where it does a write_lock
are few and appear to be correct with no possibility of deadlocking. If a lock was un-initialized, then
that could perhaps explain why it is able to deadlock (though, that should have triggered a different
bug report since I have spin/rw-lock debugging enabled.)

Quoted 24 lines

Dec 19 04:49:33 localhost kernel:  [<7832f2ea>] inetdev_init+0xea/0x160
Dec 19 04:49:33 localhost kernel:  [<7832fa2e>] 
inet_rtm_newaddr+0x16e/0x190
Dec 19 04:49:33 localhost kernel:  [<782f58a9>] 
rtnetlink_rcv_msg+0x169/0x230
Dec 19 04:49:33 localhost kernel:  [<78300ed0>] 
netlink_run_queue+0x90/0x140
Dec 19 04:49:33 localhost kernel:  [<782f56dc>] rtnetlink_rcv+0x2c/0x50
Dec 19 04:49:33 localhost kernel:  [<783014a5>] 
netlink_data_ready+0x15/0x60
Dec 19 04:49:33 localhost kernel:  [<78300167>] netlink_sendskb+0x27/0x50
Dec 19 04:49:33 localhost kernel:  [<78300bab>] 
netlink_unicast+0x15b/0x1f0
Dec 19 04:49:33 localhost kernel:  [<783013ab>] 
netlink_sendmsg+0x20b/0x2f0
Dec 19 04:49:33 localhost kernel:  [<782e12bc>] sock_sendmsg+0xfc/0x120
Dec 19 04:49:33 localhost kernel:  [<782e1a5a>] sys_sendmsg+0x10a/0x220
Dec 19 04:49:33 localhost kernel:  [<782e3311>] 
sys_socketcall+0x261/0x290
Dec 19 04:49:33 localhost kernel:  [<7810307d>] 
sysenter_past_esp+0x56/0x8d
Dec 19 04:52:17 localhost sshd[32311]: gethostby*.getanswer: asked for 

"203.60.60.10.in-addr.arpa IN PTR", got type "A"

Signature · 2 lines

Ben Greear <[email protected]> 
Candela Technologies Inc  http://www.candelatech.com

It is hard to say what kind of bug to expect because at the same time other net_rx_action with the same vlan dev could take place on other processor and this inetdev_init could do more.

The main thing is the possibility of processing skb with not entirely open source dev which isn't expected (and checked) by receive functions. I think the easiest way to convince yourself is to add temporarily IFF_UP flag checking with dropping at the beginning of netif_receive_skb and __vlan_hwaccel_rx.

On Tue, Jan 02, 2007 at 08:39:09AM +0100, Jarek Poplawski wrote:
...

Quoted 7 lines

The main thing is the possibility of processing skb with not entirely open source dev which isn't expected (and checked) by receive functions. I think the easiest way to convince yourself is to add temporarily IFF_UP flag checking with dropping at the beginning of netif_receive_skb and __vlan_hwaccel_rx.

I've looked at this a little too -- it'd be nice to know who holds the write lock.

I see ip_mc_destroy_dev() is bouncing through the lock for each multicast address, though it starts at the beginning of the list each time. I don't see a problem with it, but it'd be simpler if it acquired the write lock once, grabbed and nulled the list, released the lock and then called igmp_group_dropped() & ip_ma_put() on each address from the local list copy.

Are you destroying/creating interfaces or doing a lot of multicasting at the time? How many group memberships do you have?

                                        +-DLS

I've looked at this a little too -- it'd be nice to know who holds the write lock.

Quoted 2 lines · David Stevens

I've looked at this a little too -- it'd be nice to know who holds the write lock.

If you mean mc_list_lock - probably nobody - it's not initialized (so the timers) for this in_device

Quoted 2 lines · Jarek Poplawski

On Tue, Jan 02, 2007 at 03:35:39PM -0800, David Stevens wrote:

Quoted 6 lines

Quoted 3 lines

I've looked at this a little too -- it'd be nice to know who holds the write lock.

If you mean mc_list_lock - probably nobody - it's not initialized (so the timers) for this in_device

I should say: "... probably not initialized ...".

Jarek P.
-
To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Ben,
Here's a patch that I think will fix it, assuming the receive is
on the
same device as the initialization. Can you try this out?

                                                +-DLS

[inline for viewing, attached for applying]

Signed-off-by David L Stevens <[email protected]>

diff -ruNp linux-2.6.19.1/net/ipv4/devinet.c linux-2.6.19.1T1/net/ipv4/devinet.c
--- linux-2.6.19.1/net/ipv4/devinet.c 2006-12-11 11:32:53.000000000
-0800
+++ linux-2.6.19.1T1/net/ipv4/devinet.c 2007-01-03 14:37:56.000000000 -0800

net/ipv4/devinet.c +3 -2

@@ -165,9 +165,8 @@ struct in_device *inetdev_init(struct ne
                              NET_IPV4_NEIGH, "ipv4", NULL, NULL);
 #endif
 
-       /* Account for reference dev->ip_ptr */
+       /* Account for reference dev->ip_ptr (below) */
        in_dev_hold(in_dev);
-       rcu_assign_pointer(dev->ip_ptr, in_dev);
 
 #ifdef CONFIG_SYSCTL
        devinet_sysctl_register(in_dev, &in_dev->cnf);

@@ -176,6 +175,8 @@ struct in_device *inetdev_init(struct ne
        if (dev->flags & IFF_UP)
                ip_mc_up(in_dev);
 out:
+       /* we can receive as soon as ip_ptr is set -- do this last */
+       rcu_assign_pointer(dev->ip_ptr, in_dev);
        return in_dev;
 out_kfree:
        kfree(in_dev);

diff -ruNp linux-2.6.19.1/net/ipv6/addrconf.c linux-2.6.19.1T1/net/ipv6/addrconf.c --- linux-2.6.19.1/net/ipv6/addrconf.c 2006-12-11 11:32:53.000000000 -0800
+++ linux-2.6.19.1T1/net/ipv6/addrconf.c 2007-01-03
14:47:07.000000000 -0800

net/ipv6/addrconf.c +2 -2

@@ -413,8 +413,6 @@ static struct inet6_dev * ipv6_add_dev(s
        if (netif_carrier_ok(dev))
                ndev->if_flags |= IF_READY;
 
-       /* protected by rtnl_lock */
-       rcu_assign_pointer(dev->ip6_ptr, ndev);
 
        ipv6_mc_init_dev(ndev);
        ndev->tstamp = jiffies;

@@ -425,6 +423,8 @@ static struct inet6_dev * ipv6_add_dev(s
                              NULL);
        addrconf_sysctl_register(ndev, &ndev->cnf);
 #endif
+       /* protected by rtnl_lock */
+       rcu_assign_pointer(dev->ip6_ptr, ndev);
        return ndev;
 }
 

Ben,
Here's a patch that I think will fix it, assuming the receive is
on the
same device as the initialization. Can you try this out?

Quoted 4 lines · David Stevens

Ben,
Here's a patch that I think will fix it, assuming the receive is
on the
same device as the initialization. Can you try this out?

Hi David:

Your patch makes sense on its own but I don't see the direct connection to the soft lock-up. Sure it prevents the code path in question from triggering. However, if we don't understand why it's locking up in the first place then this may just be hiding it rather than fixing it.

In particular, a soft lockup means that we're doing so much work in the softirq handlers that processes are not getting run. So what is it exactly here that's causing us to get stuck in the softirq handlers? Is it because we're somehow getting stuck in a net rx loop?

Cheers,

I'm not sure if it helps..but I did notice that 'ip' was using 99% of the CPU on the system. Could this be because it was spinning trying to acquire the read-lock? When I ran 'ifconfig -a', that process hung, and at that point the system was rebooted. Before I ran ifconfig, 'top' and 'ls' and similar apps were responding fine, and I was logged in over ssh from the US to Australia, so it's basic networking was functioning.

You're right, I don't know whether it'll fix the problem Ben saw
or not, but it looks like the original code can do a receive before the in_device is fully initialized, and that, of course, is bad.
If the device for ip_rcv() is not the same one we were
initializing when the receive interrupted, then the patch should have no effect either way -- I don't think it'll hide other problems.
If it's hard to reproduce (which I guess is true), then you're
right, no soft lockup doesn't really tell us if it's fixed or not.

Quoted 8 lines · David Stevens

You're right, I don't know whether it'll fix the problem Ben saw
or not, but it looks like the original code can do a receive before the in_device is fully initialized, and that, of course, is bad.
If the device for ip_rcv() is not the same one we were
initializing when the receive interrupted, then the patch should have no effect either way -- I don't think it'll hide other problems.
If it's hard to reproduce (which I guess is true), then you're
right, no soft lockup doesn't really tell us if it's fixed or not.

Actually I missed your point that the multicast locks aren't even initialised at that point. So this does explain the soft lock-up and therefore your patch is clearly the correct solution.

I doubt this is the right solution. It certainly could fix this particular situation but my main point was packets shouldn't get into kernel receive queues with skb->dev not IFF_UP.

Quoted 5 lines · Jarek Poplawski

I doubt this is the right solution. It certainly could fix this particular situation but my main point was packets shouldn't get into kernel receive queues with skb->dev not IFF_UP.

I think you misunderstood. The device certainly is IFF_UP. What happens is that the multicast spin locks are set up too late:

Could you explain? I can see some inet_rtm_newaddr interrupted. For me it could be e.g.:

after
vconfig add eth0 9

ip addr add dev eth0.9 ...

Quoted 4 lines · Jarek Poplawski

Could you explain? I can see some inet_rtm_newaddr interrupted. For me it could be e.g.:

Quoted 4 lines

after
vconfig add eth0 9

ip addr add dev eth0.9 ...

Whether eth0.9 is up or not does not affect this at all. The spin locks are initialised (and used) when the first IPv4 address is added, not when the device comes up.

Quoted 5 lines · Herbert Xu

Quoted 3 lines · Jarek Poplawski

Could you explain? I can see some inet_rtm_newaddr interrupted. For me it could be e.g.:

Quoted 9 lines

Quoted 5 lines

after
vconfig add eth0 9

ip addr add dev eth0.9 ...

Whether eth0.9 is up or not does not affect this at all. The spin locks are initialised (and used) when the first IPv4 address is added, not when the device comes up.

I understand this. I consider IFF_UP as a sign all initialisations (open functions including) are completed and there is permission for working (so
logically, if I would do eth0.9 down all traffic
should be stopped, what probably isn't true now).

Jarek P.
-
To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 17 lines · Jarek Poplawski

Quoted 5 lines · Herbert Xu

Quoted 3 lines · Jarek Poplawski

Could you explain? I can see some inet_rtm_newaddr interrupted. For me it could be e.g.:

Quoted 9 lines

Quoted 5 lines

after
vconfig add eth0 9

ip addr add dev eth0.9 ...

Whether eth0.9 is up or not does not affect this at all. The spin locks are initialised (and used) when the first IPv4 address is added, not when the device comes up.

Quoted 6 lines

I understand this. I consider IFF_UP as a sign all initialisations (open functions including) are completed and there is permission for working (so logically, if I would do eth0.9 down all traffic should be stopped, what probably isn't true now).

It is certainly valid for an interface to be IF_UP, but have no IP address. My application
does bring the network device up before it assigns the IP, for instance.

There may be other issues with IF_UP, but that could be handled with a different
investigation. If you have a particular test case that fails with 802.1Q VLANs, then
I will be happy to work on it...

Quoted 8 lines · David Stevens

You're right, I don't know whether it'll fix the problem Ben saw
or not, but it looks like the original code can do a receive before the in_device is fully initialized, and that, of course, is bad.
If the device for ip_rcv() is not the same one we were
initializing when the receive interrupted, then the patch should have no effect either way -- I don't think it'll hide other problems.
If it's hard to reproduce (which I guess is true), then you're
right, no soft lockup doesn't really tell us if it's fixed or not.

Actually I missed your point that the multicast locks aren't even initialised at that point. So this does explain the soft lock-up and therefore your patch is clearly the correct solution.

From: Herbert Xu <[email protected]>
Date: Thu, 04 Jan 2007 17:26:27 +1100

Quoted 10 lines

Quoted 8 lines · David Stevens

You're right, I don't know whether it'll fix the problem Ben saw
or not, but it looks like the original code can do a receive before the in_device is fully initialized, and that, of course, is bad.
If the device for ip_rcv() is not the same one we were
initializing when the receive interrupted, then the patch should have no effect either way -- I don't think it'll hide other problems.
If it's hard to reproduce (which I guess is true), then you're
right, no soft lockup doesn't really tell us if it's fixed or not.

Quoted 3 lines

Actually I missed your point that the multicast locks aren't even initialised at that point. So this does explain the soft lock-up and therefore your patch is clearly the correct solution.

I agree too, therefore I've added David's patch as below.

I'll push this to the -stable branches as well. This fix is correct even if it does not entirely clear up the soft lockup bug being discussed in this thread, but I think it will :-)

I'd only suggest to change "goto out;" to
"return NULL;" at the end of inetdev_init because
now RCU is engaged unnecessarily.

Quoted 4 lines · Jarek Poplawski

I'd only suggest to change "goto out;" to
"return NULL;" at the end of inetdev_init because
now RCU is engaged unnecessarily.

I agree. The RCU assignment should come before the out label. Can you send a patch?

Why me? (I didn't spoil this!)

Subject: [PATCH] devinet: inetdev_init out label moved after RCU assignment

inetdev_init out label moved after RCU assignment
(final suggestion by Herbert Xu)

Signed-off-by Jarek Poplawski <[email protected]>

Quoted 2 lines · Jarek Poplawski

Why me? (I didn't spoil this!)

You spotted the problem, so it's only fair that you get the credit :)

Quoted 2 lines

Why me? (I didn't spoil this!)

You spotted the problem, so it's only fair that you get the credit :)

Quoted 6 lines

Subject: [PATCH] devinet: inetdev_init out label moved after RCU assignment

inetdev_init out label moved after RCU assignment
(final suggestion by Herbert Xu)

Signed-off-by Jarek Poplawski <[email protected]>

Thanks, looks good to me.

Signed-off-by Jarek Poplawski <[email protected]>

---

diff -Nurp linux-2.6.20-rc3-/net/ipv4/devinet.c

--- linux-2.6.20-rc3-/net/ipv4/devinet.c 2007-01-05 11:53:16.000000000

+++ linux-2.6.20-rc3/net/ipv4/devinet.c 2007-01-05 11:55:32.000000000

net/ipv4/devinet.c +2 -2

@@ -174,9 +174,10 @@ struct in_device *inetdev_init(struct ne
    ip_mc_init_dev(in_dev);
    if (dev->flags & IFF_UP)
       ip_mc_up(in_dev);
-out:
+
    /* we can receive as soon as ip_ptr is set -- do this last */
    rcu_assign_pointer(dev->ip_ptr, in_dev);
+out:
    return in_dev;
 out_kfree:
    kfree(in_dev);
-

To unsubscribe from this list: send the line "unsubscribe netdev" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

From: Herbert Xu <[email protected]>
Date: Thu, 04 Jan 2007 17:26:27 +1100

Quoted 9 lines

Quoted 8 lines · David Stevens

You're right, I don't know whether it'll fix the problem Ben saw
or not, but it looks like the original code can do a receive before the in_device is fully initialized, and that, of course, is bad.
If the device for ip_rcv() is not the same one we were
initializing when the receive interrupted, then the patch should have no effect either way -- I don't think it'll hide other problems.
If it's hard to reproduce (which I guess is true), then you're
right, no soft lockup doesn't really tell us if it's fixed or not.

Quoted 3 lines

Actually I missed your point that the multicast locks aren't even initialised at that point. So this does explain the soft lock-up and therefore your patch is clearly the correct solution.

I agree too, therefore I've added David's patch as below.

I'll push this to the -stable branches as well. This fix is correct even if it does not entirely clear up the soft lockup bug being discussed in this thread, but I think it will :-)

We were able to reproduce the problem twice on the un-patched 2.6.18.2 kernel in about 2 hours of our stress test yesterday. I applied this patch (well, the ipv4 part..the ipv6 won't apply to 2.6.18.2), and it has run the stress test clean for a total of about 8 hours.

So, I do believe this was the problem we were hitting, and it seems fixed.

So, I do believe this was the problem we were hitting, and it seems fixed.

On Fri, Jan 05, 2007 at 12:33:43PM -0800, Ben Greear wrote:
...

Quoted 2 lines

So, I do believe this was the problem we were hitting, and it seems fixed.

Congratulations!

But I can see one strange thing in vlan.c:

/* Must be invoked with RCU read lock (no preempt) */ static struct vlan_group *__vlan_find_group(int real_dev_ifindex)
...
* Must be invoked with RCU read lock (no preempt)
*/
struct net_device *__find_vlan_dev(struct net_device *real_dev,
...

But later in this file no sign of disabling preemption for these calls and for hlist_add_head_rcu and hlist_del_rcu.

I can't imagine how this works?

Jarek P.

Quoted 18 lines · Jarek Poplawski

On Fri, Jan 05, 2007 at 12:33:43PM -0800, Ben Greear wrote:
...

Quoted 2 lines

So, I do believe this was the problem we were hitting, and it seems fixed.

Congratulations!

But I can see one strange thing in vlan.c:

/* Must be invoked with RCU read lock (no preempt) */ static struct vlan_group *__vlan_find_group(int real_dev_ifindex)
...
* Must be invoked with RCU read lock (no preempt)
*/
struct net_device *__find_vlan_dev(struct net_device *real_dev,
...

Quoted 4 lines

But later in this file no sign of disabling preemption for these calls and for hlist_add_head_rcu and hlist_del_rcu.

I can't imagine how this works?

Quoted 1 line

Perhaps...I didn't RCU-ify VLANs, but I can take a look.

For the record, the soft lockup was using MAC-VLANs, not 802.1Q VLANs, so it wouldn't
have been affected by bugs in VLANs one way or the other.

Ben

Quoted 2 lines

Jarek P.

Quoted 19 lines · On Mon, 08 Jan 2007 08:57:10 -0800 Ben Greear <[email protected]> wrote:

Quoted 18 lines · Jarek Poplawski

On Fri, Jan 05, 2007 at 12:33:43PM -0800, Ben Greear wrote:
...

Quoted 2 lines

So, I do believe this was the problem we were hitting, and it seems fixed.

Congratulations!

But I can see one strange thing in vlan.c:

/* Must be invoked with RCU read lock (no preempt) */ static struct vlan_group *__vlan_find_group(int real_dev_ifindex)
...
* Must be invoked with RCU read lock (no preempt)
*/
struct net_device *__find_vlan_dev(struct net_device *real_dev,
...

Quoted 4 lines

Quoted 4 lines

But later in this file no sign of disabling preemption for these calls and for hlist_add_head_rcu and hlist_del_rcu.

I can't imagine how this works?

Preempt is already disabled on the receive path.

On Mon, Jan 08, 2007 at 10:03:50AM -0800, Stephen Hemminger wrote:

Quoted 5 lines

Quoted 5 lines

Quoted 5 lines

* Must be invoked with RCU read lock (no preempt)
*/
struct net_device *__find_vlan_dev(struct net_device *real_dev,
...

Quoted 6 lines

Quoted 4 lines

Quoted 4 lines

But later in this file no sign of disabling preemption for these calls and for hlist_add_head_rcu and hlist_del_rcu.

I can't imagine how this works?

Preempt is already disabled on the receive path.

I'm not sure you're talking about the same thing -

It looks like you're talking about the right thing and I'm a fool again! Now I try to find why I even had to pay for this. I read again and again adequate chapters from R. Love and C. Benvenuti's books, see

a lot about kernel preemption in 2.6, but can't see anything about preemption disabled in ioctls - maybe I'm blind or they are badly translated. Now I look into "Linux Device Drivers", see ch. 6 about ioctls, blocking I/O and RCU, but nothing about preemption disabled again. Maybe this is omited because it's obvious to people who started hacking with earlier kernels?

On Wed, Jan 10, 2007 at 10:04:11AM +0100, Jarek Poplawski wrote:
...

Quoted 4 lines

It looks like you're talking about the right thing and I'm a fool again! Now I try to find why I even had to pay for this. I read again and again adequate chapters from R. Love and C. Benvenuti's books, see

Quoted 8 lines

a lot about kernel preemption in 2.6, but can't see anything about preemption disabled in ioctls - maybe I'm blind or they are badly translated. Now I look into "Linux Device Drivers", see ch. 6 about ioctls, blocking I/O and RCU, but nothing about preemption disabled again. Maybe this is omited because it's obvious to people who started hacking with earlier kernels?

... or maybe it's even more complicated...

For the time being, I revoke my critique of these books.

Jarek P.

Don't rely on books too heavily, they can get out of date with a simple code change.

The path that I am talking about is the receive skb path. All data received goes through netif_receive_skb and that does rcu_read_lock(). This is done so that receive protocol list can be used with RCU (lock free). Since receiving is a time critical path, we want to process without having to do any locked operations; locked operations cause a processor force a cache miss and are one of the main CPU overheads. RCU requires no locked operation, but does prevent preemption.

Yesterday I did what I should do earlier - checked this simple way, with printk, and now I have no doubts it's a bug: if you add or remove vlan devices with vconfig, register_vlan_device and unregister_vlan_dev are called by ioctl and they use and change rcu procetded data without preemption disabled so vlan rcu hash lists could become corrupted or find results could be wrong.

From: Jarek Poplawski <[email protected]>
Date: Thu, 11 Jan 2007 08:24:28 +0100

Quoted 8 lines

Yesterday I did what I should do earlier - checked this simple way, with printk, and now I have no doubts it's a bug: if you add or remove vlan devices with vconfig, register_vlan_device and unregister_vlan_dev are called by ioctl and they use and change rcu procetded data without preemption disabled so vlan rcu hash lists could become corrupted or find results could be wrong.

Those two operations do their modifications and changes under the RTNL semaphore, via rtnl_lock() and rtnl_unlock() which guarentees that no other modifications can occur.

Quoted 12 lines · David Miller

From: Jarek Poplawski <[email protected]>
Date: Thu, 11 Jan 2007 08:24:28 +0100

Quoted 8 lines

Yesterday I did what I should do earlier - checked this simple way, with printk, and now I have no doubts it's a bug: if you add or remove vlan devices with vconfig, register_vlan_device and unregister_vlan_dev are called by ioctl and they use and change rcu procetded data without preemption disabled so vlan rcu hash lists could become corrupted or find results could be wrong.

Quoted 3 lines

Those two operations do their modifications and changes under the RTNL semaphore, via rtnl_lock() and rtnl_unlock() which guarentees that no other modifications can occur.

Sure, but is this even legal to be preempted during

reading or modifying rcu list? Doesn't this disturb rcu cycle and make possible memory release problems?

Quoted 17 lines · Jarek Poplawski

Quoted 15 lines · David Miller

From: Jarek Poplawski <[email protected]>
Date: Thu, 11 Jan 2007 08:24:28 +0100

Quoted 8 lines

Yesterday I did what I should do earlier - checked this simple way, with printk, and now I have no doubts it's a bug: if you add or remove vlan devices with vconfig, register_vlan_device and unregister_vlan_dev are called by ioctl and they use and change rcu procetded data without preemption disabled so vlan rcu hash lists could become corrupted or find results could be wrong.

Those two operations do their modifications and changes under the RTNL semaphore, via rtnl_lock() and rtnl_unlock() which guarentees that no other modifications can occur.

Quoted 1 line

Sure, but is this even legal to be preempted during

I should even say:

"... is this even legal to be blocked during ..."

Quoted 2 lines

reading or modifying rcu list? Doesn't this disturb rcu cycle and make possible memory release problems?

Sure, but is this even legal to be preempted during reading or modifying rcu list or be blocked while holding rcu protected pointer? Doesn't this disturb rcu cycle and make possible memory release problems?

From: Jarek Poplawski <[email protected]>
Date: Thu, 11 Jan 2007 09:39:34 +0100

Quoted 4 lines

Sure, but is this even legal to be preempted during reading or modifying rcu list or be blocked while holding rcu protected pointer? Doesn't this disturb rcu cycle and make possible memory release problems?

It's fine in this case.

Since the list cannot be changed by anyone else, and the hash linked list (as seen by readers) is modified atomically by a single store, it all works out.

Readers only look at foo->next in the hash traversal. Since the preceeding element cannot change outside of the current writer, the ->next pointer to update is protected.

Readers therefore will either see the hash list with the entry or without.

We then use call_rcu() to make sure any reading threads that happened to get a glimpse of the hash entry before the hlist_del_rcu() completed will go away and drop their references before we free that entry.

I really don't see any problem here. :-)

Paul McKenney has given lots of talks on RCU see:
http://www.rdrop.com/users/paulmck/RCU/

and look in Documentation/RCU

From Documentation/RCU/checklist.txt:

9. All RCU list-traversal primitives, which include
list_for_each_rcu(), list_for_each_entry_rcu(), list_for_each_continue_rcu(), and list_for_each_safe_rcu(), must be within an RCU read-side critical section. RCU read-side critical sections are delimited by rcu_read_lock() and rcu_read_unlock(), or by similar primitives such as rcu_read_lock_bh() and rcu_read_unlock_bh().

Use of the _rcu() list-traversal primitives outside of an RCU read-side critical section causes no harm other than a slight performance degradation on Alpha CPUs. It can also be quite helpful in reducing code bloat when common code is shared between readers and updaters.