大流量压测下TCP连接未复用导致的大量报错问题排查过程

·  阅读 1415
大流量压测下TCP连接未复用导致的大量报错问题排查过程

1. 问题背景

在进行业务多活的压测过程中,经常出现很诡异的周期性的请求大量异常的问题,现象就是在压测的一个长周期内(eg: 10分钟),会定期(1分钟)的出现请求大量报错的情况,并且随着流量的增加,问题出现的概率和持续的时间也会增加很多,在整个EN多活压测的期间内,经常出现,一度在多个方向上怀疑排查,但都无果,困扰了很久,如下图

image-20220119211917144

在解决这个问题的时候由于经验的缺乏,绕了很多的路,一开始在很多方向上做过怀疑,都被一一排除,最终找到了真正的问题所在

1.1 总结问题现象:

从图上看,在压测期间,一开始的流量和请求时长和异常数都很正常,但是在经过一分钟后就会出现大量的请求ERROR,但是平均请求耗时缺很正常。

1.2 压测背景:

大家可以先了解下我们整个的压测部署或者说是流量图,最开始由压测平台发起压测任务,然后调度压测肉鸡集群发起压测,最终将流量打到我们应用前面的SLB和NGINX,最终导到我们应用。

为什么会画两个一模一样的图,是因为我们的这次压测是基于多云多活的为了让大家更加了解我们多云多活的基本架构是怎么样的,所以给大家画出来(备注:真正的多云细节比这个多很多)

image-20220119211156153

2. 排查过程

  1. 当发现问题的时候,第一时间怀疑是不是后台应用集群压力过大,在一大波流量轰炸后,服务器顶不住出现的问题。所以立即去查看APM监控,果然发现了一些嫌疑

    在压测的期间内,有一段时间服务器是没有处理请求的,看起来处于空闲的时间,对比时间点和压测结果显示的异常时间点刚好对应上

    image-20220119212150962

  2. 通过第一步的排查,我下意识觉得应该是应用服务器有问题了,感觉有点像是full gc的感觉,应用在运行一段时间后,内存压力过大,进行full gc,全世界停止了,但是也有点奇怪,理论上gc的时候会影响请求的时长的,为什么整体的耗时很稳定并没有超时的出现,不管了先APM查看下,线程数也比较正常

    尴尬了,内存,CPU一切正常,根本没有full gc

    image-20220119213003873

  3. 既然如此,那也没有别的好说的了,那就祭出线程分析大法,我们直接dump出压测报错期间的线程堆栈看下看下到底线程都在干嘛

    jsatck -l pid > benchmark-2022-01-23-01.stack

    推荐一个非常好用的线程堆栈分析的工具(perfma出品):thread.console.heapdump.cn/detail/3281…

    可以看到几乎没有http在运行的线程,所有的http线程此时都在等待新的请求,都处于空闲状态

    结论:服务器是真的闲,证明流量真的没有打到后端实例

    image-20220123201958666

    image-20220123202142952

    image-20220123202210481

  4. 那其实这个时刻我的排查思路点就只剩下肉鸡nginx(一层和二层)

    我们对照下流量图

    image-20220123202841725

    image-20220123203352035

