CPU.IOWAIT 偏高问题

作者: 风 哥 分类: Linux运维 发布时间: 2019-09-02 17:09

问题描述

小米监控发现一台机器的cpu.iowait偏高,波动很严重。

那么是什么导致这个问题的产生呢?下面听我细细道来。

探究过程

每当出现一个问题的时候,背后一定存在着因果关系,区别只是背后的因素隐藏的多深!

这句话可以辩证的看待,不用过分纠结这句话本身,因为任何东西纠结到极致其实都失去了意义,比如普朗克时间内追求因果律就没有意义。

分析途径

问题出现后需要定位问题来源,离不开各种工具的辅助甚至人肉辅助。目前我手里现有的分析途径如下:

  • 小米监控
  • 各种linux命令
  • 一颗充满兴趣的心(最重要的东西)

初步怀疑

问题已经比较明确了,看着这么大幅度的波动,我首先怀疑的是小米监控的agent采集的数据是不是出了问题?

小米监控的agent是每分钟采集一次数据,具体的计算方法应该是分析 /proc/stat 文件。包括top命令也是分析这个文件得出的cpu占用率。

 

那么:

  • 什么是cpu.iowait呢?
  • cpu.iowait过高是否说明了系统存在I/O问题?
  • 是什么导致了cpu.iowait这么高?

iowait深入探究

%iowait表示什么?其实我自己也是一知半解,google了一番,找到讲的比较透彻的一篇文章:理解 %IOWAIT (%WIO),文中核心的两段话是:

我们不妨采纳Linux的措辞,%iowait 表示在一个采样周期内有百分之几的时间属于以下情况:CPU空闲、并且有仍未完成的I/O请求。

对 %iowait 常见的误解有两个:一是误以为 %iowait 表示CPU不能工作的时间,二是误以为 %iowait 表示I/O有瓶颈。

看来%iowait偏高不能说明什么问题。根据定义,它需要同时满足CPU空闲和有仍未完成的I/O请求这两个条件,说明CPU其实有空闲的,而且空闲率很高,且落在CPU空闲状态的I/O很多,才导致iowait%偏高。

CPU不能工作?

为了证明CPU确实是有空闲的,仍然能进行工作,那么如果我把CPU压满,CPU没有了空闲,iowait%理应很低或者波动很小。所以简单写了一个cpu密集型的任务:

#!/usr/bin/env python
#-*- coding:utf8 -*-
from multiprocessing import Pool
def run(num):
  while True:
    num += 1
if __name__ == "__main__":
  pool = Pool(6)
  pool.map(run,range(6))
  pool.close()
  pool.join()

没错,就是这么简单!!

为了进行对比,故采取的方式为跑压力一段时间,然后撤掉压力再收集一段时间,最后的曲线图如下:

可以很明显的看到cpu.busy压到了 70 ~ 90 ,波动范围变小了很多,同时cpu.iowait波动范围也很小了,对比撤掉压力之后的,可以说差别很大。从这里也证明了之前的猜想,CPU确实是有空闲的,也确实能进行工作,造成cpu.busy波动严重的指标就是cpu.iowait。那么是什么导致了cpu.iowait偏高,I/O是不是到了瓶颈呢?

I/O存在瓶颈?

要分析I/O是不是存在瓶颈,必然要借助一些磁盘、I/O性能分析工具,通常分析磁盘性能的工具有iostat,sar等,分析I/O情况的有iotop等,同时结合小米监控的数据进行分析。

[root@xxx-008 ~]# iostat  -xk 2 100
avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           6.77    0.00    3.88    4.31    0.00   85.05
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await  svctm  %util
sda               0.02    10.39  254.22  104.63 12579.25  5175.08    98.95     0.44    1.21   0.50  17.79
sdb               0.00     5.04   23.05   23.75  1375.87  1809.86   136.14     0.34    7.28   5.69  26.63
sdc               0.00     4.66   23.00   24.04  1372.72  1796.91   134.77     0.35    7.41   5.67  26.67
sdd               0.00     6.23   22.83   18.82  1356.25  1697.11   146.61     0.39    9.42   6.17  25.71
sde               0.00     7.01   20.54   19.57  1227.02  1724.81   147.18     0.10    2.45   8.01  32.14

