记一次DNS服务器负载过高的排查过

事情起因

公司内部的一台 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     %idle00时10分02秒     all      8.13      0.00      3.74      1.54      0.48     86.1200时20分03秒     all     14.78      0.00      4.44      8.50      0.50     71.7800时30分02秒     all     12.67      0.00      4.15      6.86      0.79     75.5200时40分03秒     all      8.12      0.00      3.82      1.88      0.40     85.7800时50分01秒     all     14.09      0.00      4.57      8.60      0.39     72.3501时00分03秒     all     10.88      0.00      4.18      7.34      0.38     77.2201时10分03秒     all      6.92      0.00      3.83      1.33      0.39     87.5301时20分02秒     all     12.22      0.00      4.32      8.53      0.35     74.5701时30分01秒     all      9.93      0.00      4.05      7.57      0.35     78.1101时40分03秒     all      5.24      0.00      3.66      1.00      0.35     89.7501时50分03秒     all     12.63      0.00      4.47      8.75      0.37     73.7902时00分02秒     all     11.03      0.00      4.24      7.19      0.39     77.1402时10分03秒     all      7.75      0.00      4.08      1.60      0.40     86.1702时20分03秒     all     13.12      0.00      4.44      8.58      0.38     73.4802时30分03秒     all     11.31      0.00      4.20      7.33      0.41     76.7502时40分01秒     all      6.64      0.00      3.81      1.55      0.37     87.6302时50分03秒     all     13.93      0.00      4.65     16.83      0.41     64.1803时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-03auditd      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 socketrsyslogd    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 pipexinetd      915    root    7u     unix 0xffff88007a353480      0t0     14856 socketsnmpd       918    root    7u     IPv4              18022      0t0       TCP localhost:smux (LISTEN)
tuned       921    root    7u     unix 0xffff880079ca6900      0t0     18268 socketlsof       1422    root    7w     FIFO                0,8      0t0 148964654 pipemaster     2164    root    7u      CHR                1,3      0t0      1028 /dev/null
qmgr       2166 postfix    7u     unix 0xffff88007a352d00      0t0     17090 socketnetdata    2183 netdata    7r     FIFO                0,8      0t0 148956393 pipepickup    20645 postfix    7u     unix 0xffff880079bdb480      0t0 148867919 socketsshd      22488    root    7w     FIFO                0,8      0t0 148879645 pipenamed     25577   named    7w     FIFO                0,8      0t0  91067709 pipesshd      29010    root    7w     FIFO                0,8      0t0 148932044 pipeshowq     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

©著作权归作者所有：来自51CTO博客作者liubin0505star的原创作品，如需转载，请注明出处，否则将追究法律责任

如果文章对你有帮助，请赞赏