记一次微信小程序页面加载慢的排查过程

发现

公司新上线了一个微信小程序,在测试环境以及小程序体验版上测试一切正常,但上线之后,页面加载尤其慢。

分析过程

1.生产日志

经过运维排查,所有的请求到达服务器后均在1s内处理完成并响应,偶尔有2-3s的请求,极少。

2.抓包

既然服务端处理请求没有问题,那么,加载可能出现在小程序本身或网络延迟,但后者可能性较低。于是,使用fiddler抓包,其中一个加载较慢的请求结果如下:

关键时间节点如下:

· 客户端与服务器完成tcp链接时间是11:31:35(时分秒)
· 客户端开始向服务端发送请求的时间是11:31:36(时分秒)
· 服务端接收到请求的时间是11:31:36(时分秒)
· 服务端开始响应的时间是11:31:46(时分秒)

也就是说,从服务器接收到请求到开始响应耗时10s,可这跟运维查看的日志结果不符!

3.使用curl分析http请求耗时

鉴于上面的抓包结果和生产日志结果相悖,决定使用curl对耗时较长的http请求进行分析。

curl -o /dev/null -s -w time_namelookup:"\t"%{time_namelookup}"\n"time_connect:"\t\t"%{time_connect}"\n"time_appconnect:"\t"%{time_appconnect}"\n"time_pretransfer:"\t"%{time_pretransfer}"\n"time_starttransfer:"\t"%{time_starttransfer}"\n"time_total:"\t\t"%{time_total}"\n"time_redirect:"\t\t"%{time_redirect}"\n" -X POST -d "token=b20f3cb4b62764e01530c2aca10a8c1c0b4a8a7269dab9a447ee05b6491d3d1b28da39d16f4a8b656c53e299ce6877588ae337627e7c2d5728232abb51ee0751c920bc40e2546a424402d811fa00e261877465e75301cfa3985594abb33afe8b6fecc583c89d1f398fb1b7eaee817b563996a54135705314d5a41508cc239203e5a4a433ae28f40681a6eea93066e78b0cbece901ff0d720e1965228955fca9939435de9902d31aa2421fce90d4748e78d6954448d3e5dcab1bcfaee28b2ac52faa7d57aa37363d7559943df2521c3a6&salesUser=27619" https://baoxian.xxxxxx.com/index.php/Jyxminiprogram/Sales4SalesUser/salesIndexCount

运行结果如下


对应的结果含义如下:

· time_namelookup :DNS 域名解析的时候,就是把 https://zhihu.com 转换成 ip 地址的过程
· time_connect :TCP 连接建立的时间,就是三次握手的时间
· time_appconnect :SSL/SSH 等上层协议建立连接的时间,比如 connect/handshake 的时间
· time_redirect :从开始到最后一个请求事务的时间
· time_pretransfer :从请求开始到响应开始传输的时间
· time_starttransfer :从请求开始到第一个字节将要传输的时间
· time_total :这次请求花费的全部时间

那么对应的时间点应该是:

· DNS解析耗时:0.005s
· TCP建立连接的耗时:0.035-0.005=0.03s
· SSL握手完成耗时:3.8-0.034=3.7s
· server处理数据的时间:3.8402-3.8401=0.0001s
· 总体的耗时:14.5s

emmm,按照这个结果来看,从服务器开始响应到传输完成一共耗时14.5-3.8=10.7s。
那么这里问题又来了,这结果跟fiddler的结果完全相反,到底是在哪个环节出了问题?

4.实时查看日志

fiddler的结果显示从服务器接收到请求到开始响应耗时10s,是服务器处理请求消耗了10s;而curl显示服务器处理请求只用了0.0001s,响应开始到结束耗时10.7s。到底哪个是对的,难道是根据本身有问题?
于是在跟运维同事一波交流之后,得到请求流转过程如下:

客户端<---------->CDN服务器<---------->Nginx代理<---------->应用服务器<---------->DB

弄清请求流转过程之后,手动发送请求,实时查看Nginx和应用服务器日志,发现请求发出后,间隔一段时间(10s左右)Nginx日志才有输出,接着很快App Server日志也有输出(包括请求和响应)。事实就摆在眼前,是CDN服务器<---------->Nginx代理之间出现了问题,具体是为什么目前还不清楚。
那么fiddler和curl抓包的结果如何解释?
fiddler:从服务器接收到请求到开始响应耗时10s,是正确的。
curl:服务器处理请求只用了0.0001s,响应开始到结束耗时10.7s。这里就有问题了,要想解释得通,只能说time_pretransfer和time_starttransfer是CDN服务器的响应时间,由于配置了CND,在向小程序应用服务器发送请求时,会先请求到CDN服务器此时CDN服务器很快就响应了客户端的请求,但CDN服务器在转发请求到Nginx代理时出现了延迟,因此在curl的请求结果中才会看起来像是响应开始到响应结束耗时较长。

最后

至于为什么请求从CND服务器到应用服务器会出现延迟,目前还没有结论。待更新

参考

http://blog.51cto.com/h2ofly/1957171
http://developer.51cto.com/art/201704/536923.htm?foxhandler=RssReadRenderProcessHandler

推荐阅读更多精彩内容