记一次IO异常捕获的过程

背景信息:

遇到一个IO异常飙升的问题,IO起飞后系统响应异常缓慢,看不到现场一直无法定位问题,检查对应时间点应用日志也没有发现异常的访问,这种问题怎么办呢?

1,采集系统IO,确认IO异常发生在系统盘,还是数据盘,使用系统自带的iostat即可采集

# iostat -d 3  -k -x -t 30
06/12/2018 09:52:33 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
xvda              0.00     0.39    0.08    0.70     1.97     5.41    18.81     0.03   44.14   1.08   0.08
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     8.59     0.00    1.14   1.09   0.00

06/12/2018 09:52:36 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
xvda              0.00     0.00    0.00    0.67     0.00     2.68     8.00     0.00    1.00   0.50   0.03
xvdb              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00

每隔3秒采集一次磁盘io,输出时间,一共采集30次,想一直抓的话把30去掉即可,注意磁盘空余量

通过这个命令我们可以确认如下信息:

- 问题发生的时间
- 哪块盘发生的io
- 磁盘的 IOPS( r/s     w/s)以及吞吐量( rkB/s    wkB/s )

2,确认哪块盘发生了IO还不够,再抓一下发生IO的进程,需要安装 iotop 进行捕获

# iotop -b -o -d 3 -t -qqq -n 30
10:18:41  7024 be/4 root        0.00 B/s    2.64 M/s  0.00 % 93.18 % fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=1k -size=1G -numjobs=1 -runtime=1000 -group_reporting -filename=iotest -name=Rand_Write_Testing

每隔3秒采集一次,一共采集30次,静默模式,只显示有io发生的进程

通过这个命令我们可以确认如下信息:
- 问题发生的时间
- 产生IO的进程id以及进程参数(command)
- 进程产生的吞吐量(如果有多个可以把qqq去掉可显示总量)
- 进程占用当前IO的百分比

俗话说得好,光说不练假把式,我们实操来看一下(涉及用户进程信息,没有得到客户授权因此以fio为演示)

3, 使用 fio 进行 IO 压测,详细参数我就不讲了,有兴趣的同学看下块存储性能

压测窗口:

# fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=1k -size=1G -numjobs=1 -runtime=1000 -group_reporting -filename=iotest -name=Rand_Write_Testing
Rand_Write_Testing: (g=0): rw=randwrite, bs=1K-1K/1K-1K/1K-1K, ioengine=libaio, iodepth=128
fio-2.0.13
Starting 1 process
^Cbs: 1 (f=1): [w] [8.5% done] [0K/2722K/0K /s] [0 /2722 /0  iops] [eta 05m:53s]
fio: terminating on signal 2

Rand_Write_Testing: (groupid=0, jobs=1): err= 0: pid=11974: Tue Jun 12 10:36:30 2018
  write: io=88797KB, bw=2722.8KB/s, iops=2722 , runt= 32613msec
 ......

iotop窗口:

# iotop -n 10 -b -o -d 3 -t -qqq
10:36:03 11974 be/4 root        0.00 B/s    2.63 M/s  0.00 % 93.95 % fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=1k -size=1G -numjobs=1 -runtime=1000 -group_reporting -filename=iotest -name=Rand_Write_Testing
10:36:06 11974 be/4 root        0.00 B/s    2.64 M/s  0.00 % 92.68 % fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=1k -size=1G -numjobs=1 -runtime=1000 -group_reporting -filename=iotest -name=Rand_Write_Testing

iostat窗口:

#  iostat -d 3  -k -x -t 10
Linux 2.6.32-431.23.3.el6.x86_64 (test)     06/12/2018     _x86_64_    (1 CPU)


06/12/2018 10:36:03 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
xvda              0.00     0.00    0.00    0.00     0.00     0.00     0.00     0.00    0.00   0.00   0.00
xvdb              0.00    10.80    0.00 2823.69     0.00  2837.63     2.01   132.97   47.00   0.37 104.53

06/12/2018 10:36:06 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
xvda              0.00     0.00    0.00    2.76     0.00    11.03     8.00     0.00    1.62   0.62   0.17
xvdb              0.00    17.24    0.00 2788.28     0.00  2805.17     2.01   131.50   47.20   0.37 103.45

通过输出结果的时间点进行对比分析,相对于 fio 的 IOPS,吞吐量 跟 iotop 以及 iostat 监控到的数据是一致。因此,看到这,您已经学会怎么查消耗IO的进程了

注意:为了压测的慢一些我特意把bs设置为1k,这样执行的时间会比较久,fio压测详见前面的块存储性能

牧原辣么长!怎么可能到这就结束了呢!

心细的同学可能发现 iotop 输出不带年月日,如果抓日志的时间超过24小时,时间重复怎么办?

彩弹:


# iotop  -b -o -d 1 -qqq |awk '{ print $0"\t" strftime("%Y-%m-%d-%H:%M:%S",systime()) } '
16209 be/4 root        0.00 B/s    2.64 M/s  0.00 % 93.72 % fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=1k -size=1G -numjobs=1 -runtime=1000 -group_reporting -filename=iotest -name=Rand_Write_Testing    2018-06-12-10:54:10
16209 be/4 root        0.00 B/s    2.63 M/s  0.00 % 93.61 % fio -direct=1 -iodepth=128 -rw=randwrite -ioengine=libaio -bs=1k -size=1G -numjobs=1 -runtime=1000 -group_reporting -filename=iotest -name=Rand_Write_Testing    2018-06-12-10:54:11

详细参数就不讲了,大家可以看下输出结果行最后一列是年月日时分秒,那么 IO 消耗的始作俑者会查了吗?

上一篇:记一次吐血的ping: unknown host


下一篇:Centos7 更换内核到4.16的尝试