​ 其实从对比压测流量和nginx流量图就可以看到其实nginx端在压测显示报错的那个时间点QPS是有大幅度降低的,也就证明了其实流量确实是没有了。OK,那问题出在哪里其实很显而易见了,就剩下肉鸡了

  1. 但是对于肉鸡(jmter集群)了解的不多仅限于对jmter会用而已,那到了这个时间点也没有别的更好的方式了。就拿张师傅和我沟通问题最多的一句话“抓包了没有,抓个包吧”。哈哈哈哈,真的是绝招,果然发现问题了,在肉鸡上抓包如下

    大量的TCP Port numbers reused

    image-20220123204059620

  2. 看到这块的时候就恍然大悟了,这不就是端口不够用嘛,再次通过端口的监控确认下,果然有大量的TIME_WAIT 状态连接,而且端口的使用量非常大,很明显在请求耗时不高的情况,还有这么大的端口使用量,肯定是端口没有复用的问题

    netstat -an|awk '/tcp/ {print $6}'|sort|uniq -c : 查看tcp每个状态的连接的数量

    image-20220123204632836

    我们查看下端口开放范围 32768 ~ 60999 差不多就是28000多个端口(通过cat /proc/sys/net/ipv4/tcp_fin_timeout查看),这个也就是为什么我们压测的时候老是会出现请求异常的问题,因为TCP的端口不够用,导致出现了 TCP Port numbers reused

    image-20220123210657802

    接下来我们分析下为什么会出现有TCP Port numbers reused 不够的情况,其实没有端口用就是之前的连接没有被及时释放,要理解这个必须要清楚 TCP四次挥手的过程

    盗用张师傅的小册的图

    image-20220123211206863

    通过上图我们很容易的看清楚,TIME_WAIT 状态主要出现在主动关闭连接的一方,也就是当客户端收到服务端发给它的第二个FIN包之后自动进入TIME_WAIT 状态,然后等2个MSL之后自动关闭 ,我们压测肉机上的MSL为60秒,通过cat /proc/sys/net/ipv4/tcp_fin_timeout 命令可查看

    • 什么是 MSL ?
      • - MSL 全称是 maximum segment lifetime,报文最大生存时间
      • - MSL 是任何 IP 数据报能够在网络内存活的最长时间,超过这个时间报文将被丢弃,服务器可以设置
      • - MSL 的具体值通常为 30 秒或者是 2 分钟
      • 为什么需要TIME_WAIT
        • 优雅的关闭TCP连接,也就是尽量保证被动关闭的一端收到它自己发出去的FIN报文的ACK确认报文;
        • 处理延迟的重复报文,这主要是为了避免前后两个使用相同四元组的连接中的前一个连接的报文干扰后一个连接。
      • image-20220123212001839
  3. OK,那要解决端口不够用的问题的话,很简单的方式就是扩大端口使用范围,但其实在我们压测的很大的流量,再多的端口都有被用光的那一刻,只不过是稍微晚一点而已,显然解决不了问题。

    那么除了这个之外, 我们还可以通过开启 tcp_tw_reuse参数 达到让处于TIME_WAIT 状态的连接可以被复用 , 但其实也有一定的等待时间,并不是一下子就提高性能,另外tcp_tw_reuse还定义了一个新的TCP选项–两个四字节的timestamp fields时间戳字段,第一个是TCP发送方的当前时钟时间戳,而第二个是从远程主机接收到的最新时间戳。通过时间戳的比对确定是否可以对连接进行复用和报文的顺序

  4. 其实仔细想下,这个问题应该主要还是jmter发请求的时候应该没有对连接进行复用导致的,联系了下压测平台的同事,简单将抓包请求和tcp连接状态的图发给他之后,他立马就意识到了jmter发请求的没有复用的点,通过下面的调整后就OK了wecom-temp-3fbc7d843561521a8cab453cbad9d7c4

3. 解决问题:

如上图:jmeter客户端实现方式有三种,一种是java,一种是httpclient4, jmter默认就是httpClient4,我们来看一下java与httpclient4的区别:

Java:选择压测时,链接是复用的(代码中的http调用都加了连接池)

httpclient4:压测时,每请求一次都创建一个新的链接,(jmeter5.0以前默认关闭了连接复用,5.0上是打开的:即每请求一次都会创建一个新的链接)

所以httpclient4 在连接复用设置打开的情况下,压测结果与java的是不一样的,因为java复用链接,httpclient4每次连接都会重新建立tcp连接,如果httpclient4吞吐量过低,需要考虑网络带宽的限制

java实现适合压榨性测试,httpclient4适合真实场景的模拟

下面是切换为 java实现的压测效果图,可以看到压测数据很平稳,也没有报错, 肉鸡实例上也没有很多TIME_OUT 的连接

image-20220123235154285

image-20220123235121027

4. 总结

其实这个问题本身很简单,很多大佬或者有经验的同学,可能一眼就看到问题所在,不过我觉得还是有必要将这个分享出来,因为在真实环境下,整个业务系统是很复杂的,从用户发起请求到服务端最后接收,可能中间过了好多个组件,每一个可能都成为系统的瓶颈,我们其实要有清晰的思路,对整个流量走向要有了然于胸,这样就算没有经验,也可以从一点一点的排除,最终找到问题所在

其次,强烈推荐挖坑的张师傅的小册 深入理解TCP协议:从原理到实战,这个小册真的很nice,之前学过这个小册子,这次的排查过程很多东西才显得那么容易

分类:
后端
分类:
后端
收藏成功!
已添加到「」, 点击更改