问题场景

在新采购的服务器一切环境搭建完毕之后并做了项目迁移,经过测试发现单个页面打开非常慢,耗时竟然长达2.2-2.4s(ps:一般超出300毫秒用户就会产生明显感知),下面是整个追查过程的分析记录:

前言:排查维度 & 涉及知识点:

1、排查维度
1.1、排查用户请求 -> HA,确认HA是否有问题
1.2、排查用户请求 -> 业务机器环节耗时
1.3、排查业务机器 -> 数据库服务器环节耗时
2、涉及知识点
2.1、haproxy
2.2、tcp 通信的三次握手
2.3、tcpdump 抓包工具的使用
2.4、tcpdump 包内容的反思
2.5、mysql 长短连接的请求对比和追查方法

一、接收到信息后首先确认问题.

1.1 项目全貌分析,针对技术框架大体分析
通过分析看到这个项目是一个类似底层用的TP框架编写的。 项目框架CLTPHP5.6 版本.
1.2 参数量化,确定项目整体响应时间.
项目打开很慢,技术应该用可量化的参数说话,所有的框架想知道具体耗时,只需要进行时间打点即可,此问题也不例外,
看到是成熟框架后,简单看了下框架底层,可以开启DEBUG 模式,有框架耗时打点可以直接在Trace中展示。

haoshi.png
看到这简单的一个列表页,这个耗时,2.09s 确实有点慢,这里完全可以借助trace信息进行直接查看耗时情况,但是如果有的框架没有收集trace信息呢? 文章的思路来剖析如何分析解决这类问题.

二、Haproxy 负载配置文件追查,看有无设置导致延时## 

2.1 以下设置就是一个很简单的IP负载到单台机器上,很简单的设置,无复杂逻辑,此环节跳过。PS: 我怀疑此处有复杂的逻辑处理导致耗时,检查后排除此因素.

haproxy_conf.png

三、网络通信检查 ping ## 

为什么做这一步呢?
PS:因为要排除网络开销,比如跨机房、异地等之间访问,有网络延时,网络不稳定等,要快速确认是否因为网络损耗导致的.
跳过Haproxy 直接单台机器检查,先进行ping,看是否网络延时过大,从图中看到单次探测还是比较短暂,而且返回耗时均匀.

ping.png

四、网络TCP 排查

4.1、抓包整体网络请求图概览

接下来抓包分析单次请求到底发生了什么?耗时的环节是在什么阶段呢?带着问题继续前进.
客户机器IP : 192.168.0.106 (我本机IP)
目标机器IP : 103.45.100.66 <---> dev.manager.subway.com 对应域名

使用命令:

sudo tcpdump -i en1 -s 0 -c 100 host 103.45.100.66

tcpdump.png
通过上面抓包截图有心的朋友已经发现问题所在了,服务器端往返客户端通信过程中有一个包传输耗费时间 > 2s, 我们应该感知耗时原因就是服务端到客户端数据传输过程中导致.

PS题外话:这里先说下tcpdump 这个工具,后面再具体分析这2s出现在哪里,这块主要给之前没了解过tcpdump工具的伙伴一个参考,熟悉的可以略过 4.2 段

4.2 Tcpdump 工具使用 & 上图内容解读

tcpdump 命令需要单独安装.上图用抓包命令用到的参数含义如下:
-i en1 :  监听网卡
-s 0   :  默认字节数有限,通过设置来打印全包内容.
-c 100 :  打印出近100条请求包数据,(搞多了也没用,当然数据量大了最好定位到文件中再分析)
host   :  指定IP进行监听

针对返回的包内容, 需要大体知道看出几个关键属性,
第一段(时间):17:25:30.080849 
第二段(请求顺序)IP 192.168.0.106.50722 > dev.manager.hzxinquanzi.com.http: 
第三段(状态标识) Flags [S], 
第四段(包数据详情) seq 899878170, win 65535, options [mss 1460,nop,wscale 6,nop,nop,TS val 847812066 ecr 0,sackOK,eol], length 0

这里主要看第三段,这个状态标识这里用了 ”缩写“,这个标识在手册中有详细描述。

用命令 man tcpdump 来查看手册,截图如下
tcpdump_flag.png

4.3 TCP 协议通信

PS: 想搞清楚抓包内容的含义,需要熟悉TCP通信原理。下面一起来熟悉下TCP 的通信过程。

