记一次内核soft lockup的定位记录

   产品大用户场景下运行一段时间即报“Aug  7 19:19:58 localhost kernel: NMI watchdog: BUG: soft lockup - CPU#7 stuck for 23s! [xxxx:80779]" 错误，内核日志调用栈显示是在获取锁时失败，该锁是读写锁，使用read_lock或者write_lock获取锁，锁使用情况如下所示，如图所示锁用在桶深256的HASH表下挂链表插入删除时的竞争保护。刚开始按照用户态经验加锁时锁不可用不是被挂起睡眠吗？等待锁可用再被唤醒，怎么会一直占有CPU20多秒，通过分析内核读写锁函数发现内核读写锁类似spin_lock死等，所以应该是该锁被其他人长时间占用，到了调用栈所示的调用时一直无法获取锁导致的，死等20多秒超时导致该CPU的watchdog发现（watchdog是IRQ所以不会因为死等锁而不能调度），同时可以确定用户态死锁不会导致soft lockup。

    结合产品内核代码进而分析可能原因： 1) 多个内核锁的PV操作顺序不当导致死锁； 2) HASH链上的节点太多，导致获取锁的任务处理时间超过20s；3)某任务获取锁之后睡眠（同spin_lock后不能睡眠）4) 其他原因死锁

    分析代码排除1，增加调试手段查看所有HASH链的长度排除2,分析代码发现操作HASH表时，获取锁后有kmalloc操作，但是参数2是GFP_ATOMIC不会睡眠（参数GFP_KERNEL可能导致睡眠），陷入困境。想到寻求内核自带debug特性辅助，发现lockdep。lockdep需要修改内核默认配置重编译内核，如何配置使能lockdep见点击打开链接。配置重编内核后运行直到出现soft lockup，dmesg当看到Interrupt的时候猛然明白了，获取锁任务被中断打断而中断中又需要获取锁，导致死锁。所以读写锁接口read_lock write_lock应该修改为关闭中断的read_lockirqsave  write_lockirqsave。

dmesg 输出：

[ 4773.122536] =================================
[ 4773.122539] [ INFO: inconsistent lock state ]
[ 4773.122542] 3.10.101 #9 Tainted: GF          O
[ 4773.122544] ---------------------------------
[ 4773.122547] inconsistent {IN-SOFTIRQ-R} -> {SOFTIRQ-ON-W} usage.
[ 4773.122551] xxx/17184 [HC0[0]:SC0[0]:HE1:SE1] takes:


[ 4773.122554]  (
[ 4773.122566] {IN-SOFTIRQ-R} state was registered at:
[ 4773.122568]   [<ffffffff810bf9bb>] __lock_acquire+0x5ab/0xc30
[ 4773.122576]   [<ffffffff810c00f0>] lock_acquire+0xb0/0x160
[ 4773.122580]   [<ffffffff815cf7d9>] _raw_read_lock+0x39/0x70
[ 4773.122586]   [<ffffffffa08a891a>] xxxx
[ 4773.122590]   [<ffffffffa08ab2c0>] xxxx
[ 4773.122595]   [<ffffffff81519f09>] udp_queue_rcv_skb+0x1b9/0x570
[ 4773.122600]   [<ffffffff8151a911>] __udp4_lib_rcv+0x181/0xa20
[ 4773.122604]   [<ffffffff8151b1ca>] udp_rcv+0x1a/0x20
[ 4773.122609]   [<ffffffff814e8512>] ip_local_deliver_finish+0xe2/0x300
[ 4773.122615]   [<ffffffff814e8ef7>] ip_local_deliver+0x47/0x80
[ 4773.122619]   [<ffffffff814e8890>] ip_rcv_finish+0x160/0x630
[ 4773.122624]   [<ffffffff814e9159>] ip_rcv+0x229/0x370
[ 4773.122628]   [<ffffffff814af0a6>] __netif_receive_skb_core+0x6c6/0x8a0
[ 4773.122634]   [<ffffffff814af298>] __netif_receive_skb+0x18/0x60
[ 4773.122639]   [<ffffffff814af363>] netif_receive_skb+0x83/0xf0
[ 4773.122644]   [<ffffffff814afe80>] napi_gro_receive+0x80/0xb0
[ 4773.122649]   [<ffffffffa004e0b4>] rtl8169_poll+0x174/0x68f [r8169]
[ 4773.122668]   [<ffffffff814af76a>] net_rx_action+0x15a/0x2a0
[ 4773.122673]   [<ffffffff81063e57>] __do_softirq+0x107/0x2a0
[ 4773.122678]   [<ffffffff815d9e3c>] call_softirq+0x1c/0x30
[ 4773.122683]   [<ffffffff810156ed>] do_softirq+0x8d/0xc0
[ 4773.122688]   [<ffffffff810641cd>] irq_exit+0xdd/0xf0
[ 4773.122692]   [<ffffffff815da766>] do_IRQ+0x56/0xc0
[ 4773.122697]   [<ffffffff815d01f2>] ret_from_intr+0x0/0x1a
[ 4773.122701]   [<ffffffff8109378b>] try_to_wake_up+0x1cb/0x2e0
[ 4773.122707]   [<ffffffff810938b5>] wake_up_process+0x15/0x20
[ 4773.122711]   [<ffffffff81237c91>] do_msgsnd+0x401/0x430
[ 4773.122717]   [<ffffffff81237d0d>] SyS_msgsnd+0x4d/0x60
[ 4773.122721]   [<ffffffff815d8ba0>] tracesys+0xdd/0xe2
[ 4773.122726] irq event stamp: 12549
[ 4773.122728] hardirqs last  enabled at (12549): [<ffffffff81142105>] user_exit+0x55/0xb0
[ 4773.122732] hardirqs last disabled at (12548): [<ffffffff811420eb>] user_exit+0x3b/0xb0
[ 4773.122736] softirqs last  enabled at (12468): [<ffffffff8149b463>] release_sock+0x173/0x1d0
[ 4773.122741] softirqs last disabled at (12464): [<ffffffff815cf478>] _raw_spin_lock_bh+0x18/0x70
[ 4773.122746] 
other info that might help us debug this:
[ 4773.122748]  Possible unsafe locking scenario:


[ 4773.122751]        CPU7
[ 4773.122752]        ----
[ 4773.122754]   lock(&xxx);
[ 4773.122757]   <Interrupt>
[ 4773.122759]     lock(&xxx);
[ 4773.122762] 

 *** DEADLOCK ***

参考：点击打开链接