Categories
程式開發

eBay云计算“网”事:网络超时篇


导读
eBay自2016年开始将业务迁往Kubernetes容器平台,其间遇到了各种网络问题。云计算“网”事系列旨在介绍 eBay IE Cloud团队 巧妙利用eBPF工具进行排查,并解决这些典型网络问题的事迹。该系列分为三篇: 网络超时篇、网络丢包篇及网络重传篇 。本篇主讲网络超时问题,希望能为类似问题的定位和解决提供思路。

背景介绍

eBay从 2016年 开始将Kubernetes项目作为下一代云平台方案。经过几年的发展实践,已经逐步完成各大主要业务往Kubernetes容器平台上的迁移。在这过程中,碰到大大小小的问题数不甚数。 其中大规模应用场景下的偶发性问题,一直是这些问题中的关键难点。 随机性,小概率发生,不容易复现,都给这类问题的现场捕捉和定位造成重重困难。定位和解决此类问题,一般需要数天甚至数周的时间。通过 eBPF方式 来对内核进行剖析,是目前业内逐步开始探索的一个定位此类问题的方式,而eBay也在定位诸多问题中,渐渐累积开发了针对某些此类问题的eBPF工具。

云计算“网”事 系列文章,将从利用eBPF工具来解决eBay云平台碰到的几个典型网络问题入手,包含 网络延时、网络丢包、网络重传 三个方面,给出详细的摸索和排查分析过程,希望能为定位和解决相关问题提供思路。

应用运行在虚拟机或者物理机上,可以直接通过机器的网络端口进行数据传输,而在Kubernetes的节点上,容器运行在独立的network namespace,通过veth pair 接口来对外进行数据通信。一个常见的容器网络配置如图1所示:

eBay云计算“网”事:网络超时篇 1

图1

外部来容器的数据,经过物理机网卡eth0接收后,会经过路由,到达运行在主机network namespace的cali端口,再通过veth pair送到容器network namespace的eth0端口。在这中间会经过iptables或者 ipvs 的处理。容器往外发生数据,是接收数据的反向路径。

网络超时篇

案例1

某个运行在Kubernetes集群上的多实例应用,客户端发起的请求偶尔会超时。从现象来看,往某些节点上的服务发起的请求,每个小时的超时数会比其他的节点多几十次或者几百次。该pod提供对后段数据库的查询,然后返回结果给用户。客户端的超时时间是 400ms

eBay云计算“网”事:网络超时篇 2

超时信息:

eBay云计算“网”事:网络超时篇 3

图2

由图2可见,有一个节点的超时次数比较高,而其他节点的超时次数一个小时内也有100次左右。从总体上来看,一个小时内的调用到达万次以上,因此总体的timeout率不高。

针对这个问题,我们首先做了如下几个排查工作:

  1. 因为用户汇报了自从某个时间段开始,发现timeout的数量增加,所以我们先查看了那个时间段,是否有什么版本改动引起了问题,并排查了几个关联的修改,但没有发现和此类问题有直接的联系。
  2. 检查出问题机器的网络配置是否正确。为了减少数据包发送的乱序,提高性能,针对cali端口,使能了RPS(Receive Packet Steering)。检查下来,该端口配置都没有问题。
  3. 节点的CPU使用率和负载并不高。
  4. 检查了出现超时问题比较多的节点及其相关metrics 的信息,没有明显的节点的丢包统计和重传。从timeout的次数和总体的查询次数来看,这个也符合预期。
  5. 通过qperf来检测节点的tcp延时,并没有看到明显的延时问题。
  6. 使用tcpdump来抓取容器端口的数据并且同步观测容器的出错信息,当日志中打出出错信息的时候,tcpdump上观测到有数据重传,如图3所示。该连接的RTO在 200ms 左右,所以当链路有问题的时候,是很可能发生重传的。

eBay云计算“网”事:网络超时篇 4

图3

  1. 从其他的节点ping该节点,会有间断的延时突发问题。

eBay云计算“网”事:网络超时篇 5

图4

通过ping pod来复现问题,可以从图4看到有延时突然增多的现象,那就基本可以确定,数据从链路到容器的tcp协议栈,已经出现延时突发的问题了。 通过ping物理机的网卡,可以看到延时突发的现象基本消失,因此主机侧出问题的可能性比较大。

但是定位主机侧的问题,面临着很大的困难。

