简介

工作的时候碰到了个问题，我们的 agent 和业务方冲突导致了业务的抖动，经过分析发现是 rtnl 锁导致的。对于这个结论，我们并不是十分认可，因为根据我们自己的分析，这个事情是由多方面的条件共同导致的。

现象分析

运行环境

系统运行的环境是 linux kernel 4.18 / 3.10，业务方使用了 Java 的 NetworkInterface 的 api，我方使用的是 golang 调取 ethtool 再加上一个 cpu 限制 5% 的 cgroups v1。

运行现象

两个程序同时运行，都在尝试获取网卡的信息，运行的一段时间里，经常会出现业务方获取时间飙升的状况。在上述条件下，业务方的延迟通常会飙升到 900 ms 以上。

[root@jd ~]# java NetworkTest
time: 2024-09-30 10:20:48.874, cost: 764ms
time: 2024-09-30 10:23:03.858, cost: 954ms
time: 2024-09-30 10:25:45.858, cost: 968ms
time: 2024-09-30 10:28:33.858, cost: 967ms
time: 2024-09-30 10:33:28.858, cost: 940ms
time: 2024-09-30 10:36:28.858, cost: 965ms
time: 2024-09-30 10:39:43.858, cost: 963ms
time: 2024-09-30 10:46:41.858, cost: 915ms
time: 2024-09-30 10:49:53.858, cost: 964ms
time: 2024-09-30 10:54:19.858, cost: 947ms
time: 2024-09-30 10:56:54.858, cost: 971ms
time: 2024-09-30 11:03:00.858, cost: 926ms
time: 2024-09-30 11:06:21.858, cost: 961ms

问题追踪

首先是追踪业务方的程序，使用 strace 工具并开启耗时标记，获取日志后，选出其中耗时较长的 syscalls 进行分析，发现 java 的程序中耗时较长的 syscall 是 ioctl 。光这一个 syscall 的耗时就和业务程序中统计的时间十分接近，由此可见，这个 syscall 就是一切问题的关键。对之前结论的资料分析后，可以判断确实和 ioctl 的 rtnl 锁机制有关系，但是根据 ioctl 的正常执行时间判断，不可能只是 ioctl 的正常执行导致的这个现象，真凶另有其人。

2870193 <... ioctl resumed>3 * sizeof(struct ifreq), ifc_buf=NULL}) = 0 <0.727053>
2870193 <... ioctl resumed>3 * sizeof(struct ifreq), ifc_buf=NULL}) = 0 <0.922707>

于是我们又对我们的自己的 agent 进行测试，经过多维度的测试，发现在对 crgoups 的 cpu 资源逐渐放开以后，这个现象的复现率大大的降低了，此时我们有一个推测：会不会是由于 agent 的 ethtool 拿到 rtnl 锁以后，由于时间片轮转的原因，导致我们的 ethtool 在还没读取完的情况下被调出，导致业务方调用 ioctl 的时候无法获取锁从而进入了睡眠状态，导致业务方程序超时。

为了证明这个推论，我们还需要分析伴随这个现象出现的状况进行分析，那就是如果业务方出现了超时，同样，agent 的 ethtool 调用也会因为时间片轮转的原因出现一定程度的超时。为了更好的捕获这个现象，我写了一个 ebpf 程序进行分析，这个程序捕获到执行时间 > 200ms 的 ioctl 时，就会打印出这个程序打印出这个 ioctl 所在的进程id、线程id、执行时间、开始时间和结束时间。有了这些参数，我们判断竞争超时就相对比较容易了。

通过 ebpf 抓取到的日志如下，其中 Java 的 PID 为 2806178:

[2024-09-30T03:50:38Z INFO  kprobe_ioctl] pid: 2829282, tgid: 11234, release spend: 968152475 ns
     start time: 504500431966358, end time: 504501400118833
[2024-09-30T03:50:38Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 627502286 ns
     start time: 504500772643373, end time: 504501400145659
[2024-09-30T03:50:39Z INFO  kprobe_ioctl] pid: 2829315, tgid: 11267, release spend: 966159100 ns
     start time: 504501433922502, end time: 504502400081602
[2024-09-30T03:51:53Z INFO  kprobe_ioctl] pid: 2831790, tgid: 13742, release spend: 972114642 ns
     start time: 504575427991109, end time: 504576400105751
[2024-09-30T03:51:53Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 877739010 ns
     start time: 504575522417102, end time: 504576400156112
[2024-09-30T03:54:55Z INFO  kprobe_ioctl] pid: 2837882, tgid: 19834, release spend: 968143681 ns
     start time: 504757431961472, end time: 504758400105153
[2024-09-30T03:54:55Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 789541889 ns
     start time: 504757610727553, end time: 504758400269442
[2024-09-30T03:55:52Z INFO  kprobe_ioctl] pid: 2839782, tgid: 21734, release spend: 969153066 ns
     start time: 504814430966399, end time: 504815400119465
[2024-09-30T03:55:52Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 931801878 ns
     start time: 504814468465197, end time: 504815400267075
[2024-09-30T03:56:33Z INFO  kprobe_ioctl] pid: 2841150, tgid: 23102, release spend: 968172665 ns
     start time: 504855431937512, end time: 504856400110177
[2024-09-30T03:56:33Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 951321252 ns
     start time: 504855448864593, end time: 504856400185845
[2024-09-30T03:57:11Z INFO  kprobe_ioctl] pid: 2842419, tgid: 24371, release spend: 968115246 ns
     start time: 504893431971907, end time: 504894400087153
[2024-09-30T03:57:11Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 954630485 ns
     start time: 504893445505035, end time: 504894400135520
[2024-09-30T03:57:45Z INFO  kprobe_ioctl] pid: 2843542, tgid: 25494, release spend: 968130028 ns
     start time: 504927431970277, end time: 504928400100305
[2024-09-30T03:57:45Z INFO  kprobe_ioctl] pid: 2806178, tgid: 53667, release spend: 959551491 ns
     start time: 504927440600364, end time: 504928400151855
[2024-09-30T04:00:03Z INFO  kprobe_ioctl] pid: 2848168, tgid: 30120, release spend: 966108112 ns
     start time: 505065433999365, end time: 505066400107477