seq_ack.png

上图是一个TCP 通信三次握手的过程图。

PS:白话解说,例子(A男和B女相亲),A男代表客户端 B女代表服务端。在这个场景下,A男比较主动,过程开始了。

第一次握手: A男 发起 (SNY=1 Seq=x) PS:(男士说我喜欢你,想和你见面聊聊)
第二次握手: B女 回复 (SNY=1,Ack=1,Seq=y,Ack=x+1) PS:(女士回复,那你来吧,见面聊聊)
第三次握手: A男 收到后回复 (ACK=1,Seq=x+1,ack=y+1)PS:(男士回复,我收到你的回复了,那我来了哈)
这里可能会有小伙伴们问,为什么是三次握手,不是四次握手? 我只能告诉你,A男已迫不及待见面了,协议最初的设计者排除了"仙人跳"的环节. 哈哈~ , 通过调侃修辞希望看的伙伴对这个过程记忆更深刻些哈~

通过上面流程图片和注解,我想读者伙伴应该对这个握手环节已经清晰了,握手之后那就是真正的数据开始往返传输通信,那接下来一起分析下,上面抓包的图里面的每一行的具体细节信息。

五、2秒的耗时排查

把之前tcpdump 抓到的包截图拿过来,再仔细分析。
tcpdump_info.png

5.1 文字描述一下包内容通信的过程
1、第一行 客户端IP后三位 .106,发起握手请求 SNY包,通信标识[s]可以确认,时间 17:25:30.080849,Seq=170(注*代表缩写,具体看截图)
2、第二行 服务端响应,域名->客户端IP .106,回复SNY包,ACK包,通信标识[s.] ACK=171,时间 17:25:30.104924
3、第三行 客户端IP后三位 *.106 发起确认收到请求ACK=1,时间 17:25:30.104994
4、第四行 客户端IP后三位 *.106 开始数据传输, 通信标识[P.] 时间 17:25:30.105153
通过以上阶段中,从握手开始到数据传输整体的时间是 17:25:30.080849 -- 17:25:30.105153,大家可以看到耗时非常短暂可以忽略了.
5、第五行、第六行 大家可以看到是从服务端响应客户端的请求,把数据返回过来,时间 17:25:32.189211,这个地方大家看一下哈,第六行返回的时间再秒单位上直接跳了2秒之多,(PS:从时间微妙上特征上看到,这哥们读了个211才来的,哈~) 通过这次请求我们就可以确认了,整个耗时在服务端了。

5.2 猜测服务端耗时原因

到目前情况已经得知,整个过程是服务端响应耗时比较久,那到底服务端做了什么呢?
有经验的伙伴可以猜测下几种情况导致耗时:
1. 重度逻辑
2. 严重IO
3. 服务器负载过高
4. 依赖第三方资源问题(Mysql、Redis、CURL请求等)

排除选项 1 的理由: 简单的后台系统列表页,不应该有重度逻辑,也代码简单确认了,予以排除
排除选项 2、3 的理由: 通过top 命令查看确认了下IO和负载都很低,予以排除
排除选项 4 的理由: 这块从代码层面也看了下直接查询数据库,并没有第三方请求,并且没有使用Redis, 这个环节应该可以猜到问题可能出现在数据库的请求上。

5.3 数据库请求猜测验证

通过前面追查的方法,如法炮制,一步步再深入探索,先大胆猜测,可能出现的问题,逐个排除.
出现了数据库请求返回慢的情况猜测有如下可能性:

1、网络开销,异地跨机房网络开销
2、数据库所在服务器机器可能存在IO过高
3、数据库所在服务器机器可能存在高负载
4、服务器硬件出现问题
5、单独编写一个数据库请求查询,打点看时间耗时,确认单次查询花费时间

针对上面猜测的这么多种情况逐一排除:

排除选项 1 的理由,我朋友说通过ping,没错,这块咱们需要通过ping 来确认。
(PS: ping 很简单的命令,但是作用很大,可以测试项目所在服务器到数据库服务器的网络请求耗时,ping 时间长一些,可以能通过返回的数据来确认网络是否稳定,这些都可以排查)
ping_db.png
看到上面截图的时候,我朋友在旁边说了: “你看没问题啊,请求只有 40ms 很短暂,肯定不是mysql出问题了”。这个地方大家注意ping 耗时很短不代表执行时间会短,这块还需要继续往下排查,此处仅代表网络损耗不大.

