求宕机原因分析

烟雾弹下的真实

问题描述：
我在local_out钩子处抓synack包并构造ack包调用dst_input上传，出现下面的问题。
BUG: soft lockup - CPU#0 stuck for 10s! [swapper:0]
CPU 0:
Modules linked in: http_info(U) ipv6(U) xfrm_nalgo(U) crypto_api(U) autofs4(U) hidp(U) rfcomm(U) l2cap(U) bluetooth(U) sunrpc(U) ip_conntrack_netbios_ns(U) xt_state(U) ip_conntrack(U) nfnetlink(U) iptable_filter(U) ip_tables(U) x_tables(U) dm_mirror(U) dm_multipath(U) scsi_dh(U) video(U) backlight(U) sbs(U) power_meter(U) hwmon(U) i2c_ec(U) dell_wmi(U) wmi(U) button(U) battery(U) asus_acpi(U) acpi_memhotplug(U) ac(U) parport_pc(U) lp(U) parport(U) floppy(U) virtio_balloon(U) i2c_piix4(U) pcspkr(U) i2c_core(U) 8139too(U) 8139cp(U) virtio_pci(U) serio_raw(U) mii(U) virtio_ring(U) virtio(U) ide_cd(U) cdrom(U) dm_raid45(U) dm_message(U) dm_region_hash(U) dm_log(U) dm_mod(U) dm_mem_cache(U) ata_piix(U) libata(U) sd_mod(U) scsi_mod(U) ext3(U) jbd(U) uhci_hcd(U) ohci_hcd(U) ehci_hcd(U)
Pid: 0, comm: swapper Tainted: G      2.6.18-194.test #7
RIP: 0010:[<ffffffff80065bfc>]  [<ffffffff80065bfc>] .text.lock.spinlock+0x2/0x30
RSP: 0018:ffffffff80447918  EFLAGS: 00000286
RAX: 0000000000000000 RBX: ffff81007f09e770 RCX: 0000000000000050
RDX: 0000000000000000 RSI: ffff81007bd740c0 RDI: ffff810071254800
RBP: ffffffff80447890 R08: ffffffff8024bd49 R09: ffffffff8024bd49
R10: 0000000080000000 R11: 0000000000000000 R12: ffffffff8005ec8e
R13: ffff8100712547c0 R14: ffffffff80079236 R15: ffffffff80447890
FS:  0000000000000000(0000) GS:ffffffff803cb000(0000) knlGS:0000000000000000
CS:  0010 DS: 0018 ES: 0018 CR0: 000000008005003b
CR2: 00002b2798b70340 CR3: 000000006f654000 CR4: 00000000000006e0

Call Trace:
<IRQ>  [<ffffffff800271b0>] tcp_v4_rcv+0x664/0xbc8
[<ffffffff8024bd49>] ip_local_deliver_finish+0x0/0x1e9
[<ffffffff80057845>] nf_hook_slow+0x58/0xbc
[<ffffffff8024bd49>] ip_local_deliver_finish+0x0/0x1e9
[<ffffffff80035167>] ip_local_deliver+0x19d/0x263
[<ffffffff884a952e>] :http_info:ws_local_out+0x3b0/0x446
[<ffffffff80034ab9>] nf_iterate+0x41/0x7d
[<ffffffff8024e135>] dst_output+0x0/0xe
[<ffffffff80057845>] nf_hook_slow+0x58/0xbc
[<ffffffff8024e135>] dst_output+0x0/0xe
[<ffffffff8024fe0b>] ip_build_and_send_pkt+0x20a/0x23c
[<ffffffff8025aac0>] tcp_v4_send_synack+0xab/0x105
[<ffffffff8025c742>] tcp_v4_conn_request+0x3ff/0x455
[<ffffffff8845e85a>] :ipv6:tcp_v6_conn_request+0x36/0x391
[<ffffffff80017b6d>] cache_grow+0x35a/0x3c1
[<ffffffff8003e5f3>] lock_timer_base+0x1b/0x3c
[<ffffffff8004358c>] tcp_rcv_state_process+0x56/0xe7f
[<ffffffff8003c30c>] tcp_v4_do_rcv+0x478/0x4cf
[<ffffffff8834f135>] :ip_conntrack:ip_confirm+0x33/0x39
[<ffffffff800276ab>] tcp_v4_rcv+0xb5f/0xbc8
[<ffffffff8024bd49>] ip_local_deliver_finish+0x0/0x1e9
[<ffffffff80057845>] nf_hook_slow+0x58/0xbc
[<ffffffff8024bd49>] ip_local_deliver_finish+0x0/0x1e9
[<ffffffff80035167>] ip_local_deliver+0x19d/0x263
[<ffffffff800362d5>] ip_rcv+0x539/0x57c
[<ffffffff800209c1>] netif_receive_skb+0x470/0x49f
[<ffffffff881bc187>] :8139cp:cp_rx_poll+0x43c/0x58c
[<ffffffff8000c88a>] net_rx_action+0xac/0x1e0
[<ffffffff80012406>] __do_softirq+0x89/0x133
[<ffffffff8005f2fc>] call_softirq+0x1c/0x28
[<ffffffff8006dbb3>] do_softirq+0x2c/0x85
[<ffffffff8006da3b>] do_IRQ+0xec/0xf5
[<ffffffff8006c360>] default_idle+0x0/0x50
[<ffffffff8005e615>] ret_from_intr+0x0/0xa
<EOI>  [<ffffffff8006c389>] default_idle+0x29/0x50
[<ffffffff8004a0c3>] cpu_idle+0x95/0xb8
[<ffffffff8040780b>] start_kernel+0x220/0x225
[<ffffffff8040722f>] _sinittext+0x22f/0x236

