转载

头大的问题

需要说明的是，这里的头指的是大头，当然如果是另外一个头大了就好解决得多了。

1) 缘起

业务发现线上的某一个 mcq 资源这几天慢请求报警增加了不少。咦，这台机器的资源什么都没动啊，怎么说慢就慢了呢。没见过场面的小林，遇到这种情况也是很紧张呢，然迅速且熟练地从档中掏出之前磨好的工具蠢蠢欲动。

首先得确认一下到到底是客户端本身有问题还是服务处理慢呢？这时候平时写的工具就起了作用。

先用 tcprstat 监控一下看有木有超过一定阀值( 200ms )的请求。

跑了一会，活捉一条慢请求，如下:

[2016-04-07 15:11:21.414] 192.168.21.18:19617 <==> 192.168.21.17:23204 cost 359.568ms

因为这个工具可看出客户端从发包到服务端返回耗时将近 360ms, 而我们客户端反馈的延时也是 360ms，所以客户端本身是没有问题的。

2）服务慢

既然客户端没有问题，那么服务的背后很自然的出现了一朵圆形的大锅。

在客户端发送请求并监控的过程，同时也在服务端抓了一下包:

15:11:21.025117 IP 192.168.21.18.52473 > 192.168.21.17.23204: Flags [P.], seq 1:9, ack 1, win 29, options [nop,nop,TS val 546605754 ecr 2709027525], length 8 15:11:21.025129 IP 192.168.21.17.23204 > 192.168.21.18.52473: Flags [.], ack 9, win 29, options [nop,nop,TS val 2709027525 ecr 546605754], length 0 15:11:21.384705 IP 192.168.21.17.23204 > 192.168.21.18.52473: Flags [P.], seq 1:441, ack 10, win 29, options [nop,nop,TS val 2709027885 ecr 546605754], length 440 15:11:21.384857 IP 192.168.21.18.52473 > 192.168.21.17.23204: Flags [.], ack 441, win 31, options [nop,nop,TS val 546606114 ecr 2709027885], length 0

从抓包记录来看，客户端在 15:11:21.025117 发了第一条请求数据包, 而服务端在 15:11:21.384705 (第三条记录) 才响应。也就是服务这边从接收到数据包到处理返回耗时 360ms。

所以到这里也说明，服务慢跟外部的网络链路是没有关系的，是服务本身接收和处理慢导致。

3) 磁盘异常

因为明确知道服务慢而导致慢请求，所以第一反应还是先撸一把压压惊，然后再检查一下系统各个资源的利用率情况(主要是 cpu, 内存以及磁盘)。

发现磁盘读写有问题，基本没有读写的情况下，util 接近 100%...

2016年04月07日 15时11分20秒 Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util sda               0.00    24.00    0.00    0.00     0.00     0.00     0.00     5.90    0.00   0.00  98.40  2016年04月07日 15时11分21秒 Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s avgrq-sz avgqu-sz   await  svctm  %util sda               0.00     5.94    0.00    0.00     0.00     0.00     0.00     7.99    0.00   0.00  99.01

然后观察一段时间后，发现出现慢请求的时刻都是伴随着 util 标高，同时 await 也是到几百毫秒。那么就怀疑服务慢是跟磁盘有问题有关，接下去当然是来收集数据证明。

4) strace

因为客户端发送的慢请求是 stats 命令，只是简单从内存获取统计数据不涉及磁盘操作，那怎么会影响到呢？所以带着疑问使用 strace 看一下系统调用的情况和耗时:

15:11:20.570239 epoll_wait(10, {{EPOLLIN, {u32=71, u64=71}}}, 32, 4294967295) = 1 <0.806745> 15:11:21.377273 read(71, "get .../r/n", 2048) = 16 <0.000094> 15:11:21.382178 read(68, 0x7f7cd009cfb0, 2048) = -1 EAGAIN (Resource temporarily unavailable) <0.000022> ... 15:11:21.382334 epoll_wait(10, {{EPOLLIN, {u32=8, u64=8}}}, 32, 4294967295) = 1 <0.001650> 15:11:21.384065 read(8, "/0", 1) = 1 <0.000029> 15:11:21.384165 epoll_ctl(10, EPOLL_CTL_ADD, 53, {EPOLLIN, {u32=53, u64=53}}) = 0 <0.000040> 15:11:21.384312 epoll_wait(10, {{EPOLLIN, {u32=53, u64=53}}}, 32, 4294967295) = 1 <0.000023> 15:11:21.384421 read(53, "stats/r/n/n", 2048) = 8 <0.000026>

我们发现第一条记录的 epoll_wait 等待 800ms 才接收到事件。而上面的抓包记录来看，数据包是 15:11:21.02 就已经到达了服务这边，为什么 epoll_wait 直到 15:11:21.377273 才有触发事件呢？我们也可以看到 strace 最后一条记录，读到 stats 请求的时间是 15:11:21.384421 ，和服务回包时间一致，所以说明 stats 命令处理很快, 跟服务具体的处理没关系，是 epoll_wait 的问题。

所以这里重新梳理一下思路，即数据包很早就到达服务，而因为系统调用 epoll_wait 事件触发的延时导致了响应延时。。