前些日子，监控显示线上偶尔发生请求两秒超时的情况。解决这个问题前前后后花了不少时间，也走了一些弯路。这里记录下来备忘。

前期分析

首先需要了解一下我们的服务：

我们的服务是一组无状态的前端服务器加上有状态的后端存储层。

这些服务都部署在腾讯云黑石服务器上面。

第一件事是要定位问题出现在前端还是后端。通过日志，我们发现在出错时间段里，每个前端服务器都有报错，并且出错请求都是发往同一后端服务器的。由此可见，问题出现在后端服务上。

接下来，需要分析出错的特征。通过日志发现错误都是因为前端两秒超时导致，而后端在前端超时之后事实上是完成了请求。因为是存储服务，我们自然在第一时间就查看了磁盘的情况。果然，在出错时，磁盘的io.util非常高(sar -dp的输出，从第4列开始分别是tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util)：

需要注意的是：

io.util非常高，且只持续了2~3秒

几乎所有盘的io.util都高

io的tps和吞吐并不高

另外，还发现了另外一个规律：单台机器，大概每12小时左右会出现io.util高，并伴随着超时出错：

问题排查

快速排查

我们做了一些快速排查，试图以比较小的代价找到问题的根源：

查看系统的定时任务

查看系统日志

查看存储服务代码中的定时任务

可惜，都没有发现有价值的线索。于是推测，一定是有一个我们不知道的存在以12小时为周期在消耗IO。

追踪IO使用状况

先使用iotop来定位出错时刻是谁占用了大量IO：

python /sbin/iotop -bPto -n 86400 > iotop.log

上述命令以批处理的形式，每1秒一个输出，一共持续86400秒(24小时)。同样，并没有发现除了我们程序之外的可疑线程。

Iotop虽然是一个好工具，然而一个缺陷是并没有详细的文档说明它的工作原理。对于一个系统工具来说，原理性的文档还是很有必要的。在这种情况下，我们怀疑iotop并不能真实的反映进程的IO使用状况。为了再次确认，我们采用SystemTap来统计IO调用。下面是改良过的iotop.stp：

global count_stacks

global size_stacks

global max_seconds = 172800

global elapsed_seconds = 0

global interval = 2

probe ioblock.request {

if(devname == "sdd") {

count_stacks[pid(), execname(), bio_rw_str(rw), backtrace()]++

size_stacks[pid(), execname(), bio_rw_str(rw), backtrace()] += size

}

}

probe timer.s(1)

{

if (++elapsed_seconds % interval == 0) {

if (elapsed_seconds >= max_seconds) {

delete count_stacks

exit()

}

time_string = ctime(gettimeofday_s())

foreach ([process_id, process_name, read_write, stack] in count_stacks- limit 5) {

printf("==== %25s %6d %20s %s %d\n", time_string, process_id, process_name, read_write, count_stacks[process_id, process_name, read_write, stack])

print_syms(stack)

}

foreach ([process_id, process_name, read_write, stack] in size_stacks- limit 5) {

printf("++++ %25s %6d %20s %s %d\n", time_string, process_id, process_name, read_write, size_stacks[process_id, process_name, read_write, stack])

print_syms(stack)

}

delete count_stacks

delete size_stacks

}

}

这个脚本以2秒间隔，采样发生在/dev/sdd上的所有IO读写请求，并分别按照请求栈出现的次数以及IO总大小，打印前5名。执行脚本：

nohup stap --suppress-handler-errors -d xfs ./iotop.stp > stap.log &

一个典型的部分结果是：

==== Wed Oct 24 09:19:03 2018 1984 java W 20

0xffffffff812c7130 : generic_make_request+0x0/0x130 [kernel]

0xffffffff812cd89b : blkdev_issue_flush+0xab/0x110 [kernel]

0xffffffffa0681dc9 : xfs_blkdev_issue_flush+0x19/0x20 [xfs]

0xffffffffa066b506 : xfs_file_fsync+0x1e6/0x200 [xfs]

0xffffffff8120f975 : do_fsync+0x65/0xa0 [kernel]

0xffff882025940b80 : 0xffff882025940b80

0xffffffff8120fc40 : SyS_fsync+0x10/0x20 [kernel]

0xffffffff81645909 : system_call_fastpath+0x16/0x1b [kernel]

==== Wed Oct 24 09:19:03 2018 1984 java R 5

0xffffffff812c7130 : generic_make_request+0x0/0x130 [kernel]

0xffffffff8121f630 : do_mpage_readpage+0x2e0/0x6e0 [kernel]

0xffffffff8121fb1b : mpage_readpages+0xeb/0x160 [kernel]

0xffffffffa065fa5d : xfs_vm_readpages+0x1d/0x20 [xfs]

0xffffffff81175cdc : __do_page_cache_readahead+0x1cc/0x250 [kernel]

0xffff88201534cf00 : 0xffff88201534cf00

0xffffffff81175ee6 : ondemand_readahead+0x126/0x240 [kernel]

0xffffffff811762c1 : page_cache_sync_readahead+0x31/0x50 [kernel]

0xffffffff8120e0d6 : __generic_file_splice_read+0x556/0x5e0 [kernel]

0xffffffff8120c9b0 : spd_release_page+0x0/0x20 [kernel]

