当ATS遇上curl: 记ATS的一次故障排查经历

不是最近懒了不写blog,而是每天到家都10点以后了,实在累得没力气。

这周花了很多时间排查一个bug。我刚做了一项架构升级,把某个项目所用的http server换成了ATS。这种小破事儿按理说1-2天就可以完成,结果耗费了我3-4周。

我把http server替换成ATS后,放在线上用真实流量一跑,发现性能跟不上。大部分请求(超过70%)都因为处理超时而返回5xx类型的错误。而我把压力降低到每秒只有50-100个请求,情况还是如此。

在我们这套系统的架构中,ATS后面还有一个后端服务器,ATS主要充当的是反向代理的作用。

client <-------> ATS <-------> 后端

而经线上测试发现,从client到ATS之间有1万多个已建立(established)的TCP连接,从ATS到后端之间也是。这是极不正常的。因为我们每秒的请求数很低啊!!!!

在我们的设计中,ATS和后端之间是短连接,它每收到一个请求都会去连后端,用完后关闭。我第一个反应是,会不会是ATS用完这个连接之后没有关??

我给后端的服务进程加了些日志,让它每关闭一条连接都打一条日志。发现,情况并非如此。基本上每秒新建多少就关闭多少,大体上相等。而且,我在测试环境中,用curl把真实的线上请求一条条的发给ATS做测试,也没有发现问题。连接在处理完后被立即断掉了。可见这块代码没什么问题。

我认为,既然后端收到了tcp close请求,那么依然存在这么多已建立连接只有一个可能:后端处理太慢。

为了验证我的想法,我用netstat查ATS和后端之间已建立的连接有哪些,随便挑一个,然后用lsof找出它的文件描述符(fd),然后去/proc下找到这个fd,就能看到这个连接是什么时候建立的。发现大部分连接都持续了3-5分钟以上。顿时释然。这也就解释了为什么会有几万个连接。

于是我继续找瓶颈。很遗憾的是,disk io几乎没有。ATS和后端是处于同一台机器上,走lo接口,所以网络瓶颈不存在。于是我猜是CPU。因为我看见负载飘动在10-20之间。kernel的event进程经常被唤醒,占用了大量CPU。但是这我没法整,我主要看用户态的代码哪里有问题。每秒才几十个HTTP请求,瓶颈怎么也不能出在kernel的TCP栈上,对吧?

于是我用perf继续查,然后发现后端的服务器在管理已建立的连接的时候,没有用map,而用了链表std::list。而且,由于后端采用的是多线程的代码,所以多个线程会同时抢这一把锁,并且遍历这个list。而且,std::list的remove方法与众不同,它不是找到匹配的删除后就return,而是无论如何都要遍历完这个链表。并且,perf的结果表明,用户态的代码主要的CPU都耗费在了这里。

我很想找一个无锁化的hash map,可惜没有现成的。leveldb里的skiplist只能增加不能删除,也不能满足我的需求。tbb的hashmap也有硬伤,不能用在这个场景上。所以我就还是用mutex+std::unordered_map。改完代码,再测试,问题依旧。虽然CPU降下来许多,但是处理依然超时。

接着,我调整了下tcp的sysctl参数。增加窗口大小。发现负载降下来了,但是处理依然超时。

然后我继续给后端服务器加代码,让它把处理的各个阶段都打印出来。我认为一般来说,一个请求的处理无非就是这么几个阶段:

  1. accept new connection
  2. recv request
  3. process request
  4. send response
  5. close connection

我把它们的时间点全打印出来,就知道慢在哪了。

结果很出人意料,服务器处理很快,慢在了网络收发上。这让我崩溃坏了。同一个机器内,每秒不到100个请求,走loopback接口,怎么会慢呢!!我每个请求最多也就1-2K字节啊!!

既然是网络的问题,那就抓包来解决。

我用tcpdump去抓包,发现一个很有趣的现象,在tcp三次握手完毕后,ATS并没有立即发送HTTP Request给后端,而是等了4-5秒之后才发。但不是所有的请求都是这样。有的立即发了,有的要等很久。这样我很郁闷,难道是ATS内部在处理事件的时候有问题?

而且我通过检查代码发现,ATS是在接到来自client的accept请求之后,就立马去连接后端。但是是在收完一个完整的http request之后,才把它发给后端。于是我想,问题是不是出在client和ATS之间的连接上了。

于是我继续抓包。结果发现,确实是这样。ATS要花费4-5秒来接收一个HTTP请求。

最后发现,这是因为client发来的请求中的header中带一个叫做Expect":"100-continue"的东西……服务器收到后要立即返回100,这样它才会把后续的body立即发过来。否则它会一直等着,一直等到timeout之后再发……

最终的解决办法:在ATS的配置文件records.config中加上

CONFIG proxy.config.http.send_100_continue_response INT 1

问题全解决了……

此博客中的热门博文

在windows下使用llvm+clang

少写代码,多读别人写的代码

tensorflow distributed runtime初窥