对HTTP请求接口资源下载时间过长的问题分析
问题描述
我司某产品线有指定业务接口customQuery在线上环境中,与首页一起打开时下载数据的时间明显过长(平均可以达到2s)
注:
- “与首页一起打开” 的含义是指用户进入WEB系统后会首次加载的主页面,该主页会提前请求customQuery数据,以用于显示首页中的列表数据。
- 正常的想法会第一时间认为是刚进入首页请求多,导致的下载速度慢,这个自然不是这个原因,要不然也不会专门写这些内容,后面会讲到。
- 下文中我会尽量仅针对问题本身,不掺杂业务逻辑进行表述,并尽可能的做到描述清晰,准确。不过个人表达力及知识储备难免会有盲区,下文如有描述不当或有事实错误的地方,希望大家可以直接悉心指出。
- 这里需要单独说明下因为之前已经发过一篇关于customQuery请求gzip压缩的帖子,而这里讲的是2个没有关系的东西,不用联系在一起。
先直接上问题请求的截图
如上图323K的数据下载用了近2s,明显是出问题了。
该接口有在数据翻页时也会触发,不过下载时间表现正常。(如下图,同样的软硬件条件,在其他场景下,同样的参数拉取同一个接口的情况)
上图是翻页的场景(因为是列表数据,默认进入打开第一页,也可以自己触发翻页到其他页或回到第一页),也就是说只有在首页中被调用时下载时间异常,在正常TAB页中切换翻页数据下载表现都很正常。
还有一个细节,这个接口在测试或预发环境表现都是正常的,没有出现下载时间过长的问题,这也从侧面证明了并不是因为首页数据量大导致下载慢,通过查看各个整个过程的请求时间线也能明显看出,在出问题的时间断,并没有很多数据资源正在传输。
排除服务端问题
为了排除服务端的问题,自己构建了测试程序简单模拟了下面场景。
- 同一请求顺序发送10次,结果如下(下载时间全部保持在300ms以下)
通过上面的测试不难看出无论是顺序发送,或同一个客户端同时并行请求该请求资源的情况下,下载速度都不会下降到超过1s的水平。
Chrome DevTools 里可以看到当前浏览器默认同一个域名虽也是同时维持着6个http1.1链接,但除了目标接口,其他5个请求都会非常快的完成(其他响应大多小于1kb,不会占用太多带宽)
虽然这样想,但是现在也只能暂时怀疑是网络方面的问题了,为了证实自己的猜想,需要分析TCP原始报文。
注:本文并不阐述如何解决问题,主要通过各种事实数据证明问题出现在哪一个点,从而将问题转到正确的责任人。因为一般比较诡异的问题如果不能确认是问题具体是出在哪一块(服务端,运维,前端,嵌入式),那任何一方在工作压力已经如此大的情况下难免会本能的认为是其他人的问题,最后的结果就是,问题长时间都得不到解决。不过如果有充足是事实证据证明问题出在哪里,那通常负责那一块的同学还是会尽力去解决的。
排查网络问题
准备工作
为了配合Wireshark分析TCP报文我们需要使用Chrome的【Capture Network Log】直接在chrome中访问 chrome://net-export/ 即可以打开。
(Capture Network Log 的使用见 https://support.google.com/chrome/a/answer/3293821?hl=en 仅仅是用还是比较容易的)
如下图,在把Capture Network Log启动后,再次触发首页加载,DevTools显示下载时间依然很长。
刚刚network logs里的数据我们可以在netlog viewer里打开(https://netlog-viewer.appspot.com/ 这是官方的在线日志分析器,访问这个链接您可能需要“梯子”)
如上图,通过查看netlog viewer 里的SOCKET_BYTES_SENT记录我们不难发现这个链接其实一共发送了4次HTTP应用层请求(分别在第26ms,第119ms,第153ms,第184ms 注意这里使用的是相对时间)
通过计算保留到秒的绝对时间分别为35.528;35.621;35.655;35.686 (实际是最后一个才是我们的目标请求,通过chrome时间线或响应的大小可以很容易的确认这个点)
netlog viewer对的上去的(因为请求实际上都很小,一个报文长度内就能发完)
目标流量确认了,现在我们可以安心的去分析TCP报文了
1:首先怀疑滑动窗持续收缩,导致后面接收效率急剧下降
Wireshark提供的流图形我们可以直观的看到滑动窗口在整个TCP数据流里的变化趋势(当然在外面报文列表里也能直接看出来)
2:而后是拥塞窗口cwnd,会不会是发送端因为乱序或超时导致服务器当前链路的cwnd下降而主动降速
因为cwnd是发送端本地维护的,我们无法像Win窗口一样在Wireshark里直接看到,不过我们可以通过观察流量包的状态得出初步的判断。(分析在没有ACK确认的情况下可以发送多少数据)
目标请求response一共323KB(服务端回我们的包一个为1460字节)理论一共大概会回复我们200多个包(通过过滤器我们可以准确统计出229个含有有效数据的回包,当然包括少量的TLS握手及前3个请求的回包)
如果按默认拥塞窗口阀值ssthresh取65532,最差会在第45个包左右(每个报文段都充满的情况下)就会完成慢启动进入拥塞避免状态。
3:后面想到的就是数据包乱序,或丢包
因为无论是丢包还是乱序,最终都会反应到cwnd下降,发送效率降低,不过从数据包列图表来看并没有发生这些情况。
为了分析丢包及乱序对资源下载的影响,实际测试的时候有意创造了较差网络,分析了这些有很多乱序及重传的情况,如下图是一次有乱序的流量。(与前文中的截图不是同一个流量数据,该图是专门选取的网络条件较差的情况)
可以明显看出来,即使发生了丢包及乱序,TCP恢复的都非常的快,绝不会把下载速度拖到超过1s。
确认问题
明确原因
反复查看了多组测试数据包,怎么看都觉得流量是正常的,链路上的数据包及他们的确认包,还包括他们从异常状态中的恢复过程都很正常,完全看不不同寻常的东西。
有的时候陷进去了是很难拔出来的,之前一直认为是运维的问题,所以竭尽全力的去寻找网络上的问题。
会不会是最开始判断错了,恍然大悟,如果网络都是正常的那不可能是超过1s的传输时间啊,200多个包一次15个间隔大概10ms,那发送及确认的时间绝不会超过200ms才对!
这个时候我才开始怀疑chrome的数据(因为之前计算TTFB的时间chrome与wireshark的时间一致,后面就再也没有怀疑过chrome的时间,也没有特意去对比后面的时间点)
验证问题
为了验证这个的结论可以使用使用了常用的代理软件(charles及fiddler)他们都会有独立的时间线统计功能。
其实到现在已经可以下结论是客户端的的问题(前端)。不过因为这个请求其实在浏览器除首页的其他场景或着使用其他客户端直接请求下载速度都是正常的,出问题的那次请求又是预加载的请求(同时还会有好几个请求会被一起发送),所以乍一看总会觉得是网络方面的问题,当然这个上文中的内容已经证明了,完全不是网络的问题。不过要让前端同学“诚恳”的接受这个是自己的问题并想办法修复它,可能还需要我们进一步指出问题出在了什么地方(万一有同学把问题直接推给chrome那不就无解了么)。
通过上文的描述我们可以发现响应回包已经在200ms内全部被客户端socket确认,但是chrome似乎认为是1,2s。
排除其他因素
还有一个细节,因为下载时间变长在测试或预发环境表现正常,因此一开始我按自己的经验认为是运维的问题(服务器,网络,nginx)所以一直在试图证明自己的错误的想法,偏执的去找数据流量的茬,同时也没有怀疑过chrome统计的数据可能不是真实的网络时间,导致整个过程花了很长时间。