linux 系統監控、診斷工具之 IO wait

作者：xrzs 2014-12-15 10:06:13

系統 Linux 系統運維

最近在做日志的實時同步，上線之前是做過單份線上日志壓力測試的，消息隊列和客戶端、本機都沒問題，但是沒想到上了第二份日志之后，問題來了……

1、問題：

最近在做日志的實時同步，上線之前是做過單份線上日志壓力測試的，消息隊列和客戶端、本機都沒問題，但是沒想到上了第二份日志之后，問題來了：

集群中的某臺機器 top 看到負載巨高，集群中的機器硬件配置一樣，部署的軟件都一樣，卻單單這一臺負載有問題，初步猜測可能硬件有問題了。

同時，我們還需要把負載有異常的罪魁禍首揪出來，到時候從軟件、硬件層面分別尋找解決方案。

2、排查：

從 top 中可以看到 load average 偏高，%wa 偏高，%us 很低：

從上圖我們大致可以推斷 IO 遇到了瓶頸，下面我們可以再用相關的 IO 診斷工具，具體的驗證排查下。

PS：如果你對 top 的用法不了解，請參考我去年寫的一篇博文：

linux 系統監控、診斷工具之 top 詳解

常用組合方式有如下幾種：

• 用vmstat、sar、iostat檢測是否是CPU瓶頸
• 用free、vmstat檢測是否是內存瓶頸
• 用iostat、dmesg 檢測是否是磁盤I/O瓶頸
• 用netstat檢測是否是網絡帶寬瓶頸

2.1 vmstat

vmstat命令的含義為顯示虛擬內存狀態（“Viryual Memor Statics”），但是它可以報告關于進程、內存、I/O等系統整體運行狀態。

它的相關字段說明如下：

Procs（進程）  
• r: 運行隊列中進程數量，這個值也可以判斷是否需要增加CPU。（長期大于1）  
• b: 等待IO的進程數量，也就是處在非中斷睡眠狀態的進程數，展示了正在執行和等待CPU資源的任務個數。當這個值超過了CPU數目，就會出現CPU瓶頸了  
   
Memory（內存）  
• swpd: 使用虛擬內存大小，如果swpd的值不為0，但是SI，SO的值長期為0，這種情況不會影響系統性能。  
• free: 空閑物理內存大小。  
• buff: 用作緩沖的內存大小。  
• cache: 用作緩存的內存大小，如果cache的值大的時候，說明cache處的文件數多，如果頻繁訪問到的文件都能被cache處，那么磁盤的讀IO bi會非常小。  
   
Swap  
• si: 每秒從交換區寫到內存的大小，由磁盤調入內存。  
• so: 每秒寫入交換區的內存大小，由內存調入磁盤。  
注意：內存夠用的時候，這2個值都是0，如果這2個值長期大于0時，系統性能會受到影響，磁盤IO和CPU資源都會被消耗。有些朋友看到空閑內存（free）很少的或接近于0時，就認為內存不夠用了，不能光看這一點，還要結合si和so，如果free很少，但是si和so也很少（大多時候是0），那么不用擔心，系統性能這時不會受到影響的。  
   
IO（現在的Linux版本塊的大小為1kb）  
• bi: 每秒讀取的塊數  
• bo: 每秒寫入的塊數  
注意：隨機磁盤讀寫的時候，這2個值越大（如超出1024k)，能看到CPU在IO等待的值也會越大。  
   
system（系統）  
• in: 每秒中斷數，包括時鐘中斷。  
• cs: 每秒上下文切換數。  
注意：上面2個值越大，會看到由內核消耗的CPU時間會越大。  
   
CPU（以百分比表示）  
• us: 用戶進程執行時間百分比(user time)  
us的值比較高時，說明用戶進程消耗的CPU時間多，但是如果長期超50%的使用，那么我們就該考慮優化程序算法或者進行加速。  
• sy: 內核系統進程執行時間百分比(system time)  
sy的值高時，說明系統內核消耗的CPU資源多，這并不是良性表現，我們應該檢查原因。  
• wa: IO等待時間百分比  
wa的值高時，說明IO等待比較嚴重，這可能由于磁盤大量作隨機訪問造成，也有可能磁盤出現瓶頸（塊操作）。  
• id: 空閑時間百分比

從 vmstat 中可以看到，CPU大部分的時間浪費在等待IO上面，可能是由于大量的磁盤隨機訪問或者磁盤的帶寬所造成的，bi、bo 也都超過 1024k，應該是遇到了IO瓶頸。

