表现在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,尖刺时间神奇的一致。

(哈哈,绿色围墙,贴图犯法)

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

  • 发表于:
  • 原文链接:http://kuaibao.qq.com/s/20180107G09OPD00?refer=cp_1026

扫码关注云+社区