从一个抓包打满cpu问题理解内核soft lockup

原创

johnazhang

发布于 2022-08-09 17:56:50

2.2K1

发布于 2022-08-09 17:56:50

文章被收录于专栏：Linux问题笔记

一台线上服务器在流量大时挂掉，怀疑是大流量时的抓包行为导致，向我们给出了线索是当时可能存在的三个抓包组件：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，先来分析看看：

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相关信息。

分析下这里的代码逻辑：

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   %eax,%eax
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),%eax
0xffffffffa0174db1 <inet_csk_diag_dump+113>:    mov    %eax,(%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的地址：

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的汇编代码：

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

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算出来的话：

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，没法去下一级函数里找，只能在本级函数里分析逻辑看是在哪里被赋值的：

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的地方：

0xffffffff818c3ca9 <__netif_receive_skb_core+2041>:     mov    -0x50(%rbp),%r8
0xffffffff818c3cad <__netif_receive_skb_core+2045>:     je     0xffffffff818c3800 <__netif_receive_skb_core+848>

栈：

#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。

最终的脚本代码如下：

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 %s\n##############################################################\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 us\n")
        foreach ([item] in cost_sk_total+)
        {
                printf("SOCK: %p called tpacket_rcv %lu us in total\n", 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 total\n", 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 total\n", 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 %d\n", 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：