2.2 iostat

下面再用更加專業的磁盤 IO 診斷工具來看下相關統計數據。

它的相關字段說明如下：

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的單位為毫秒)

可以看到兩塊硬盤中的 sdb 的利用率已經 100%，存在嚴重的 IO 瓶頸，下一步我們就是要找出哪個進程在往這塊硬盤讀寫數據。

2.3 iotop

根據 iotop 的結果，我們迅速的定位到是 flume 進程的問題，造成了大量的 IO wait。

但是在開頭我已經說了，集群中的機器配置一樣，部署的程序也都 rsync 過去的一模一樣，難道是硬盤壞了？

這得找運維同學來查證了，***的結論是：

Sdb為雙盤raid1，使用raid卡為“LSI Logic / Symbios Logic SAS1068E”，無cache。近400的IOPS壓力已經達到了硬件極限。而其它機器使用的raid卡是“LSI Logic / Symbios Logic MegaRAID SAS 1078”，有256MB cache，并未達到硬件瓶頸，解決辦法是更換能提供更大IOPS的機器。

不過前面也說了，我們從軟硬件兩方面著手的目的就是看能否分別尋求代價最小的解決方案：

知道硬件的原因了，我們可以嘗試把讀寫操作移到另一塊盤，然后再看看效果：

3、***的話：另辟蹊徑

其實，除了用上述專業的工具定位這個問題外，我們可以直接利用進程狀態來找到相關的進程。

我們知道進程有如下幾種狀態：

PROCESS STATE CODES  
 D uninterruptible sleep (usually IO)  
 R running or runnable (on run queue)  
 S interruptible sleep (waiting for an event to complete)  
 T stopped, either by a job control signal or because it is being traced.  
 W paging (not valid since the 2.6.xx kernel)  
 X dead (should never be seen)  
 Z defunct ("zombie") process, terminated but not reaped by its parent.

其中狀態為 D 的一般就是由于 wait IO 而造成所謂的”非中斷睡眠“，我們可以從這點入手然后一步步的定位問題：

for x in `seq 10`; do ps -eo state,pid,cmd | grep "^D"; echo "----"; sleep 5; done  
 D 248 [jbd2/dm-0-8]  
 D 16528 bonnie++ -n 0 -u 0 -r 239 -s 478 -f -b -d /tmp  
 ----  
 D 22 [kdmflush]  
 D 16528 bonnie++ -n 0 -u 0 -r 239 -s 478 -f -b -d /tmp  
 ----  
# 或者：  
while true; do date; ps auxf | awk '{if($8=="D") print $0;}'; sleep 1; done  
 Tue Aug 23 20:03:54 CLT 2011  
 root       302  0.0  0.0      0     0 ?        D    May22   2:58  \_ [kdmflush]  
 root       321  0.0  0.0      0     0 ?        D    May22   4:11  \_ [jbd2/dm-0-8]  
 Tue Aug 23 20:03:55 CLT 2011  
 Tue Aug 23 20:03:56 CLT 2011  
   
cat /proc/16528/io  
 rchar: 48752567  
 wchar: 549961789  
 syscr: 5967  
 syscw: 67138  
 read_bytes: 49020928  
 write_bytes: 549961728  
 cancelled_write_bytes: 0  
    
lsof -p 16528  
 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME  
 bonnie++ 16528 root cwd DIR 252,0 4096 130597 /tmp  
 <truncated>  
 bonnie++ 16528 root 8u REG 252,0 501219328 131869 /tmp/Bonnie.16528  
 bonnie++ 16528 root 9u REG 252,0 501219328 131869 /tmp/Bonnie.16528  
 bonnie++ 16528 root 10u REG 252,0 501219328 131869 /tmp/Bonnie.16528  
 bonnie++ 16528 root 11u REG 252,0 501219328 131869 /tmp/Bonnie.16528  
 bonnie++ 16528 root 12u REG 252,0 501219328 131869 <strong>/tmp/Bonnie.16528</strong>  
    
df /tmp  
 Filesystem 1K-blocks Used Available Use% Mounted on  
 /dev/mapper/workstation-root 7667140 2628608 4653920 37% /  
    
fuser -vm /tmp  
        USER        PID ACCESS COMMAND  
 /tmp:  db2fenc1   1067 ....m db2fmp  
        db2fenc1   1071 ....m db2fmp  
        db2fenc1   2560 ....m db2fmp  
        db2fenc1   5221 ....m db2fmp