关于iostat的各项参数解释如下: 请点击<Linux iostat命令详解>

其中重点需要关注的是avgqu-sz、await、svctm、util这四个指标,这里推荐可以看一下这篇文章容易被误读的IOSTAT,里面提到util和await两个指标要辩证的看待,并不绝对。对于util,由于当今世界的ssd已经具有较高的并行速度,即便util达到了100%也并不能证明磁盘利用率很高,await这个指标也没有较为标准的衡量。但是,我们可以借此来分析,作为参考,这是可以的。

同时,查看小米监控关于磁盘的各项数据(主要是disk.io.avgqu-sz、disk.io.util、disk.io.svctm、disk.io.await):

上图可以看到这几个指标波动很大,disk.io.util波动幅度很大很严重;disk.io.await最大值竟然达到了1.252k;disk.io.svctm最大值竟然飙到了192.6;同时disk.io.avgqu-sz也波动,该指标是I/O量的衡量。猜测这台机器的SSD磁盘确实可能存在I/O性能问题。

那么怎么验证呢?

Find The Murderer

一定要找到凶手! 《致命ID》

上面的过程可谓拨开云雾见青天,经过一步一步的分析探究,最终得到了猜想:

猜测这台机器的SSD磁盘确实可能存在I/O性能问题。

那么怎么来验证呢?很简单,找到造成这些I/O的凶手就行!怎么找,过程中我先后使用了两种方法。

Process Status D

ps 命令可以查看有关进程的详细信息,比如状态码,关于进程状态码的解释如下:

PROCESS STATE CODES
       D   uninterruptible sleep (usually IO)
       R   runnable (on run queue)
       S   sleeping
       T   traced or stopped
       Z   a defunct ("zombie") process
       For BSD formats and when the "stat" keyword is used, additional letters may be displayed:
       W   has no resident pages
       <   high-priority process
       N   low-priority task
       L   has pages locked into memory (for real-time and custom IO)

其中重点关注的状态码为D,它表示不可中断的休眠状态,通常表示I/O操作。这就很简单了,要找到进行I/O操作的进程,写个脚本抓一下:

#!/usr/bin/env python
#-*- coding:utf-8 -*-
import os
import time
def run():
  result = []
  timestamp = time.strftime('%Y-%m-%d %H:%M:%S', time.localtime(time.time()))
  cmd = 'ps auxf'
  ret = os.popen(cmd).readlines()
  for i in ret:
    item = i.split()
    if len(item) > 7:
      item = item[7]
      if item == 'D':
        result.append(i)
  for r in result:
    process = '%s %s' % ( timestamp,r[:-1])
    print process
  if result:
    print '\n'
if __name__ == "__main__":
  while True:
    run()
    time.sleep(0.5)

最终得到的结果如下:

这里发现有nginx进程,这个并不奇怪,但是也有大量的kworker进程,一脸懵逼!

使用iotop

在寻找进行I/O操作的进程的同时,我同时也打开了iostat命令,重点关心%iowait,看当有I/O操作的时候%iowait是不是变高了,两个命令均是动态运行,所以能够抓到同时产生的现象

如上图所示,屏幕左右两边是同时产生的结果,左边iotop抓到了产生大量I/O操作的进程,同时屏幕右半边最下面iostat命令输出%iowait从一个很低的值 0.25 飙升到了 51.71,同时注意avgqu-sz、await、svctm三个指标,三个指标均出现了大幅度的增加。从这里就可以肯定的说明系统I/O确实存在问题,I/O操作量较大的进程也找到了。

这里也出现了大量的kworker进程,那么到底kworker是什么?谷歌了一番:

简而言之,kworker进程是内核在做一些工作,比如系统调用等等。这里的kworker伴随着X进程大量出现,可以猜测是bear进程进行的一些系统调用。

到这里,其实已经可以得出结论了。

最终结论

经过上述的探究,可以得到如下的结论:

系统存在I/O瓶颈,这台机器的SSD系统盘有性能退化问题。

 

