问题描述

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

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

探究过程

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

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

分析途径

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

小米监控
各种linux命令 && 各种代码技能
一颗充满兴趣的心（最重要的东西）

初步怀疑

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

小米监控的agent是每分钟采集一次数据，具体的计算方法应该是分析 /proc/stat 文件。包括top命令也是分析这个文件得出的cpu占用率。那么我自己来分析这个文件试试。核心代码部分如下：

cmd = 'cat /proc/stat |grep "cpu "'
ret = os.popen(cmd).readlines()[0]
ret = ret.split()
ret = ret[1:]
total = 0
for i in ret:
  total += int(i)

user = int(ret[0])
nice = int(ret[1])
system = int(ret[2])
idle = int(ret[3])
iowait = int(ret[4])
irq = int(ret[5])
softirq = int(ret[6])
cpubusy = total - idle


user = float(user / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
nice = float(nice / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
system = float(system / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
idle = float(idle / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
iowait = float(iowait / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
irq = float(irq / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
softirq = float(softirq / os.sysconf(os.sysconf_names['SC_CLK_TCK']))
cpubusy = float(cpubusy / os.sysconf(os.sysconf_names['SC_CLK_TCK']))

timestamp = int(time.time())

STORE['user'] = user
STORE['nice'] = nice
STORE['system'] = system
STORE['idle'] = idle
STORE['iowait'] = iowait
STORE['irq'] = irq
STORE['softirq'] = softirq
STORE['cpubusy'] = cpubusy

STORE['timestamp'] = timestamp
with open(CPUSTORE,'w') as fout:
  fout.write(json.dumps(STORE))

采集到的数据先暂存到redis:

t1 = result.get('timestamp')
t1 = int(t1)
l1 = time.localtime(t1)
d1 = time.strftime('%d%H%M%S', l1)
hostname = os.uname()[1]
skey = 'scpu_%s' % hostname
hkey = 'cpu_%s_%s' % (hostname,d1)
r.sadd(skey,hkey)
r.hset(hkey,'timestamp',d1)
r.hset(hkey,'cpubusy',result.get('cpubusy'))
r.hset(hkey,'user',result.get('user'))
r.hset(hkey,'nice',result.get('nice'))
r.hset(hkey,'system',result.get('system'))
r.hset(hkey,'idle',result.get('idle'))
r.hset(hkey,'iowait',result.get('iowait'))
r.hset(hkey,'irq',result.get('irq'))
r.hset(hkey,'softirq',result.get('softirq'))
#每隔5s采集一次
time.sleep(5)

所以最终redis里面的数据如下所示：
有了数据，现在就缺一个前端的展示，很简单，highcharts用起来，最终前端展示得到的曲线如下图：

可以看到这台机器的cpu.iowait确实波动很厉害，说明小米监控的agent采集到的数据是准确的。

那么：

什么是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的各项参数解释如下：

rrqm/s:  	每秒进行 merge 的读操作数目。即 delta(rmerge)/s
wrqm/s:		每秒进行 merge 的写操作数目。即 delta(wmerge)/s
r/s:		每秒完成的读 I/O 设备次数。即 delta(rio)/s
w/s:		每秒完成的写 I/O 设备次数。即 delta(wio)/s
rsec/s:		每秒读扇区数。即 delta(rsect)/s
wsec/s:		每秒写扇区数。即 delta(wsect)/s
rkB/s:		每秒读K字节数。是 rsect/s 的一半，因为每扇区大小为512字节。(需要计算)
wkB/s:		每秒写K字节数。是 wsect/s 的一半。(需要计算)
avgrq-sz:	平均每次设备I/O操作的数据大小 (扇区)。delta(rsect+wsect)/delta(rio+wio)
avgqu-sz:	平均I/O队列长度。即 delta(aveq)/s/1000 (因为aveq的单位为毫秒)。
await:		平均每次设备I/O操作的等待时间 (毫秒)。即 delta(ruse+wuse)/delta(rio+wio)
svctm:		平均每次设备I/O操作的服务时间 (毫秒)。即 delta(use)/delta(rio+wio)
%util:		一秒中有百分之多少的时间用于 I/O 操作，或者说一秒中有多少时间 I/O 队列是非空的。即 delta(use)/s/1000 (因为use的单位为毫秒)

其中重点需要关注的是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)

最终得到的结果如下：

2017-12-14 10:36:25 root      378315  0.0  0.0      0     0 ?        D    10:27   0:00  \_ [kworker/5:18]
2017-12-14 10:36:25 root      378337  0.0  0.0      0     0 ?        D    10:27   0:00  \_ [kworker/7:34]
2017-12-14 10:36:25 root      378339  0.0  0.0      0     0 ?        D    10:27   0:00  \_ [kworker/7:36]
2017-12-14 10:36:25 root      378340  0.0  0.0      0     0 ?        D    10:27   0:00  \_ [kworker/7:37]
2017-12-14 10:36:25 root      378343  0.0  0.0      0     0 ?        D    10:27   0:00  \_ [kworker/7:40]
2017-12-14 10:36:25 root      378344  0.0  0.0      0     0 ?        D    10:27   0:00  \_ [kworker/7:41]
2017-12-14 10:36:25 root      382918  0.0  0.0      0     0 ?        D    10:31   0:00  \_ [kworker/3:1]
2017-12-14 10:36:25 root      383821  0.0  0.0      0     0 ?        D    10:31   0:00  \_ [kworker/6:8]
2017-12-14 10:36:25 root      384627  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/3:2]
2017-12-14 10:36:25 root      384638  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/3:3]
2017-12-14 10:36:25 root      384640  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/0:0]
2017-12-14 10:36:25 root      384642  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/4:0]
2017-12-14 10:36:25 root      384643  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/4:1]
2017-12-14 10:36:25 root      384644  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/4:3]
2017-12-14 10:36:25 root      384645  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/4:4]
2017-12-14 10:36:25 root      384654  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/2:10]
2017-12-14 10:36:25 root      384655  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/2:11]
2017-12-14 10:36:25 root      384656  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/2:12]
2017-12-14 10:36:25 root      384659  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/5:1]
2017-12-14 10:36:25 root      384660  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/5:2]
2017-12-14 10:36:25 root      384661  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/5:3]
2017-12-14 10:36:25 root      384662  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/5:4]
2017-12-14 10:36:25 root      384663  0.0  0.0      0     0 ?        D    10:32   0:00  \_ [kworker/5:5]
2017-12-14 10:36:25 root      393220  0.0  0.0      0     0 ?        D    10:36   0:00  \_ [kworker/3:4]
2017-12-14 10:36:25 root      393222  0.0  0.0      0     0 ?        D    10:36   0:00  \_ [kworker/3:5]
2017-12-14 10:36:25 nobody   2646439  2.5  1.1 2626256 191388 ?      D    Dec04 369:05      \_ nginx: worker process
2017-12-14 10:36:25 nobody   2646440  2.9  1.1 2029968 185368 ?      D    Dec04 422:39      \_ nginx: worker process
2017-12-14 10:36:25 nobody   2646441  2.5  1.2 3371008 208164 ?      D    Dec04 363:58      \_ nginx: worker process
2017-12-14 10:36:25 nobody   2646442  3.4  1.1 2337132 188544 ?      D    Dec04 490:30      \_ nginx: worker process
2017-12-14 10:36:25 nobody   2646443  2.5  1.1 2646092 195748 ?      D    Dec04 371:57      \_ nginx: worker process
2017-12-14 10:36:25 nobody   2646445  4.6  1.1 2576596 195664 ?      D    Dec04 662:33      \_ nginx: worker process

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