排除选项 2、3 的理由,登录到数据库服务器通过top查看发现IO 和 负载都非常低,可以予以排除.
排除选项 4 的理由,可以查看linux 机器异常的系统日志,也没有发现异常。
排除选项 5 的理由,单独写了测试用例测试了单次mysql 查询列表耗时,仅有短暂的几十ms。

排查到这里的时候,朋友说:“肯定不是msyql问题,你看执行很快呀,单次执行打点的耗时也只有几十ms”。

大家要注意了,代码的执行是流程式顺序执行的,单次执行会很快,那如果多执行几次呢?那时间不就累加上去了么。大家都知道一次数据库操作的过程包含 连接数据库 -> 执行数据库命令 -> 关闭数据库。但经常为了节省开销,我们一贯做法就是省掉第一过程 和 第三过程。需要时执行命令即可,于是引入了长链接的机制。

有了上面的分析,再次通过抓包形式来确认下猜测,依然使用tcpdump,(PS:这个图后来补的)
tcpdump_db.png
我们来分析下上面抓包的情况,业务机器
客户端机器:(业务机器) 4-project
服务端机器:(数据库服务器) 2-dbmain

我们来看一下,三行发起的是一个TCP的三次握手请求,这个阶段在43ms左右,这个地方 和 ping 的结果相近属于正常.
时间点 41:27.010338 客户端发起->服务端
时间点 41:27.053041 服务端回复->客户端
时间点 41:27.053131 客户端再次回复->服务端
在接下里来的后面的数据出现批量的往返传输
时间点 41:27.320288 再次开始进行请求连接,继而下一个时间点是在41:27.541078 这图中的请求以及数据传输代表了个整体包的执行耗时。
因为版面有限,只截图了一部分。当时的表现形式是,刷新一次页面后,通信中出现大批量的往返。含义代表一次页面刷新,多次数据连接、执行等操作,具体我们还需要再次确认。

带着上面的猜测再次查看代码,并打印了个log,就执行一个列表的情况下,产生了很多额外的请求,从中拷贝了部分执行的sql信息如下,整体执行篇幅就这样代码有大约七八次,这里面大家要知道,每一行可都是一次请求呀,都是有耗时的。

mysql:host=2-dbmain;port=3306;dbname=subway_v1;charset=utf8
SHOW COLUMNS FROM `df_field`
SELECT * FROM `df_field` WHERE ( moduleid=1 ) ORDER BY `sort`
mysql:host=2-dbmain;port=3306;dbname=subway_v1;charset=utf8
SELECT * FROM `df_field` WHERE ( moduleid=2 ) ORDER BY `sort`
mysql:host=2-dbmain;port=3306;dbname=subway_v1;charset=utf8
SELECT * FROM `df_field` WHERE ( moduleid=3 ) ORDER BY `sort`
SELECT VERSION() AS ver

看到这里都表示不敢相信。
这块的时间上单词执行的环节分为如下:
1.连接开关在40-50ms
2.数据sql命令执行show一次
3.select 一次
整体耗时在200多毫秒,这样整体算下来执行多次我时间上就可观了.

当然可以通过绕过上面的trace信息,进行通过linux命令快速确认mysql连接的状态是什么情况呢?
在业务服务器上执行命令:

netstat -an | grep 3306

截图如下:
netstat_mysql.png

我们看到与mysql 链接的状态都是 TIME_WAIT, 明显没有开启长链接,如果是长链接开启,状态是 ESTABLISH,并且统计了下ESTABLISH 的数量,返回结果也是0。由此断定为非长链接。

看到这里我们应该明白了,整体的耗时是产生在数据库执行阶段。
1、大批量mysql 打开链接 耗时
2、单功能操作执行了批量sql耗时

接下来建议修复的点即为:

  1. 开启mysql 长链接
  2. 把相同功能模块的执行放在一次进行请求,把返回数据放在PHP中进行处理,批量循环sql处理

以上整体虽然我们看到数据库的ping 的时间为40毫秒,但此40毫秒非彼40毫秒啊。

六、总结反思

在项目的开发过程中,事无巨细不可称其圆。一个小疏忽可能导致整个项目质量呈指数趋势下降。这警示我们在开发的过程中需要考虑周全,做事周详,大处着眼,小处着手,仔细揣摩,用心开发。