基于以上的分析,有必要用另外的方法。那么如何统计每个进程的 I/O 数呢,进而找到 I/O 数最高的进程?下面是查找过程。

首先,关闭syslog:

dmesg -c
/etc/init.d/klogd stop

接着下载一个 perl 脚本:

  
wget https://github.com/true/aspersa-mirror/blob/master/iodump

然后,打开 block_dump,这是内核关于 I/O 信息的一些日志:

echo 1 > /proc/sys/vm/block_dump

block_dump中设置非零值能够打开内核关于每一个 I/O 操作进行记录的开关,这时候可以看到内核已经收集到了 I/O 的日志:

[root@localhost]# dmesg
someprocess(1880): READ block 3830529728 on bcache1 (160 sectors)
someprocess(1877): READ block 2492278208 on bcache2 (160 sectors)
someprocess(1878): READ block 1407266528 on bcache3 (160 sectors)
someprocess(1877): WRITE block 2671126368 on bcache2 (160 sectors)
someprocess(1877): WRITE block 2671126528 on bcache2 (160 sectors)

接下来就是对这些日志进行分析,这时就用到了 iodump 脚本:

while true; do sleep 1; dmesg -c; done | perl iodump

这时候可能会出错:

-bash: perl: command not found

oho,这台机器没有 perl 环境,好吧,接着装一个好了:

wget http://www.cpan.org/src/5.0/perl-5.26.1.tar.gz
tar zxvf perl-5.26.1.tar.gz
cd perl-5.26.1
./Configure -des -Dprefix=./localperl
make test
make install

然后添加环境变量:

  
export PATH=$PATH:/root/mydir/localperl/bin

重新执行命令:

  
while true; do sleep 1; dmesg -c; done | perl iodump

又抛错了?纳尼?

  
Can't locate strict.pm in @INC (you may need to install the strict module) (@INC contains: /root/mydir/localperl/lib/site_perl/5.20.1/x86_64-linux /root/mydir/localperl/lib/site_perl/5.20.1 /root/mydir/localperl/lib/5.20.1/x86_64-linux /root/mydir/localperl/lib/5.20.1 .) at iodump line 34

好吧,设置下库路径:

export PERL5LIB=$PERL5LIB:/root/mydir/localperl/lib

重新运行命令,正常的话可以看到下面的输出:

[root@localhost]# while true; do sleep 1; dmesg -c; done | ./localperl/bin/perl iodump
TASK                   PID      TOTAL       READ      WRITE      DIRTY DEVICES
someproce             1877       7236       5923       1313          0 sda3
someproce             1879       7206       5877       1329          0 sda3
jbd2/sda3-8           1241        235          0        235          0 sda3
kworker/u16:2       949469         84          0         84          0 sda3, sda1
jbd2/sda1-8            509         82          0         82          0 sda1
edge-speeds-ale    1265169          3          0          3          0 sda3
falcon-agent          4144          2          0          2          0 sda3
falcon-agent          1831          1          0          1          0 sda3
wc                 1266086          1          0          1          0 sda3
curl               1266655          1          0          1          0 sda3
curl               1265033          1          0          1          0 sda3
wc                 1266089          1          0          1          0 sda3
falcon-agent        116709          1          0          1          0 sda3
bash               1264583          1          0          1          0 sda1
falcon-agent          4142          1          0          1          0 sda3
wc                 1266083          1          0          1          0 sda3
falcon-agent          4150          1          0          1          0 sda3
falcon-agent        116710          1          0          1          0 sda3

 

统计结果很明白了,I/O 频繁的进程自然是导致 IOWAIT% 偏高的原因,那么根本原因还是硬件性能不足,磁盘 SSD 性能退化问题。

 

回顾

整个探究过程经过了大概3天左右的时间,相对来说还是有点复杂,有些时候信息太多也不是一件好事,因为太多的信息反而会让你忽视掉一些东西,我说的是小米监控上的数据,小米监控上的指标太多了,而且精度也不算很高。探究问题的过程就是慢慢的把复杂的繁杂的信息简化剥离成清晰明了的东西。没错!

发表评论

电子邮件地址不会被公开。 必填项已用*标注