使用iotop

这台机器没有这个工具，本地下载了iotop的源码包后传上去，运行抛错：

1
2
3

Could not run iotop as some of the requirements are not met:
- Linux >= 2.6.20 with
  - I/O accounting support (CONFIG_TASKSTATS, CONFIG_TASK_DELAY_ACCT, CONFIG_TASK_IO_ACCOUNTING)

错误的原因很明显，内核版本不对，因为这台机器是裁剪了linux内核并重新进行了命名，那么怎么办？

也很简单，修改iotop/data.py，注释掉下面这段代码就行，骗一下iotop:

'''
if not ioaccounting or not vm_event_counters:
    print('Could not run iotop as some of the requirements are not met:')
    print('- Linux >= 2.6.20 with')
    if not ioaccounting:
        print('  - I/O accounting support ' \
          '(CONFIG_TASKSTATS, CONFIG_TASK_DELAY_ACCT, ' \
          'CONFIG_TASK_IO_ACCOUNTING)')
    if not vm_event_counters:
        print('  - VM event counters (CONFIG_VM_EVENT_COUNTERS)')
    sys.exit(1)
'''

iotop命令的使用很简单，我常用命令：

1	python iotop.py -o

-o参数表示：only show processes or threads actually doing I/O。

在寻找进行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是什么？谷歌了一番：

what is kworker

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

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

最终结论

经过上述的探究，可以得到如下的结论：

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

回顾

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

林夕水共

CPU.IOWAIT 偏高问题