表现在499上的一个长耗时问题

声明：走过的大罗神仙请多斧正，路过的小猿也请多多指教。如果不正不实之处，请多多拍砖。

背景：

两周前，发生在我们组内的一件事情。新服务上线后的各种不稳定问题，常常需要追查问题原因以做优化。本文描述case表现为服务稳定性指标出现几分钟的尖刺。其实，一段时间以来这样的尖刺问题有过几次。由于，迅速就要去处理其他高优的事情，或者另一个紧急的事情就盖了过来。一直没有腾出时间将这类问题跟进到底。希望本文能够记录下来通常大家排查问题的经验推断（比如，硬盘，网络，CPU等）还是有道理的。

问题：

一个时间点，我们的稳定性突然下跌，几分钟后又快速回升。一个小时，或者几个小时整体来看：稳定性线条出现几分钟的尖刺，或者叫抖动。

本文稳定性指标表达一定程度上服务非正常可用的情形。稳定性指标这里定义为服务请求中status=200次数占比服务总体请求次数。

稳定性指标： stability=(COUNT(status=200))/COUNT

这时就聚合统计看到引起稳定性跌落的非200错误码大量集中在499上面，客户端主动断开连接。

问题：我们服务响应超过等待时间，客户端主动断开连接，Nginx状态码499。

参考统计命令：

grep -Po 'status=[^2]\d+' log/access_log sort uniq -c

场景：

服务背景，这里不多介绍。简要说明为客户端提供服务的Nginx+PHP（O）上游仍有一层Nginx+PHP服务（A）为之提供计算。客户端主动断开，Nginx返回499，但是PHP仍继续执行，PHP所调用的上游服务继续正常执行。故而，此时看到上游A服务Nginx中并未出现大量非200错误码。

（图1）app服务O和A结构图

那么，出现问题的那几分钟，究竟哪里出现了长耗时？导致超过了客户端的接受时间。整体链路上，我们开始查找各个环节的关键日志以及寻找线索。

追溯：

前提要明白，只有我们php代码拖Nginx的后腿的份儿哈。（Nginx的性能，以及Nginx和PHP原理不是我们今天讨论的范围，就不再展开。）所以，拿几条499请求，直接从上到下的排查线索。

经过一顿翻查O服务和A服务hhvm日志中，php运行时打印日志，各处耗时并未发现明显长耗时情况。

单单只在Nginx日志中显示cost几百毫秒，对比hhvm-access.log中cost只有十几ms。（如上图截取日志）access_log中确实cost=0.250。时间不在php处理上面，时间消耗在哪儿了？PHP之后Nginx又干啥了？？

在翻查各种日志查找有无其他异常情况时，又发现有时候会有如下日志：

(an upstream response is buffered to a temporary file 。。。while reading upstream。。)

这又是什么鬼？也不知道有没有联系？

陷入了困境：说不清楚自己遇到了什么困难，但是停止了前行的脚步。（反过头来说这里，我们没办法说明我们对未知的东西知道多少。所以，我们往往说不清楚困难是什么。）

于是，两个人兵分两路去请教其他人。（这里，2个人并没有约定，只是过了一会儿，不约而同的发现步调神奇的一致）

求助：

一方面，笔者抱着上面的日志，同时不知道怎么描述自己问题的混沌状态，找到了一个神秘人。就在聊天框框里不知所云的叨叨着。Nginx拿到PHP返回后又干啥了？我们这里有几分钟请求发生了好多长这样儿的。。。Nginx错误日志里面的写临时文件的是啥意思啊？看起来它们也不是相同请求的日志，到底有关系么？（好烦躁）

Nginx有将内容写入buffer的动作，没有其他动作，直接响应客户端。一般来讲，这里的写buffer不会出现太多耗时，如果php没问题，机器IO正常，就基本还好。上面upstream to buffered的相关Nginx参数的影响可以忽略。【fastcgi_buffering，fastcgi_cache可以参考官方资料了解其标准含义】（那个鬼可以忽略。嘻嘻，同时神秘人也帮补充了2个nginx参数的知识。）

这时，另一个小朋友小懒同学发来贺电：来自17哥的帮助，提供新的线索，也顺便给了结论：Nginx返回客户端网络传输耗时。

好尴尬，为啥，凭啥？小懒同学放学别走，请你说清楚：

Nginx日志里面还有一个时间被我们忽略了（好吧，我们压根儿就不知道这个变量的存在）fastcgi处理结束时间，应该叫upstream响应结束时间：$upstream_response_time 在上述日志截图中，那个伟大的0.009

再一次把目标缩小到了Nginx和CGI交互以及Nginx和Client交互时间。

于此同时，小懒同学大量聚合A服务当时的日志分析得到，cost-$upstream_response_time时间差200ms的请求量占长耗时300ms请求量的比重很大。进一步推进原因可能就是网络发生了问题。

参考统计命令：

//这一时段的所有请求的2个关键数字摘出来

//根据日志顺序$3:（$upstre__ time）$1: cost=（）

grep ' 2017:15:0 ' log/access_log awk -F " " ''awk -F "=" ''awk -F " " '' // 转毫秒

//基于上述，cost=300ms以上的请求数量X，并且2个差值大于200ms的请求数量Y，看Y占X多少

X = awk ''

Y=awk ''awk ''awk '{ if($1>200) n++} END { print n }'

//Y占的越多，网络传输原因的占比就越多。

那原因能再具体点儿么？网络传输上：接收方，发送方？哪里的问题？

结局：

不省心的两个死孩子，终于还是来到了大神面前，耽误大神几分钟。Nginx读取完毕php返回的响应数据后，同时写入内存buffer（不够则写临时文件）。完成后可以断开与php的连接，一方面释放了php连接资源；一方面减少同时维护2个连接的时间提高效率。此时$upstream_response_time时间点。之后，将buffer内数据返回给客户端Client，此时的Client也可能是前面的负载Nginx。

（图2）分段看时间范围

那么，原因很明确了，Nginx返回客户端的网络传输过程消耗时间。同时，大神顺便带我们看发送方和接收方分别的网络IO监控图。对比发现，Nginx的客户端，也就是前面一层Nginx的网卡直接打满了。它尖刺的时间和本文开篇提到的稳定性下跌的尖刺时间神奇的吻合；网络重传次数突增之后回到0，尖刺时间神奇的一致。

（哈哈，绿色围墙，贴图犯法）

写在最后：本文以记事的形式，希望阐述发生耗时问题排查的大概方法以及涉及知识点的补充方式。我们目前还没有足够的内力深入分析系统的原理，也没有牛逼的技术去分辨架构设计等方面。故而，文中一些基础系统和框架的原理不做过多分析。毕竟也还在学习的路上，只觉越来越不敢说熟悉和明白。