神刀安全网

头大的问题

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

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 事件触发的延时导致了响应延时。 。

5) 疑问

这台机器上部署了好几个 mcq 实例,看了一下所有实例都是有同样的问题。所以是磁盘导致问题的概率很大,才能让机器上面的服务都表现很一致。

剩下的问题是,是磁盘有问题导致? 为何磁盘有问题能导致 epoll_wait 事件唤醒问题? 理论上 epoll 跟磁盘是完全没有关系的。

有什么其他思路来证明???

转载本站任何文章请注明:转载至神刀安全网,谢谢神刀安全网 » 头大的问题

分享到:更多 ()

评论 抢沙发

  • 昵称 (必填)
  • 邮箱 (必填)
  • 网址
分享按钮