记一次服务器负载过高的排查过程
作者：互联网
事情起因
公司内部的一台 DNS 服务器,运行在 Xen 的虚拟机上，仅仅运行了 Bind 服务，但经常有 CPU 负载过高的报警，同样配置的其他 Bind 服务器却没有这种情况。
排查过程
首先看了一下内存使用正常，swap 基本没用，因为是阶段性的出现这个问题，使用 top 命令当时也没有看到服务器的负载有异常，但从 load average 看到最近的 15 分钟负载确实有一点高。
于是我使用 dmesg 命令看了一下最近时间段也没有异常信息，又使用 sar 命令查看了该服务器近几个小时的负载情况，以下是我截取了输出结果中的一小部分：
# sar -u
Linux 3.10.0-327.4.5.el7.x86_64 2019年04月03日 _x86_64_ (2 CPU)
00时00分03秒 CPU %user %nice %system %iowait %steal %idle
00时10分02秒 all 8.13 0.00 3.74 1.54 0.48 86.12
00时20分03秒 all 14.78 0.00 4.44 8.50 0.50 71.78
00时30分02秒 all 12.67 0.00 4.15 6.86 0.79 75.52
00时40分03秒 all 8.12 0.00 3.82 1.88 0.40 85.78
00时50分01秒 all 14.09 0.00 4.57 8.60 0.39 72.35
01时00分03秒 all 10.88 0.00 4.18 7.34 0.38 77.22
01时10分03秒 all 6.92 0.00 3.83 1.33 0.39 87.53
01时20分02秒 all 12.22 0.00 4.32 8.53 0.35 74.57
01时30分01秒 all 9.93 0.00 4.05 7.57 0.35 78.11
01时40分03秒 all 5.24 0.00 3.66 1.00 0.35 89.75
01时50分03秒 all 12.63 0.00 4.47 8.75 0.37 73.79
02时00分02秒 all 11.03 0.00 4.24 7.19 0.39 77.14
02时10分03秒 all 7.75 0.00 4.08 1.60 0.40 86.17
02时20分03秒 all 13.12 0.00 4.44 8.58 0.38 73.48
02时30分03秒 all 11.31 0.00 4.20 7.33 0.41 76.75
02时40分01秒 all 6.64 0.00 3.81 1.55 0.37 87.63
02时50分03秒 all 13.93 0.00 4.65 16.83 0.41 64.18
03时00分04秒 all 10.70 0.00 4.13 7.50 0.41 77.25通过上述结果可以看到 CPU 的 %idle 说明 CPU 使用率并不高，但是 %iowait 确实有点过高，可能存在 I/O 问题，此时我又登陆了该 DNS 服务运行虚拟机所在的物理机上以同样的方式查看了一下，发现物理机的负载都很低，使用 dmesg 命令也没有过滤到报错，也确认了物理机磁盘没有问题。
因为上面的结果中也可以看到 iowait 是阶段性的。于是又打开了一个终端，使用命令 # iostat -dx 2 持续观察了一下系统的 IO 情况，通过输出结果看到 r/s 和 rkB/s 参考项的值会在一端时间内增加很多，%util 有时也过了 60%，这说明磁盘短时间内有大量的读操作，此时也结合了 iotop 命令一直在观察，发现添加到计划任务的 puppet 在运行的时候占用了大量的 IO，而且持续了两三分钟，且 puppet 的 DISK READ 和 IO 百分比的值都很高。基本确认了这个机器的负载过高与周期运行在本机的 puppet 有关从而导致的 IO 过高，但是我们所有的工作站和服务器都运行的 puppet，为什么单单这个机器上的 puppet 脚本运行占用这么长时间和大量的读 IO 呢?
说到这里，需要说明一下，我们内部的配置管理使用的 puppet，并不是使用的 C/S 架构，而是将写好的 manifest.pp 文件，相关 erb 模块的文件以及相关联的脚本和其他文件，一起放在了存储服务器的指定目录下，然后每个服务器和工作站通过 NFS 挂载存储的这个指定目录。计划任务定期执行：# puppet apply /nfs/manifests/ 命令读取 NFS 挂载目录下的的 puppet 文件，并根据 facter 获取变量来执行对应的配置，每个机器上的计划任务时间的间隔都是固定的 15 分钟运行一次，但是时间点是随机生成的，每个机器的运行的时间点是不相同的，而且脚本运行很快。
带着运行 puppet 计划任务造成 IO 负载高的问题，我又去 Git 代码中看了一下与 DNS 有关的 manifest 文件，看这个文件最近也没有更改提交记录，暂时没看到问题。dns_server.pp 部分配置内容如下：
class wdroot::dns_master_server {
package{'bind': }->
file{'zones':
path =>'/var/named/zones',
source => "$git_files/var/named/zones",
recurse => true ,
ensure => directory ,
}->
file{'zones backup':
path =>'/var/named/zones/backup',
ensure => directory ,
owner => 'named',
group => 'named',
mode => 0777
}->
file{'reverse.conf':
path => '/var/named/zones/reverse.conf',
ensure => file,
owner => 'named',
group => 'named'
}->
file{'system.log':
path => '/var/log/system.log',
ensure => file,
owner => 'named',
group => 'named'
}->
file{'named.log':
path => '/var/log/named.log',
ensure => file,
owner => 'named',
group => 'named'
}->
file{'named config file':
path => '/etc/named.conf',
content => template("$git_files/etc/named.conf.erb"),
owner => 'named',
group => 'named',
backup => true,
}~>
service{'named':}然后又通过 strace 命令追踪 puppet 运行时的详细的文件读取调用情况，命令如下：
# strace -T -tt -e trace=all -p $(ps -ef | grep puppet | grep -v grep | awk '{print $2}')其中 -p 参数是跟踪 puppet 进程 id 的所有系统调用（-e trace=all），这里也就是获取的我手动运行 puppet 时候的进程。通过追踪发现大量的时间都耗费在 read 操作：
16:12:53.059111 read(7, "", 2863) = 0 <0.000051>
16:12:53.059235 read(7, "", 4096) = 0 <0.000078>
16:12:53.059417 close(7) = 0 <0.000054>
16:12:53.059700 lstat("/var/named/zones/backup/wdroot.com.db._old_18-07-19-08-19-46", {st_mode=S_IFREG|0755, st_size=512378, ...}) = 0 <0.000084>
16:12:53.059992 open("/var/named/zones/backup/wdroot.com.db._old_18-07-19-08-19-46", O_RDONLY|O_CLOEXEC) = 7 <0.000124>
16:12:53.060251 fcntl(7, F_GETFD) = 0x1 (flags FD_CLOEXEC) <0.000064>
16:12:53.060401 fstat(7, {st_mode=S_IFREG|0755, st_size=512378, ...}) = 0 <0.000074>
16:12:53.060592 ioctl(7, SNDCTL_TMR_TIMEBASE or SNDRV_TIMER_IOCTL_NEXT_DEVICE or TCGETS, 0x7ffdbe2d45f0) = -1 ENOTTY (Inappropriate ioctl for device) <0.000059>通过追踪发现一直有大量的类似文件状态校验和文件读操作，我截取了其中一小部分 strace 追踪的信息，输出信息中能够看到，对应的文件描述符编号是 7，于是使用 lsof 命令查看对应的文件描述符号被哪些进程在使用，执行结果如下：
# lsof -d 7
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
systemd 1 root 7u a_inode 0,9 0 5818 [timerfd]
systemd-j 494 root 7u a_inode 0,9 0 5818 [eventpoll]
systemd-u 533 root 7r a_inode 0,9 0 5818 inotify
crond 595 root 7w FIFO 0,19 0t0 148959867 /run/systemd/sessions/93489.ref
puppet 607 root 7r REG 253,1 483669 35330998 /var/named/zones/backup/wdroot.com.db._old_18-08-02-15-43-03
auditd 629 root 7u a_inode 0,9 0 5818 [eventpoll]
systemd-l 651 root 7u a_inode 0,9 0 5818 [signalfd]
dbus-daem 653 dbus 7u unix 0xffff88003690d640 0t0 12997 socket
rsyslogd 664 root 7r REG 0,19 8388608 139703174 /run/log/journal/b249909a1cc7460a937fd98eaf756ce6/system@3f7cfe8c4b60419fb0a0e8102afcf065-000000000004d3b9-000585377a120684.journal
rpcbind 713 rpc 7u IPv4 14638 0t0 UDP *:838
gssproxy 747 root 7w FIFO 0,8 0t0 15492 pipe
xinetd 915 root 7u unix 0xffff88007a353480 0t0 14856 socket
snmpd 918 root 7u IPv4 18022 0t0 TCP localhost:smux (LISTEN)
tuned 921 root 7u unix 0xffff880079ca6900 0t0 18268 socket
lsof 1422 root 7w FIFO 0,8 0t0 148964654 pipe
master 2164 root 7u CHR 1,3 0t0 1028 /dev/null
qmgr 2166 postfix 7u unix 0xffff88007a352d00 0t0 17090 socket
netdata 2183 netdata 7r FIFO 0,8 0t0 148956393 pipe
pickup 20645 postfix 7u unix 0xffff880079bdb480 0t0 148867919 socket
sshd 22488 root 7w FIFO 0,8 0t0 148879645 pipe
named 25577 named 7w FIFO 0,8 0t0 91067709 pipe
sshd 29010 root 7w FIFO 0,8 0t0 148932044 pipe
showq 32152 postfix 7u unix 0xffff88007a352940 0t0 148952214 socket发现 puppet 好长时间都在读取 /var/named/zones/backup 目录，于是进入到了该 backup 目录发现有大量历史的 zones 备份文件，是每次修改DNS 解析记录后，脚本自动备份到 backup 目录下的。DNS 的 zone 文件是加到了 puppet 配置中，puppet 每次都在递归读取 zones 目录下的文件并校验，由于 backup 目录下的备份文件当时没有自动清理旧 zone 文件，导致 backup 目录下的 zone 文件越来越多，导致 puppet 每次都读取和校验该目录下的文件状态是否发生改变，造成了大量不必要的读 IO 操作。
至此，该服务器负载经常过高的原因找到。
总结
备份数据不要和生产环境混在一起，备份数据要单独放置并且根据实际需求保留备份文件的数量。
总结一下本次排查中涉及到的几个命令: top, iotop, iostat, sar, strace
标签：03,负载,0.00,named,排查,puppet,服务器,root,0t0 来源： https://blog.51cto.com/liubin0505star/2657009