首先,在大规模的集群上,节点的metrics很多都是以分钟为间隔来进行抓取的,很多时候并不能反应出问题时间段内发生了什么。 假如因为某个时间段内的系统负载突然增高导致了延时问题,从metrics上往往是看不到的。另外,metrics的精细化不够。例如tcp的丢包和重传,反映的是一个时间段内总的增长值,但如果问题是在很短的时间内发生的,那就很难说明两者之间有必然的相关性。
其次,很难直接找到和延时相关的证据。 一般都是看到某些异常,从离散的点去怀疑,不断修改验证,最后观察到问题没有再出现,说明问题已经解决。这也是目前在众多公众号文章看到定位系统问题的普遍解决方式。 因为Linux系统模块之间错综复杂的联系和相互影响,导致很多时候解决问题只能用排除法。 如果排除了怀疑的点后,问题仍旧没有改善,那就只能找新的点继续排除。该方法并不能说是不好,但肯定不是最优的解决问题的方式。因为就算解决了问题,很多时候还是无法找到引起问题的具体原因。
除此之外,利用tcpdump来处理这样的问题,会比较困难 ,得在主机的eth0, cali端口,容器的eth0同时长时间抓包,之后再将抓到的数据进行合并分析,看看是哪一节点引入的延时。另外tcpdump本身的overhead,是否会导致延时的突发也是个未知数,而且也无法诊断是否是iptables/ipvs引起的延时。 还有tcpdump只能输出基本的数据包信息,但是有关内核的信息在定位问题的时候还是不够。 因此tcpdump只能作为一个辅助工具,无法完全依赖。

在这样的基础上,我们只能逐步排查是哪个模块引起的问题。思路是逐步停掉各种业务,然后进行ping测试,如果没有出现突发情况,则说明跟停掉的模块有很大的关系。

通过该方式,我们发现kubelet有很大的嫌疑 ,查看社区问题,找到一个类似的案例:

https://github.com/google/cadvisor/issues/1774#issuecomment-501907566

同我们碰到的问题一样,可以通过drop cache 来进行修复。在继续往下深究的过程中,该问题的处理作者发布了一个博客:

https://github.blog/2019-11-21-debugging-network-stalls-on-kubernetes/

其中详细阐述了他们定位该问题的过程,以及引起该问题的原因。

简单来说,就是pod删除后,cgroup还残留在cache中,导致kubelet获取根cgroup内存统计信息的系统调用耗费太长时间,进而影响了ksoftirqd对softirq的处理。而为何cgroup在容器删除后,还会有信息遗留呢,感兴趣的可以查看链接:

https://lwn.net/Articles/787614/

主机的延时问题会是经常碰到的一个难题 ,因此在定位该问题的过程中,我们就在想如何能够加速该类型问题的定位,而不用像定位本案例的时候,采取逐个排除的方式。主要的想法就是利用工具来快速找到数据产生延时的点,当获知数据在哪个路径上产生了延时之后,就可以针对性缩小范围进行下一步的排查。受开源项目https://github.com/yadutaf/tracepkt的启发, 我们也开发了基于eBPF的工具,来记录数据包在内核里面的处理流程。主要功能包括

  • 通过TRACEEVENT或者kprobe来探测网络协议栈在二层,三层和四层上的典型路径,例如net:netif_rx,net:net_dev_queue,net:napi_gro_receive_entry,net:netif_receive_skb_entry等。可以通过指定IP地址或者端口号等来抓取指定的数据包的处理事件。
  • 当对应的函数被调用或者event被触发,则会从skb中获取当前的network namespace、端口信息、CPU核、调用时间、进程号、数据包的五元组、数据包长度等信息。
  • 因为我们的节点上会同时使用iptables和ipvs,所以也抓取了iptables和ipvs 各个处理链的入口和出口,用于计算各个处理链的花费时间,以及已经处理链对数据包的处理策略,例如ACCEPT,DROP等。

案例2

某个应用的实例有部署在虚拟机中,也有以容器部署到kuberntes集群中。应用的管理员从监控中发现,调用某个第三方API的超时比例不同,前者在 0.001% ,后者在 0.01%-0.04% ,之间差了数十倍,因此汇报出该问题,让我们去排查为何会有这样的差别。

经过沟通了解到,该用户客户端的超时时间是 100ms ,所有以容器部署的节点,超时的错误率都比运行在虚拟机上要高。于是我们开始着手定位该问题:

  1. 开始复现

    在节点上进行100次的API调用,每次调用可以在30ms-40ms之间完成。

    对节点容器进行1万次的ping操作,并没有发现有延时现象。

    因此复现失败。

  2. 是否是由之前定位过的kubelet搜集获取memory.stat引起的呢?(详见案例1)

    用命令:

    eBay云计算“网”事:网络超时篇 6

    来计算读取memory.stat的消耗时间,大部分都超过了50ms。因为客户端的超时时间设置为100ms,而调用API的耗时在30-40ms,再加上这个消耗的50ms,是很可能导致超时的。于是执行drop cache的操作,很遗憾的是drop cache后,并没有让超时问题得到多少改善。

  3. 于是继续跑设计的eBPF工具,希望能查找到在主机的哪个位置产生了超时。

在抓取了超十万条数据记录后,用脚本对输出结果进行分析,根据输出条目的时间戳和数据包信息,过滤出在主机上有异常延时的数据包信息,如图5所示:

eBay云计算“网”事:网络超时篇 7

图5

图5中的第二列代表了当前处理数据包的network namespace,第三列代表当前数据包处理的端口,第四列显示了数据包信息,第五列显示了IPVS或者iptables对数据包的处理,第六列显示了处理softirq的进程信息,第七列显示了当前处理数据的CPU核,第八列显示了处理数据开始的时间戳,是系统的启动时间,单位为ns。

