記一次服務器負載太高的排查過程

時間 2021-03-16

標籤 node ios git 服務器 session 架構 app ssh socket ide 欄目負載均衡简体版

原文原文鏈接

事情原由

公司內部的一臺 DNS 服務器,運行在 Xen 的虛擬機上，僅僅運行了 Bind 服務，但常常有 CPU 負載太高的報警，一樣配置的其餘 Bind 服務器卻沒有這種狀況。node

排查過程

首先看了一下內存使用正常，swap 基本沒用，由於是階段性的出現這個問題，使用 top 命令當時也沒有看到服務器的負載有異常，但從 load average 看到最近的 15 分鐘負載確實有一點高。ios

因而我使用 dmesg 命令看了一下最近時間段也沒有異常信息，又使用 sar 命令查看了該服務器近幾個小時的負載狀況，如下是我截取了輸出結果中的一小部分：git

# 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 呢?session

說到這裏，須要說明一下，咱們內部的配置管理使用的 puppet，並非使用的 C/S 架構，而是將寫好的 manifest.pp 文件，相關 erb 模塊的文件以及相關聯的腳本和其餘文件，一塊兒放在了存儲服務器的指定目錄下，而後每一個服務器和工做站經過 NFS 掛載存儲的這個指定目錄。計劃任務按期執行：# puppet apply /nfs/manifests/ 命令讀取 NFS 掛載目錄下的的 puppet 文件，並根據 facter 獲取變量來執行對應的配置，每一個機器上的計劃任務時間的間隔都是固定的 15 分鐘運行一次，可是時間點是隨機生成的，每一個機器的運行的時間點是不相同的，並且腳本運行很快。架構

帶着運行 puppet 計劃任務形成 IO 負載高的問題，我又去 Git 代碼中看了一下與 DNS 有關的 manifest 文件，看這個文件最近也沒有更改提交記錄，暫時沒看到問題。dns_server.pp 部分配置內容以下：app

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 運行時的詳細的文件讀取調用狀況，命令以下：ssh

# 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 操做：socket

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 命令查看對應的文件描述符號被哪些進程在使用，執行結果以下：ide

# 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 操做。

至此，該服務器負載常常太高的緣由找到。