接口响应时间剖析

在日常工作过程中，我们经常需要关注接口的响应时间，优化接口的时延，那么接口的响应时间由哪些部分组成呢？先给出一个公式：

接口响应时间 = 请求机器与服务器之间包往返时间 RTT * N + 业务处理处理时间

通过下面的一组实验数据，我们可以完整地解析出从请求接口，到接口返回最后一个字节的数据，所用的时间，下面是测试环境：

请求机器 ip：10.145.67.55
请求机器端口：51830
服务器 ip：10.109.93.26
服务器端口：8703

通过 curl 命令可以获取接口的响应时间：

curl -o /dev/null -s -w "time_connect: %{time_connect}\ntime_starttransfer: %{time_starttransfer}\ntime_total: %{time_total}\n" 'http://10.109.93.26:8703/xxx'
time_connect: 0.012622
time_starttransfer: 0.028162
time_total: 0.028248

时间指标解释：
time_connect 建立到服务器的 TCP 连接所用的时间 12.6 ms
time_starttransfer 在发出请求之后，Web 服务器返回数据的第一个字节所用的时间，28.1 ms
time_total 完成请求所用的时间，28.2 ms

首先，可以通过 ping 命令找到获取 RTT （Round-Trip Time）：

ping -c 3 10.109.93.26

PING 10.109.93.26 (10.109.93.26) 56(84) bytes of data.
64 bytes from 10.109.93.26: icmp_seq=1 ttl=57 time=10.5 ms
64 bytes from 10.109.93.26: icmp_seq=2 ttl=57 time=10.4 ms
64 bytes from 10.109.93.26: icmp_seq=3 ttl=57 time=10.5 ms

--- 10.109.93.26 ping statistics ---
3 packets transmitted, 3 received, 0% packet loss, time 2013ms
rtt min/avg/max/mdev = 10.482/10.517/10.538/0.121 ms

由上可以看出 RTT 为 10.5 ms

通过 tcpdump 命令可以获取请求机器与服务器之间的通信细节：

tcpdump -S -n -i any host 10.109.93.26

19:37:44.217739 IP 10.145.67.55.51830 > 10.109.93.26.8703: Flags [S], seq 2113915355, win 29200, options [mss 1460,sackOK,TS val 1993677883 ecr 0,nop,wscale 8], length 0
19:37:44.230092 IP 10.109.93.26.8703 > 10.145.67.55.51830: Flags [S.], seq 4262241738, ack 2113915356, win 28960, options [mss 1460,sackOK,TS val 1329263607 ecr 3677883,nop,wscale 8], length 0
19:37:44.230132 IP 10.145.67.55.51830 > 10.109.93.26.8703: Flags [.], ack 4262241739, win 115, options [nop,nop,TS val 1993677896 ecr 1329263607], length 0
19:37:44.231506 IP 10.145.67.55.51830 > 10.109.93.26.8703: Flags [P.], seq 2113915356:2113915459, ack 4262241739, win 115, options [nop,nop,TS val 1993677897 ecr 9263607], length 103
19:37:44.243846 IP 10.109.93.26.8703 > 10.145.67.55.51830: Flags [.], ack 2113915459, win 114, options [nop,nop,TS val 1329263621 ecr 1993677897], length 0
19:37:44.245639 IP 10.109.93.26.8703 > 10.145.67.55.51830: Flags [P.], seq 4262241739:4262241916, ack 2113915459, win 114, options [nop,nop,TS val 1329263623 ecr 3677897], length 177
19:37:44.245660 IP 10.145.67.55.51830 > 10.109.93.26.8703: Flags [.], ack 4262241916, win 119, options [nop,nop,TS val 1993677911 ecr 1329263623], length 0
19:37:44.245687 IP 10.109.93.26.8703 > 10.145.67.55.51830: Flags [F.], seq 4262241916, ack 2113915459, win 114, options [nop,nop,TS val 1329263623 ecr 1993677897], length 0
19:37:44.245694 IP 10.145.67.55.51830 > 10.109.93.26.8703: Flags [.], ack 4262241917, win 119, options [nop,nop,TS val 1993677911 ecr 1329263623], length 0
19:37:44.245818 IP 10.145.67.55.51830 > 10.109.93.26.8703: Flags [F.], seq 2113915459, ack 4262241917, win 119, options [nop,nop,TS val 1993677911 ecr 1329263623], length 0
19:37:44.258120 IP 10.109.93.26.8703 > 10.145.67.55.51830: Flags [.], ack 2113915460, win 114, options [nop,nop,TS val 1329263635 ecr 1993677911], length 0

分析：

编号为 1-3 消息为 tcp 的三次握手，耗时 12.3 ms，计入响应时间。
第 4 条消息为请求机器向服务机器发送请求
第 5 条消息为服务器对于消息的确认
第 6 条消息为服务的结果响应，第 5 条与第 6 条消息之间耗时 1.8 ms，为业务处理时间，这里因为仅仅返回固定的文本，无其他复杂逻辑，所以耗时比较短
第 7 条消息为请求机器对服务器响应的消息确认，至此服务器响应结束。
编号 8-11 消息为 tcp 的四次挥手，不计入响应时间。
本次请求响应时间包括，三次握手的一个 RTT（消息 1 - 2，发送最后一个确认的同时开始发送请求体）12.3 ms，服务器处理时间 1.8ms，以及消息返回请求一个RTT （消息 4-6）14.1 ms，总体 28.2 ms 与 curl 命令打印时间相符。