标签：03 负载 0.00 named 排查 puppet 服务器 root 0t0

事情起因

公司内部的一台 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

本站声明： 1. iCode9 技术分享网（下文简称本站）提供的所有内容，仅供技术学习、探讨和分享；
2. 关于本站的所有留言、评论、转载及引用，纯属内容发起人的个人观点，与本站观点和立场无关；
3. 关于本站的所有言论和文字，纯属内容发起人的个人观点，与本站观点和立场无关；
4. 本站文章均是网友提供，不完全保证技术分享内容的完整性、准确性、时效性、风险性和版权归属；如您发现该文章侵犯了您的权益，可联系我们第一时间进行删除；
5. 本站为非盈利性的个人网站，所有内容不会用来进行牟利，也不会利用任何形式的广告来间接获益，纯粹是为了广大技术爱好者提供技术内容和技术思想的分享性交流网站。