一台线上服务器在流量大时挂掉，怀疑是大流量时的抓包行为导致，向我们给出了线索是当时可能存在的三个抓包组件：A、B、C，当三个组件全部开启时，将流量打上去进行压测，很快会报soft lockup错误，且机器会非常卡。但是只开启一个组件压测，则并没有相关soft lockup报错。看现象似乎不符合逻辑？本文记录该问题的分析过程。
结论先行
流量起来时，抓包把90%以上的处理资源都耗光了，且无论是否有soft lockup，业务也已经无法正常提供服务。
而soft lockup出现的原因是，在软中断一直处于占cpu100%的情况下，内核有大量的软中断需要处理，当有进程在内核态触发软中断，就会使得该进程更难从系统调用的内核态返回，反复在内核栈->硬中断->软中断->内核栈之间不停的pin pon导致该进程在系统调用里面因为被软中断抢走而退不出来，导致watchdog进程得不到调度，从而在到达内核soft lockup检查时限时，就会报soft lockup。
分析方法
首先分析第一时间的内核coredump，看到最后报错的进程是组件A的进程：
分析得知抓包的只有组件B和组件C进程：
从core里看到的组件作用：
A: 不抓包，但是要频繁在内核态通过netlink获取socket信息
B: 抓包
因此分四种情况测试，编写内核stap脚本分别抓取内核在netlink、软中断和抓包上的耗时：
- ABC同时全开
- 只开C
- 开AB但不开C
- 开CA，不开B
（没有开BC是因为和1一样）
数据体现
四种情况均能复现，复现时间是“开AB但不开C”情况最长。
机器有80个核。
这里列出四种情况复现时单次调用netlink的最大耗时（不开启panic，等恢复后观察最大值）、软中断总耗时（单个核的耗时*80来计算，为近似值）与抓包总耗时的占比（开启panic，数据均为kexec重启前的最后一次的累计值，统计累计耗时而没有统计每秒耗时是因为，80个核cpu100%，每秒软中断总耗时都是80s），表中单位为us：
抓包累计总耗时 | 软中断累计总耗时 | 抓包在软中断中占比 | netlink单次最大耗时 | |
|---|---|---|---|---|
ABC同时全开 | 2284195602 | 2432000000 | 93% | 63926202 |
只开C | 10730132532 | 11856500000 | 91% | 没抓到，因为栈不在netlink调用上，见下一小节问题原因的最后一段分析 |
开AB但不开C | 11249816264 | 12426800000 | 91% | 32454524 |
开CA，不开B | 7169569435 | 7920000000 | 91% | 33554432 |
上述统计，主要说明三个问题：
- 抓包是软中断中的大头，占了软中断处理90%以上的耗时
- 复现问题所需要的时间长度是 “ABC同时全开”< “开CA，不开B”<“只开C”< “开AB但不开C”, 且后两个只开的情况差异也几乎可忽略
- 根因还是有进程在内核态时间太久没有被调度出来（见netlink统计，均超过watchdog的报错时间10s）
问题原因
问题复现时，系统软中断负载打到100%：
软中断时主要消耗在抓包上（tpacket_rcv是抓包函数）：
而系统软中断要执行的任务很多的时候，存在进程长时间处在执行软中断上下文的状态下，无法被调度走，而导致softlockup报错。
而开了组件A更容易复现的原因是，组件A会有比较多的netlink内核态操作，见下图的栈，而netlink_sendmsg->inet_diag_dump_icsk后，会做do_softirq主动触发软中断，导致被软中断拿走的情况更多，因此组件A会更难返回用户态触发调度，反复在inet_csk_diag_dump->硬中断->软中断->inet_csk_diag_dump之间不停的pin pon导致组件A在系统调用里面因为被软中断抢走而退不出来，导致watchdog得不到调度，从而到达内核soft lockup检查时限时，检查到了watchdog在时限内没有被调度，就会报soft lockup。
从一次复现时从内核抓到的组件A netlink函数耗时统计（记录进程退出netlink_sendmsg时的时间戳，减去进程进入netlink_sendmsg的时间戳），可以更直观看出，运行组件A的cpu有60多秒都没被调度：
然后开启内核softlockpanic配置，再复现一遍，这样触发coredump后可以更实锤的查看触发softlock瞬间的调度时间的情况：
最后一次调度时间是panic前23秒：
但是需说明，组件A并不是导致softlockup现象本身的原因，而是加速暴露了softlockup的出现，因为很多进程都是要进入内核态的，也会有很多地方会主动触发软中断，只是因为组件A他进入内核态主动触发软中断的次数比较多，而成为了倒霉蛋。
对于上述的反向论证是，在只开组件C的情况下，如果压测时间够久，也是可以复现。来直观的看一下只开组件C关掉AB后抓到的coredump：
仍然是内核态主动触发了do_softirq软中断，只是这里不是组件A进程而是另一个名为base的进程，触发软中断也不是netlink而是sys_read。
因此只要是在软中断一直处于占cpu100%的情况下，有进程在内核态触发软中断，就有概率出现soft lockup。
分析过程
附上从头到尾对该问题的详细分析过程。以下出现的代码均来自基于3.10的内核版本。
内核coredump分析
首先拿到的是当时留下的内核coredump，先来分析看看：
代码语言：javascript复制crash> bt
PID: 61739 TASK: ffff883fa1fe99d0 CPU: 39 COMMAND: "组件A"
#0 [ffff88407f263950] machine_kexec at ffffffff8103040c
#1 [ffff88407f2639a8] crash_kexec at ffffffff810b8592
#2 [ffff88407f263a78] panic at ffffffff819dc46a
#3 [ffff88407f263af8] watchdog_timer_fn at ffffffff810d49c3
#4 [ffff88407f263b28] __run_hrtimer at ffffffff81071853
#5 [ffff88407f263b68] hrtimer_interrupt at ffffffff81072047
#6 [ffff88407f263bd8] smp_apic_timer_interrupt at ffffffff81ac6e99
#7 [ffff88407f263bf8] apic_timer_interrupt at ffffffff81ac5fca
#8 [ffff88407f263c98] tpacket_rcv at ffffffff819accb2
#9 [ffff88407f263d30] __netif_receive_skb_core at ffffffff818c381c
#10 [ffff88407f263d90] __netif_receive_skb at ffffffff818c3d5d
#11 [ffff88407f263db0] netif_receive_skb at ffffffff818c3e02
#12 [ffff88407f263de0] napi_gro_receive at ffffffff818c4810
#13 [ffff88407f263e00] i40e_clean_rx_irq at ffffffffa0057afa [i40e]
#14 [ffff88407f263e68] i40e_napi_poll at ffffffffa0058513 [i40e]
#15 [ffff88407f263ee8] net_rx_action at ffffffff818c4169
#16 [ffff88407f263f40] __do_softirq at ffffffff8104ebb0
#17 [ffff88407f263fb0] call_softirq at ffffffff81ac66ac
--- <IRQ stack> ---
#18 [ffff883f96bbb7d0] inet_csk_diag_dump at ffffffffa0174db9 [inet_diag]
#19 [ffff883f96bbb820] inet_diag_dump_icsk at ffffffffa017580d [inet_diag]
#20 [ffff883f96bbb930] tcp_diag_dump at ffffffffa02110bc [tcp_diag]
#21 [ffff883f96bbb940] __inet_diag_dump at ffffffffa0174620 [inet_diag]
#22 [ffff883f96bbb978] inet_diag_dump_compat at ffffffffa0174ed6 [inet_diag]
#23 [ffff883f96bbb9d8] netlink_dump at ffffffff818f140e
#24 [ffff883f96bbba08] __netlink_dump_start at ffffffff818f2033
#25 [ffff883f96bbba40] inet_diag_rcv_msg_compat at ffffffffa017480b [inet_diag]
#26 [ffff883f96bbbaa0] sock_diag_rcv_msg at ffffffff818d7e40
#27 [ffff883f96bbbac8] netlink_rcv_skb at ffffffff818f3e09
#28 [ffff883f96bbbaf0] sock_diag_rcv at ffffffff818d7c68
#29 [ffff883f96bbbb08] netlink_unicast at ffffffff818f3572
#30 [ffff883f96bbbb50] netlink_sendmsg at ffffffff818f3923
#31 [ffff883f96bbbbe8] sock_sendmsg at ffffffff818a97e0
#32 [ffff883f96bbbd28] ___sys_sendmsg at ffffffff818ac8ce
#33 [ffff883f96bbbec8] __sys_sendmsg at ffffffff818ad041
#34 [ffff883f96bbbf38] compat_sys_socketcall at ffffffff818e3456
#35 [ffff883f96bbbf80] sysenter_dispatch at ffffffff81ac6753
RIP: 00000000f7785440 RSP: 00000000ffe77bbc RFLAGS: 00000296
RAX: 0000000000000066 RBX: ffffffff81ac6753 RCX: 00000000ffe77bd0
RDX: 000000000839a47c RSI: 0000000000000000 RDI: 000000000000000a
RBP: 00000000ffe79d58 R8: 0000000000000000 R9: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: 0000000000000000 R14: 0000000000000010 R15: 000000002ed970c2
ORIG_RAX: 0000000000000066 CS: 0023 SS: 002b看到死在组件A，了解到组件A是需要通过netlink获取一些信息，也是要用inet_diag模块来去统计socket相关信息。
分析下这里的代码逻辑：
代码语言：javascript复制crash> dis -rl ffffffffa0174db9
0xffffffffa0174d40 <inet_csk_diag_dump>: nopl 0x0(%rax,%rax,1) [FTRACE NOP]
0xffffffffa0174d45 <inet_csk_diag_dump 5>: push %rbp
0xffffffffa0174d46 <inet_csk_diag_dump 6>: mov %rsp,%rbp
0xffffffffa0174d49 <inet_csk_diag_dump 9>: push %r15
0xffffffffa0174d4b <inet_csk_diag_dump 11>: mov %rcx,%r15
0xffffffffa0174d4e <inet_csk_diag_dump 14>: push %r14
0xffffffffa0174d50 <inet_csk_diag_dump 16>: mov %rdx,%r14
0xffffffffa0174d53 <inet_csk_diag_dump 19>: push %r13
0xffffffffa0174d55 <inet_csk_diag_dump 21>: mov %r8,%r13
0xffffffffa0174d58 <inet_csk_diag_dump 24>: push %r12
0xffffffffa0174d5a <inet_csk_diag_dump 26>: mov %rsi,%r12
0xffffffffa0174d5d <inet_csk_diag_dump 29>: mov %rdi,%rsi
0xffffffffa0174d60 <inet_csk_diag_dump 32>: push %rbx
0xffffffffa0174d61 <inet_csk_diag_dump 33>: mov %rdi,%rbx
0xffffffffa0174d64 <inet_csk_diag_dump 36>: mov %r9,%rdi
0xffffffffa0174d67 <inet_csk_diag_dump 39>: sub $0x18,%rsp
0xffffffffa0174d6b <inet_csk_diag_dump 43>: callq 0xffffffffa0174410 <inet_diag_bc_sk>
0xffffffffa0174d70 <inet_csk_diag_dump 48>: test �x,�x
0xffffffffa0174d72 <inet_csk_diag_dump 50>: je 0xffffffffa0174db9 <inet_csk_diag_dump 121>
0xffffffffa0174d74 <inet_csk_diag_dump 52>: mov (%r14),%rdx
0xffffffffa0174d77 <inet_csk_diag_dump 55>: mov (%r15),%rax
0xffffffffa0174d7a <inet_csk_diag_dump 58>: mov %r13,%rcx
0xffffffffa0174d7d <inet_csk_diag_dump 61>: mov %rbx,%rsi
0xffffffffa0174d80 <inet_csk_diag_dump 64>: mov %rbx,%rdi
0xffffffffa0174d83 <inet_csk_diag_dump 67>: mov 0x3c(%rdx),%r9d
0xffffffffa0174d87 <inet_csk_diag_dump 71>: mov 0x48(%rdx),%rdx
0xffffffffa0174d8b <inet_csk_diag_dump 75>: mov 0x1f0(%rdx),%rdx
0xffffffffa0174d92 <inet_csk_diag_dump 82>: mov 0x18(%rdx),%rdx
0xffffffffa0174d96 <inet_csk_diag_dump 86>: mov 0x70(%rdx),%rdx
0xffffffffa0174d9a <inet_csk_diag_dump 90>: mov 0x78(%rdx),%r8
0xffffffffa0174d9e <inet_csk_diag_dump 94>: mov %rax,0x10(%rsp)
0xffffffffa0174da3 <inet_csk_diag_dump 99>: mov %r12,%rdx
0xffffffffa0174da6 <inet_csk_diag_dump 102>: movl $0x2,0x8(%rsp)
0xffffffffa0174dae <inet_csk_diag_dump 110>: mov 0x8(%rax),�x
0xffffffffa0174db1 <inet_csk_diag_dump 113>: mov �x,(%rsp)
0xffffffffa0174db4 <inet_csk_diag_dump 116>: callq 0xffffffffa0174840 <inet_sk_diag_fill>
0xffffffffa0174db9 <inet_csk_diag_dump 121>: add $0x18,%rsp对应的是：
也就是说这里被中断激活软中断收包抢走，进入irq栈。
这里关中断
然后再打开中断，关下半部
这里进的net_rx_action, 进去的时候是软中断上下文，因此这时初步怀疑，如果太久没出来，有可能是导致soft lock的原因。
继续往下一层看。
这里进i40e_napi_poll，物理机intel网卡驱动。
i40e_napi_poll是i40e注册的napi poll收包函数。
从这里进了i40e_clean_rx_irq，这里又出现一个疑点，就是会不会是这个vector太长了？来确认下。
先分析代码把数据结构找到：
napi的地址是ffff881fc52f3010，是从栈中找到，此处省略过程。
看到解析出来可以对上，说明找对了。
然后进一步找到vector的地址：
代码语言：javascript复制crash> i40e_q_vector -xo | grep napi
[0x10] struct napi_struct napi;
crash> i40e_q_vector.rx ffff881fc52f3000
rx = {
ring = 0xffff881fc5303700,
next_update = 4377687765,
total_bytes = 59645184,
total_packets = 806016,
count = 1,
target_itr = 32778,
current_itr = 32778
}
crash> i40e_ring 0xffff881fc5303700
struct i40e_ring {
next = 0x0,可以看到count是1 next是0，数组很小就一个，循环自然不会耗时，那目测就不是这里的问题。
继续往栈下看：
最后调用pt_prev->func的汇编代码：
代码语言：javascript复制0xffffffff818c3815 <__netif_receive_skb_core 869>: mov %r8,%rdx
0xffffffff818c3818 <__netif_receive_skb_core 872>: callq *0x10(%r8)
0xffffffff818c381c <__netif_receive_skb_core 876>: mov -0x40(%rbp),%rbx调用的是r8 0x10，而r8给了rdx，也就是第三个参数，而第三个参数正是pt_prev本身（r8一般是第五个参数，这里看起来是这样应该是内核编译优化导致的）。可以看到func指针的偏移量正好是0x10。
crash> packet_type.func -xo struct packet_type {[0x10]int(*func)(struct sk_buff *, struct net_device *, struct packet_type *, struct net_device *);}
到此可以确定，是这里进入的tpacket_rcv无误。
到这里，又存在一种可能，就是一次软中断，调用了很多次tpacket_rcv，每次耗时都不短，然后加起来最终导致超时。这里对应的就是ptype链表，所以来看看是不是ptype链表太长了。
链表是pytpe_base:
先找PTYPE_HASH_MASK:
是1111
代码语言：javascript复制crash> sk_buff.protocol ffff883d43aeed00
protocol = 8
crash> p ptype_base[8]
$3 = {
next = 0xffffffff82045a40 <ptype_base 128>,
prev = 0xffffffff82045a40 <ptype_base 128>
}
crash> eval ffffffff820459c0 0x80
hexadecimal: ffffffff82045a40
crash> rd ffffffff82045a40 2
ffffffff82045a40: ffffffff82045a40 ffffffff82045a40 @Z......@Z......找到后发现当前这个东西值等于自己的地址，还是刚初始化的状态，推测应该是之后被什么东西改回去了。
看到代码里，没有地方会给他直接赋值。
不过这也无法说明他没有被赋值，因为他是按照ptype->list去赋值的。
所以可以先忽略这个链表处于初始化状态的现象。
先按当前的值，list entry算出来的话：
代码语言：javascript复制crash> packet_type -xo
struct packet_type {
[0x0] __be16 type;
[0x8] struct net_device *dev;
[0x10] int (*func)(struct sk_buff *, struct net_device *, struct packet_type *, struct net_device *);
[0x18] bool (*id_match)(struct packet_type *, struct sock *);
[0x20] void *af_packet_priv;
[0x28] struct list_head list;
}
crash> eval ffffffff82045a40-0x28
hexadecimal: ffffffff82045a18 这个地址是解析不出来的，如果真的是这个地址，也没办法通过函数指针去进入tpacket_rcv。
因此试图换个方法找到他，尝试直接从栈里找一下pt_prev, 现在知道他是r8，因为r8不是callee-saved，没法去下一级函数里找，只能在本级函数里分析逻辑看是在哪里被赋值的：
代码语言：javascript复制0xffffffff818c380b <__netif_receive_skb_core 859>: mov 0x20(%rbx),%rsi
0xffffffff818c380f <__netif_receive_skb_core 863>: mov %rbx,%rdi
0xffffffff818c3812 <__netif_receive_skb_core 866>: mov %r14,%rcx
0xffffffff818c3815 <__netif_receive_skb_core 869>: mov %r8,%rdx
0xffffffff818c3818 <__netif_receive_skb_core 872>: callq *0x10(%r8)分析代码的跳转逻辑，得知是从这里跳回848后一路走到的872call，也就是r8的值应该在栈里-50的地方：
代码语言：javascript复制0xffffffff818c3ca9 <__netif_receive_skb_core 2041>: mov -0x50(%rbp),%r8
0xffffffff818c3cad <__netif_receive_skb_core 2045>: je 0xffffffff818c3800 <__netif_receive_skb_core 848>栈：
代码语言：javascript复制#9 [ffff88407f263d30] __netif_receive_skb_core at ffffffff818c381c
ffff88407f263d38: 0000000000000000 0000000000000000
ffff88407f263d48: ffff883d43aeed00 ffffffff82048528
ffff88407f263d58: 000000002ed970c2 ffff883d43aeed00
ffff88407f263d68: ffff881fc52f3010 000000000000004a
ffff88407f263d78: 0000000000000000 ffff881fc5303700
ffff88407f263d88: ffff88407f263da8 ffffffff818c3d5d发现居然是0?
但是他如果进去了tpacket_rcv，就说明这块的内存肯定是之后被什么东西改掉了，无法参考，而不是第一现场。
因此现在从core里的现场，已经没办法统计这个链表到底有多长了。
得动态分析软中断/抓包耗时来确认问题。
先从core里看一把临死前有哪些socket在抓包：
看到只有组件C和组件B有开了PACKET协议的sock，说明是他俩在抓包，和业务的描述能对上（这里看到SOCKET类型是PACKET说明是在抓包，内核里抓包其实走的是一个单独的四层协议栈，从socket层面是以PF_PACKET作为参数下发）。
到目前，怀疑的点还是在软中断本身耗时上。
动态抓取内核行为统计各部耗时
使用业务提供的环境直接开启压测，问题可以稳定必现，且复现速度比较快。
首先复现一把。
复现时的top，都是软中断高：
perf抓下来，耗时在抓包上：
抓包函数tpacket_rcv里有个spinlock，如果大家都在抢这一把锁，可能确实会耗时很久：
所以有必要统计一下耗时。
试验方法
编写了stap脚本，主要实现统计每秒软中断总耗时（按cpu区分），软中断中抓包函数tpacket_rcv总耗时（按sock区分），netlink耗时（由于在core里看到栈死在netlink_sendmsg上，所以也要排除有可能是netlink耗时久的影响，按进程execname区分）。并且将截止到当前时间的耗时时间分布，按直方图打印出来，每秒打印一次，所有单位均为us。
最终的脚本代码如下：
代码语言：javascript复制global curr, cost_sk_total, sk_map
global nl, nl_cnt, nl_cnt_total, soft_curr, soft_cnt, soft_cnt_total
global cost_sk, tpacket_rcv_cnt, tpacket_rcv_max
global netlink_superhigh
probe kernel.function("tpacket_rcv").call
{
sk = $pt->af_packet_priv
if(sk != 0)
{
sk_map[$skb] = sk
curr[$skb] = gettimeofday_us()
}
tpacket_rcv_cnt[cpu()] = 1
}
probe kernel.function("tpacket_rcv").return
{
sk = sk_map[@entry($skb)]
delete sk_map[@entry($skb)]
if(sk != 0)
{
val = gettimeofday_us() - curr[@entry($skb)]
cost_sk <<< val
cost_sk_total[sk] = val
}
delete curr[@entry($skb)]
}
probe kernel.function("netlink_sendmsg").call
{
nl[execname()] = gettimeofday_us()
}
probe kernel.function("netlink_sendmsg").return
{
val = gettimeofday_us() - nl[execname()]
nl_cnt <<< val
nl_cnt_total[execname()] = val
if(val > 5000000)
{
printf("##################super high cost netlink found######################n")
printf("comm: %s took %lu us in netlink at %sn##############################################################n", execname(), val, tz_ctime(gettimeofday_s()))
}
}
probe kernel.function("net_rx_action").call
{
soft_curr[cpu()] = gettimeofday_us()
}
probe kernel.function("net_rx_action").return
{
val = gettimeofday_us() - soft_curr[cpu()]
soft_cnt <<< val
soft_cnt_total[cpu()] = val
if(tpacket_rcv_max[cpu()] < tpacket_rcv_cnt[cpu()])
{
tpacket_rcv_max[cpu()] = tpacket_rcv_cnt[cpu()]
}
tpacket_rcv_cnt[cpu()] = 0
}
probe timer.s(1)
{
printf("n-----------------------%s------------------------n", tz_ctime(gettimeofday_s()))
printf("All statistics are in unit of usn")
foreach ([item] in cost_sk_total )
{
printf("SOCK: %p called tpacket_rcv %lu us in totaln", item, cost_sk_total[item])
}
if(@count(cost_sk))
{
print(@hist_log(cost_sk))
}
printf("---------------------------------------------------------------------n")
foreach ([comm] in nl_cnt_total )
{
printf("NETLINK: comm %s called netlink_sendmsg %lu us in totaln", comm, nl_cnt_total[comm])
}
if(@count(nl_cnt))
{
print(@hist_log(nl_cnt))
}
printf("---------------------------------------------------------------------n")
foreach ([c] in soft_cnt_total )
{
printf("SOFTIRQ: cpu %d cost %lu us in totaln", c, soft_cnt_total[c])
}
if(@count(soft_cnt))
{
print(@hist_log(soft_cnt))
}
printf("---------------------------------------------------------------------n")
foreach ([c] in tpacket_rcv_max )
{
printf("There are maximum %d tpacket_rcv executed in a single softirq of cpu %dn", tpacket_rcv_max[c], c)
}
}然后开始实验，配置都是watchdog thresh为10秒超时报错，开启softlockup panic在报错的同时重启生成coredump。
分四种情况测试：
- ABC同时全开
- 只开C
- 开AB但不开C
- 开CA，不开B
软中断与抓包耗时分析
ABC同时全开
问题可以复现，生成对应vmcore和脚本日志。
从core里找到两者的sock：
挂掉前脚本记录的最后信息：
可以看到，sock 0xffff883f98da9000对应的是组件C，sock 0xffff883f95a90800对应的是组件B, 这两者在抓包上的总耗时平分秋色，而该秒的耗时通过直方图可以看出，单次耗时的分布主要集中在1024-2048us区间。
而netlink记录到的耗时跟两者不在一个量级。
软中断的耗时，每个核最终是30s左右，80个核就是2400s左右；而抓包tpacket的耗时把组件C和组件B两者相加，是2200s左右；因此可以算出抓包占软中断耗时的比例在90%以上，是软中断耗时的大头。
再来计算下，每秒的抓包总耗时，这样可以直观的和后续其他情况做对比。
从日志里来看，压测时，每秒的抓包耗时是十分接近的，因此取一秒前的日志计算：
计算组件C该秒总耗时增长：
计算组件B该秒总耗时增长：
两者也接近，是37s左右（1s里耗时37s是因为这里是所有抓包耗时加起来，如果softirq是100%的情况下，80个核就是80s，90%左右就是72s左右，而37*2是74s左右，也是可以和之前算出来的结果对上）。
但是这里一个疑点就出现了，单次抓包的耗时从这个直方图里来看，分布最多的不过就耗时了1ms左右，一次软中断里，得调10000次抓包（中间修改过脚本统计了一次，平均是100次左右最多也不过200多次，不过后来把脚本改回去了，这个中间状态的数据就没有记录下来），才能达到softlock的超时时间10s，这显然不可能。
单次抓包耗时分布直方图：
而从软中断的耗时直方图来看，更直观：
单次软中断耗时最多的分布也就集中在0.1s左右。所以这里可以确认的是，抓包导致的软中断高，进而导致打满cpu，但无法解释soft lockup出现的原因。
AB全开，关闭C
继续把接下来的实验做完，业务侧也需要了解观察抓包上的对比，以及确认现象是否都是类似。
问题可以复现，生成对应vmcore和脚本日志。
core里看到，只有组件B在抓包：
挂掉前脚本记录日志的最后信息，sock可以对上：
抓包tpacket_rcv总耗时在11000s左右，每次的耗时依然集中在1024与2048us之间为主。
软中断单核总耗时155s左右，80核12400s左右，抓包总耗时依然占软中断耗时90%以上。
不过可以注意到的是，总耗时明显增加了几倍多，初步推测怀疑是因为并发相对不激烈，这也是为什么之前测试的时候，只开启某一个抓包未能复现，其实只是因为压测时间不够长。
再来看一下每秒的耗时，还是取一秒前的数据：
每秒耗时，也比之前的组件B有一倍左右的增长，72s左右的每秒总耗时和之前相比也没有变化，且从之前实验组件C和组件B抓包负载接近来看，关掉组件C、组件B耗时总量有一倍的增长也是符合预期。
同样也没有观察到非常耗时的抓包和软中断的出现，抓到的netlink耗时也非常短。
后面两次只开组件C和同时开启组件AC的实验，统计方法相同，就不重复贴上来了，数据可以参考结论部分中的“数据体现”。
进程内核态耗时太高的真相浮出水面
到这里，我们每次生成的coredump里都可以明确的看到，报错进程是有超过20s没被调度走，比如：
但是最后死亡现场的栈，并不一定都在抓包上，比如下图这次，内核栈是netlink但是irq栈不是抓包：
且最关键的是stap脚本抓到的耗时统计却完全无法对上，软中断被证明了耗时不会太长，也没有抓到非常耗时的netlink。
这里也就不卖关子了，直接说原因。问题本质上还是在进程的内核态耗时太长（系统调用，比如上图里就是sendmsg->netlink_sendmsg），但是打印不出来是因为，在之前的实验里，开启了softlock直接panic生成coredump，在调度回来的第一时间就触发了panic挂掉了，根本没有时间给我们systemtap返回来把日志打印出来！
因此，首先关掉softlock panic再来继续试验。
然后修改脚本，只打印超过五秒耗时的netlink：
再复现一把，直接抓到：
可以看到，打印出来的时候说明了该组件A进程耗时了63秒在netlink的系统调用上没出来（原因请见第一节中的“问题原因”）。
从第一次打印softlock的时间15:34:47往回倒推报错的22s是15:34:25，到打印出来进程执行完netlink的时间戳15:35:27, 是62s，时间也可以对上。
至于这里最终是卡了60s而之前是20s原因也比较好理解，就是没有开panic的情况下没有立刻重启，我们手动停压测操作慢了一些，就导致他在内核栈来回处理软中断表现的耗时更久了一些。
根据此方法，再将之前四种情况在不开启panic的情况下，重复测试了一遍，得到了第一小节“数据体现”中的“netlink单次最大耗时”。
到这里算是抓到了实锤，已经可以得出开篇给出的结论，且也可以合理的解释了为什么每次生成的coredump中的irq栈并不一定都在抓包上。
关于netlink为什么会触发大量软中断
而netlink调用路径会触发大量软中断的原因，从代码里推测来看，是在调用到inet_diag_dump_icsk这层后，该函数中会有两次spin_lock_bh/spin_unlock_bh调用：
而spin_unlock_bh调用中，是会在最终触发do_softirq，从他的层层定义里可以挖到：
这个if判断，顾名思义在有大量软中断的时候会为真，因此会触发do_softirq。
关于watchdog超时时间与softlockup报警逻辑
设置10s为thresh但是20s报错的原因是，thresh只是软狗检查的timer设定，而softlock的报错周期是thresh*2：
soft lockup打印了两次，但是内容相同的原因是这里是syslog打印了两次，时间戳其实是syslog打出来的，而dmesg本身只打印了一次，原理可以参考软狗timer代码watchdog_timer_fn：
