剖析页面耗时思路解析

## 问题场景

在新采购的服务器一切环境搭建完毕之后并做了项目迁移，经过测试发现单个页面打开非常慢，耗时竟然长达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][1]
看到这简单的一个列表页，这个耗时，2.09s 确实有点慢，这里完全可以借助trace信息进行直接查看耗时情况，但是如果有的框架没有收集trace信息呢？ 文章的思路来剖析如何分析解决这类问题.

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

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

![haproxy_conf.png][2]

## 三、网络通信检查 ping ##

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

![ping.png][3]
   
## 四、网络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][4]
通过上面抓包截图有心的朋友已经发现问题所在了，服务器端往返客户端通信过程中有一个包传输耗费时间 > 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][6]

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

![seq_ack.png][5]

上图是一个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][7]

**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][8]
看到上面截图的时候，我朋友在旁边说了: “你看没问题啊，请求只有 40ms 很短暂，肯定不是mysql出问题了”。这个地方大家注意ping 耗时很短不代表执行时间会短，这块还需要继续往下排查,此处仅代表网络损耗不大.

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

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

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

有了上面的分析，再次通过抓包形式来确认下猜测,依然使用tcpdump，（PS:这个图后来补的）
![tcpdump_db.png][9]
我们来分析下上面抓包的情况,业务机器
客户端机器:(业务机器)     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][10]

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

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

接下来建议修复的点即为：
1. 开启mysql 长链接
2. 把相同功能模块的执行放在一次进行请求，把返回数据放在PHP中进行处理，批量循环sql处理

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

六、总结反思

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

[1]: http://blogimg.bravedu.com/2019/7/14/haoshi.jpg
  [2]: http://blogimg.bravedu.com/2019/7/14/haproxy_conf.png
  [3]: http://blogimg.bravedu.com/2019/7/14/ping.png
  [4]: http://blogimg.bravedu.com/2019/7/14/tcpdump.png
  [5]: http://blogimg.bravedu.com/2019/7/14/seq_ack.png
  [6]: http://blogimg.bravedu.com/2019/7/14/tcpdump_flag.jpg
  [7]: http://blogimg.bravedu.com/2019/7/14/tcpdump_info.jpg
  [8]: http://blogimg.bravedu.com/2019/7/14/ping_db.png
  [9]: http://blogimg.bravedu.com/2019/7/14/tcpdump_db.png
  [10]: http://blogimg.bravedu.com/2019/7/14/netstat_mysql.png

BraveDu

剖析页面耗时思路解析

您可以选择一种方式赞助本站

发表评论