Godbach

BUG: soft lockup - CPU#0 stuck for 10s! [swapper:0]

很常见的一个错误。过长时间占用锁。
这段代码是你自己写的吗？

烟雾弹下的真实

bh_lock_sock_nested(sk);
        ret = 0;
        if (!sock_owned_by_user(sk)) {
#ifdef CONFIG_NET_DMA
                struct tcp_sock *tp = tcp_sk(sk);
                if (!tp->ucopy.dma_chan && tp->ucopy.pinned_list)
                        tp->ucopy.dma_chan = get_softnet_dma();
                if (tp->ucopy.dma_chan)
                        ret = tcp_v4_do_rcv(sk, skb);
                else
#endif
                {
                        if (!tcp_prequeue(sk, skb))
                        ret = tcp_v4_do_rcv(sk, skb);
                }
        } else
                sk_add_backlog(sk, skb);
        bh_unlock_sock(sk);

上面是tcp_v4_rcv函数里面的代码，我把bh_lock_sock_nested(sk)和bh_unlock_sock(sk)注销掉后，就不会出现问题，现在不清楚在local_out钩子处，这个sock的锁怎么给锁了

Godbach

那你又在 localout 做了什么工作呢

luoyan_xy

回复 4# Godbach


    你说的过长时间占用锁，是说在netfilter挂载的钩子函数的处理流程过长的意思吗？   
   是不是在netfilter流程处理没结束的情况下，协议栈不能正确接收新的数据包？

Godbach

回复 5# luoyan_xy

    你说的过长时间占用锁，是说在netfilter挂载的钩子函数的处理流程过长的意思吗？   

需要结合你的代码进行判断

   是不是在netfilter流程处理没结束的情况下，协议栈不能正确接收新的数据包？

对于同一个 CPU，可以理解为对数据包的处理是串行的。
因此，如果在处理某个数据包期间，你使用了锁，比如 spinlock 之类的，但是处理的时间过长，内核就会抱怨的。

Godbach

我在local_out钩子处抓synack包并构造ack包调用dst_input上传，出现下面的问题。

不涉及保密的话，把你截获并构造包的代码贴出来看一下

烟雾弹下的真实

回复 4# Godbach

加上下面的代码就不会死锁了
            if(skb->sk)
           {
                bh_unlock_sock(skb->sk);
                dst_input(skb);
                bh_lock_sock_nested(skb->sk);
           }
不过会不会出问题，还不得知

hritian

回复  Godbach

加上下面的代码就不会死锁了
            if(skb->sk)
           {
                ...
烟雾弹下的真实 发表于 2011-04-20 13:49

    按道理是不会，不过你要小心被调度，小心被进程切换；

hritian

按道理是不会，不过你要小心被调度，小心被进程切换；
hritian 发表于 2011-04-20 14:02

    靠，lz我应该认识吧。