专栏首页Linux问题笔记从一个抓包打满cpu问题理解内核soft lockup
原创

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

一台线上服务器在流量大时挂掉,怀疑是大流量时的抓包行为导致,向我们给出了线索是当时可能存在的三个抓包组件: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、软中断和抓包上的耗时:

  1. ABC同时全开
  2. 只开C
  3. 开AB但不开C
  4. 开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

上述统计,主要说明三个问题:

  1. 抓包是软中断中的大头,占了软中断处理90%以上的耗时
  2. 复现问题所需要的时间长度是 “ABC同时全开”< “开CA,不开B”<“只开C”< “开AB但不开C”, 且后两个只开的情况差异也几乎可忽略
  3. 根因还是有进程在内核态时间太久没有被调度出来(见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。

分四种情况测试:

  1. ABC同时全开
  2. 只开C
  3. 开AB但不开C
  4. 开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:

原创声明,本文系作者授权腾讯云开发者社区发表,未经许可,不得转载。

如有侵权,请联系 cloudcommunity@tencent.com 删除。

登录 后参与评论
0 条评论

相关文章

  • soft lockup和hard lockup介绍

    在linux kernel里,有一个debug选项LOCKUP_DETECTOR。

    233333
  • linux内核崩溃问题排查过程总结

    技巅
  • K8S内核故障[内核BUG]

    开启7个异常会触发OOM的节点,在一个NODE上,经过测试发现,3.10内核,是并行创建了7个任务,同时触发oom,导致内核锁耗死。测试 2-3分钟内,服务器会...

    院长技术
  • 一个ext4的Bug分析过程

    腾讯数据库技术
  • [linux][memory]ksm/uksm的调优和优化尝试

    前言: 在前文《[linux][memory]KSM技术分析》中,分析了KSM技术的基本实现原理。这里再总结一下使用ksm/uksm遇到的几个问题,并附加上作者...

    皮振伟
  • NFSv4客户端hung住的BUG,您解决了吗?

    最近经常在修复漏洞,昨天有几台物理机突然说需要升级内核,升级原因为 Redhat 7.4 kernel介于3.10.0-693.el7和3.10.0-693.5...

    雨夜v1
  • 不为人知的网络编程(十一):从底层入手,深度分析TCP连接耗时的秘密

    对于基于互联网的通信应用(比如IM聊天、推送系统),数据传递时使用TCP协议相对较多。这是因为在TCP/IP协议簇的传输层协议中,TCP协议具备可靠的连接、错误...

    JackJiang
  • 深入解析常见三次握手异常

    在后端接口性能指标中一类重要的指标就是接口耗时。具体包括平均响应时间 TP90、TP99 耗时值等。这些值越低越好,一般来说是几毫秒,或者是几十毫秒。如果响应时...

    开发内功修炼
  • 在调试器里看LINUX内核态栈溢出

    图灵最先发明了栈,但没有给它取名字。德国人鲍尔也“发明”了栈,取名叫酒窖。澳大利亚人汉布林也“发明”了栈,取名叫弹夹。1959年,戴克斯特拉在度假时想到了...

    Linux阅码场
  • 聊聊TCP连接耗时的那些事儿

    在互联网后端日常开发接口的时候中,不管你使用的是C、Java、PHP还是Golang,都避免不了需要调用mysql、redis等组件来获取数据,可能还需要执行一...

    Bug开发工程师
  • 聊聊TCP连接耗时的那些事儿

    在互联网后端日常开发接口的时候中,不管你使用的是C、Java、PHP还是Golang,都避免不了需要调用mysql、redis等组件来获取数据,可能还需要执行一...

    开发内功修炼
  • 动图图解!没有accept,能建立TCP连接吗?

    其实只要在执行accept() 之前执行一个 sleep(20),然后立刻执行客户端相关的方法,同时抓个包,就能得出结论。

    小白debug
  • 动图图解!没有accept,能建立TCP连接吗?

    其实只要在执行accept() 之前执行一个 sleep(20),然后立刻执行客户端相关的方法,同时抓个包,就能得出结论。

    moon聊技术
  • Kubernetes 疑难杂症排查分享:神秘的溢出与丢包

    图片下载走的 k8s ingress,这个 ingress 路径对应后端 service 是一个代理静态图片文件的 nginx deployment,这个 de...

    imroc
  • Redis高负载下的中断优化

    Redis 服务端的总体请求量从年初最开始日访问量百亿次级别上涨到高峰时段的万亿次级别,给运维和架构团队都带来了极大的挑战。

    美团技术团队

扫码关注腾讯云开发者

领取腾讯云代金券