从抓取数据信息来看,有数据包从容器发出到主机端口发送,时间使用10865291752989502 – 10865291551167147 = 201822355ns, 也就是超过了200ms,主要的时间消耗在从第3步到第4步之间 ,从容器的network namespace到主机的network namespace,就超过10865291752980718 – 10865291551180388 = 201800330 (> 200ms)。

在分析了多个数据超时的数据包后,发现他们具有同样的模版,那就是在主机network namespace上处理veth pair端口过来数据包的CPU core,都是 32

通过top命令来查看该核的运行情况,发现该核的中断处理时间si会间歇性比较高,经常达到30%的使用率,而节点的load很低,整体CPU的使用率也不高。

eBay云计算“网”事:网络超时篇 8

如果没有基于eBPF的工具,而是通过类似排查问题1这样的定位手段,想要定位到这一步,是需要很长的时间的,我们可能会注意到32的si会稍微高点,但是很难和网络延时问题进行直接的关联。 而有了eBPF工具,通过抓取数据,很快就得到了这样的关键信息,这些信息对于解决问题可谓是至关重要。

接着通过perf,来查看下具体该核都在做什么事情,并生成火焰图(图6)。

eBay云计算“网”事:网络超时篇 9

图6

可以看到该核消耗了很大的一部分时间在处理estimation_timer。而si比较高,要么estimation_timer的中断次数很多,要么处理某个中断耗时很长。

先看中断次数是否很多,通过我们自己开发的小工具,从/proc/interrupts获取一段时间内该核的中断数量,结果显示该核上并没有很多timer中断数量,其他类型的中断也很少。

eBay云计算“网”事:网络超时篇 10

既然没有很多的中断,那么问题大概率是中断处理时间比较长。于是,我们对bcc的softirq 工具https://github.com/iovisor/bcc/blob/master/tools/softirqs.py 进行了修改,让它只统计CPU32 上不同类型的softirq耗时信息。在运行一段时间后,从输出结果中发现有timer的softirq执行时间在 262ms-524ms 之间。

eBay云计算“网”事:网络超时篇 11

从代码得知,estimation_timer是由ipvs模块进行注册的:

eBay云计算“网”事:网络超时篇 12

eBay云计算“网”事:网络超时篇 13

从estimation_timer的函数实现来看,它会调用spin_lock进行锁的操作,并且会查询每一条的ipvs rules进行相关操作。我们集群上的service比较多,因此在节点上,会存在很多的ipvs 规则,导致estimation_timer的执行需要消耗大量的时间。

但是为什么只有在核32上会出现问题呢?

通过ftrace,我们抓取了estimation_timer()的function_graph, 从图7的结果可以看到,estimation_timer()在很多的核上都被执行,但是只有在32核上执行的时候,消耗了很多的时间,其他核上消耗的时间都很少。

eBay云计算“网”事:网络超时篇 14

图7

在kube-proxy使用ipvs模式的节点上,只有主机的host network namespace才有很多的ipvs rules,而在容器的netowrk namespace里面,并没有ipvs rules存在。从现象来看,核32应该是被用来处理host network namespace的ipvs rules,而其他的核用来处理其它容器network namespace的ipvs rules,所以才会有这么大的差别。

那为什么核32被用来处理host network namespace,而不是其他的核呢?

从实验结果来看,该值是由加载ipvs 模块时候的核决定的,如果通过task_set来设定加载ipvs模块的核,那么会由该核来执行host network namespace的estimation_timer。

至此,我们已经知道了该问题的来龙去脉,解决方法主要是:

  • 短期内 通过live patch将estimation_timer的执行功能替换来解决线上的问题,目前我们暂时不需要estimation_timer对不同的链路进行速率等的统计,所以暂时将功能替换为不执行任何操作。
  • 在长期方案上 ,我们选择去除该timer,通过kernel thread来定期执行ipvs相关的链路速率、数据包等的统计功能,也就是来完成之前estimation_timer的工作。该方案目前还在进行更多详细的测试。

总结——网络超时篇

网络超时问题,关键还是在于找寻网络超时的时间点。如果可以找出这个时间点,就能快速缩小问题范围,也为最终解决问题提供一个正确有力的指导方向。这事情如同穿衣服,第一个纽扣对上了,后面的其他纽扣也就自然而然对上了。

从上面两个案例的定位方式对比来看, 抛弃手忙脚乱进行各种尝试,而是利用工具,来寻找第一个纽扣 ,是在复杂的Linux环境下,快速定位此类问题的关键方法。利用eBPF可以对内核进行更深入的剖析,让我们初步感受到了它的威力。因此我们也将用它来定位其他类型的问题,详情请关注后续的丢包篇和重传篇。

本文转载自公众号eBay技术荟(ID:eBayTechRecruiting)。

原文链接

https://mp.weixin.qq.com/s/ZUS94PMCKsqgZFHX9b99-g