0xffffffff81513d48 : sk_reset_timer+0x18/0x30 [kernel]

0xffffffff81582ce5 : tcp_schedule_loss_probe+0x145/0x1e0 [kernel]

0xffffffff81583b40 : tcp_write_xmit+0x2b0/0xce0 [kernel]

0xffffffff8163cb5b : _raw_spin_unlock_bh+0x1b/0x40 [kernel]

0xffffffff815154a8 : release_sock+0x118/0x170 [kernel]

0xffffffff815769e6 : tcp_sendmsg+0xd6/0xc20 [kernel]

0xffffffff8120e19e : generic_file_splice_read+0x3e/0x80 [kernel]

0xffffffffa066bc5b : xfs_file_splice_read+0xab/0x140 [xfs]

0xffffffff8120d222 : do_splice_to+0x72/0x90 [kernel]

0xffffffff8120d2f7 : splice_direct_to_actor+0xb7/0x200 [kernel]

第一个栈是我们的程序在做fsync，第二个栈是程序在做read ahead。这两个我们都排除了：

系统压力并不大，fsync也是一直在做的操作

read ahead我们通过blockdev也修改了，并没有效果

至此，我们的调查陷入僵局：并没有谁在做IO，然而io.util就是高。

找到元凶

继续思考，我们推测：可能有某个操作并没有做大量的IO，但是可能会把盘给夯住。注意，这个推测和我们最初对IO的分析是一致的。

于是，我们想到用top来看看当时的进程状况(按道理这是第一个需要尝试的手段！)：

nohup top -b -d 1 -n 86400 > top.log &

即，以批处理的方式，每1秒打印一次进程状况，一共持续24小时。然后，在发生问题的时刻，我们搜素所有处于D状态的(等IO)的进程。果然，发现一个可疑进程：

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

32289 root 20 0 2148 1528 212 D 0.0 0.0 0:00.00 sas3flash

sas3flash是个什么进程呢？先找到他的位置：

$locate sas3flash

/usr/local/agenttools/agent/plugins/titan_tools/sas3flash

所在的目录貌似是属于一个agent的，嗯～相当可疑。看看他是被谁调用的：

/usr/local/agenttools/agent/plugins$grepsas3flash * -r

Binary file titan_for_serverV1.0 matches

/usr/local/agenttools/agent/plugins$strings titan_for_serverV1.0 | grepsas3flash

sas3flash

/usr/local/agenttools/agent/plugins/titan_tools/sas3flash -list

/usr/local/agenttools/agent/plugins/titan_tools/sas3flash

report_hba_by_sas3flash

report_hba_by_sas3flash

report_hba_by_sas3flash

再通过一通搜索，我们得知：

sas3flash貌似是一个HBA管理工具(pdf)

agenttools这个目录是腾讯云黑石的监控组件目录

sas3flash --list看上去是一个查看命令，貌似人畜无害，但很可能是问题的元凶

于是执行sas3flash --list，果然问题重现！用strace查看可知，该命令并没有发什么IO请求，而是做了一些ioctl的调用。实验证实这些查询调用会夯住IO。

在/usr/local/agenttools/agent/Agent_log.log日志文件中，我们能够找到这个命令执行的时间点和输出，考虑到执行-汇报时间差，可以发现该命令执行的时间点就是线上超时错误问题出现的时间点：

[2018-10-25 19:12:13] Send warning info, id:36149, value:[CollectID:

ServerSN:2102311YMD10J1000212

Avago Technologies SAS3 Flash Utility

Version 09.00.00.00 (2015.02.03)

Copyright 2008-2015 Avago Technologies. All rights reserved.

Adapter Selected is a Avago SAS: SAS3008(C0)

Controller Number : 0

Controller : SAS3008(C0)

PCI Address : 00:01:00:00

SAS Address : 5e86819-f-8f0a-f000

NVDATA Version (Default) : 0b.02.00.01

NVDATA Version (Persistent) : 0b.02.00.01

Firmware Product ID : 0x2721 (IR)

Firmware Version : 12.00.02.00

NVDATA Vendor : LSI

NVDATA Product ID : SAS3008

BIOS Version : 08.29.02.00

UEFI BSD Version : 17.00.04.00

FCODE Version : N/A

Board Name : SAS3008

Board Assembly : N/A

Board Tracer Number : 022CDECNHC010620

Finished Processing Commands Successfully.

Exiting SAS3Flash.

]

通过仔细查看这个目录下面的文件，就会发现，这个监控组件有着自己的一套定时任务逻辑以及日志输出。这就是为什么我们通过系统的crontab、cron.d以及系统日志无法定位问题的原因。

至于，为什么这个命令会导致IO夯，我们还在等腾讯云的答复。临时的解决方案是禁掉这个命令的执行(这也需要腾讯云出一个监控组件的hotfix包才能完成，单纯的删除sas3flash没有用)。

小结

纵观整个排查过程，我们其实是走了一些弯路，通过分析IO特征，如果第一时间采用top就能更快的发现问题。

同时，我也深深感受到了以下一些痛点：

iotop应该有原理性文档

腾讯云的监控组件不应该完全独立于系统。如果走的是系统的contab，或者日志，我们可以很快定位问题

系统的监控组件应该得到充分的测试