刚刚network logs里的数据我们可以在netlog viewer里打开(https://netlog-viewer.appspot.com/ 这是官方的在线日志分析器,访问这个链接您可能需要“梯子”)
如上图我们通过Sockets及Events里的记录定位到我们请求的链路。
主要是要获得这个链路的本地端口号(在Wireshark里我们需要通过这个端口号跟踪我们的tcp流)
当然还可以得到这个链路的开始时间,及耗时 (需要明确一点这个开始时间是握手开始时间,不完全等于这个请求的开始时间,而且这个链接其实也会发好几个请求,后面会提到)
根据netlog viewer里的信息找到指定端口,如上图追踪目标流(本质是对网卡数据包进行过滤筛选,更容易定位问题)
如上图,通过查看netlog viewer 里的SOCKET_BYTES_SENT记录我们不难发现这个链接其实一共发送了4次HTTP应用层请求(分别在第26ms,第119ms,第153ms,第184ms 注意这里使用的是相对时间)
通过计算保留到秒的绝对时间分别为35.528;35.621;35.655;35.686 (实际是最后一个才是我们的目标请求,通过chrome时间线或响应的大小可以很容易的确认这个点)
如上图,通过在指定流筛选由客户端发出去的大小合适的数据,可以看到发送的时间点基本上是跟前面Chrome的netlog viewer对的上去的(因为请求实际上都很小,一个报文长度内就能发完)
目标流量确认了,现在我们可以安心的去分析TCP报文了
我们只需要关注No 968 后面的报文(因为我们的目标请求是从这里开始的),可以看到其实第一个数据回包在No 1031 (时间为:35.875)
与发出请求的那个包的时间差为189ms,这个其实就是TTFB (与chrome里计算出的198ms也是接近的)
逐条查看后面下载的包,看起来都很正常。
下面列出最开始在网络方向怀疑的几个可能的点,并逐个尝试排查。 (下一段内容主要是逐个排除自己猜测,且过程与网络传输强相关,如果实在不感兴趣可以跳过直接看结论 )
1:首先怀疑滑动窗持续收缩,导致后面接收效率急剧下降
通过Wireshark提供的流图形我们可以直观的看到滑动窗口在整个TCP数据流里的变化趋势(当然在外面报文列表里也能直接看出来)
不过看起来当前流最差的情况滑动窗口也还有100kb (完全是够用,事实上只要红框处tcptrace的2条线不重合即表示滑动窗口还没有满)
2:而后是拥塞窗口cwnd,会不会是发送端因为乱序或超时导致服务器当前链路的cwnd下降而主动降速
因为cwnd是发送端本地维护的,我们无法像Win窗口一样在Wireshark里直接看到,不过我们可以通过观察流量包的状态得出初步的判断。(分析在没有ACK确认的情况下可以发送多少数据)
目标请求response一共323KB(服务端回我们的包一个为1460字节)理论一共大概会回复我们200多个包(通过过滤器我们可以准确统计出229个含有有效数据的回包,当然包括少量的TLS握手及前3个请求的回包)
如果按默认拥塞窗口阀值ssthresh取65532,最差会在第45个包左右(每个报文段都充满的情况下)就会完成慢启动进入拥塞避免状态。
如上图,通过查看建立链接握手时收到ACK的时间点,可以大致推断出客户端到服务器的RTT大概是10ms (因为握手的ACK一般不会延迟发送)