通過blktrace, debugfs分析磁碟IO

http://www.07net01.com/2014/09/71589.html

前幾天微博上有同學問我磁碟util達到了100%時程式效能下降的問題，由於資訊實在有限，我也沒有辦法幫太大的忙，這篇blog只是想給他列一下在磁碟util很高的時候如何通過blktrace+debugfs找到發生IO的檔案，然後再結合自己的應用程式，分析出這些IO到底是誰產生的，最終目的當然是儘量減少不必要的IO干擾，提高程式的效能。

blktrace是Jens Axobe寫的一個跟蹤IO請求的工具，Linux系統發起的IO請求都可以通過blktrace捕獲並分析，關於這個工具的介紹請自行google之，這裡推薦我們部門的褚霸同學的blog，裡面有好幾篇文章分別介紹了blktrace, blkparse以及blkiomon等工具的使用。

debugfs是ext2, ext3, ext4檔案系統提供的檔案系統訪問工具，通過它我們可以不通過mount檔案系統而直接訪問檔案系統的內容，它是e2fsprogs的一部分，預設應該都是安裝的，詳細的說明可以通過man debugfs得到。

下面我來演示一下如何通過這兩個工具的配合來找到磁碟IO的源頭。

先看一個簡單的例子：
在一個終端會輸入如下命令：
while [ 1 ];do dd if=/dev/zero of=test_file bs=4k count=20 seek=$RANDOM oflag=sync;done
隨機的在test_file裡面寫資料造成較大的IO壓力，現在看看如何通過blktrace和debugfs抓到它。

1. 通過iostat觀察到有很大的磁碟壓力
Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util
sdb 0.00 2759.00 0.00 3515.50 0.00 50196.00 14.28 0.90 0.26 0.24 85.70

2. 我們看到sdb壓力很大，這時候就需要通過blktrace抓取對應盤的資料
blktrace /dev/sdb 有IO壓力的時候一會兒就可以了，通過ctrl+c停止抓取。
blktrace是需要debugfs支援的，如果系統提示debugfs沒有mount，需要先mount上
mount -t debugfs none /sys/kernel/debug 再執行blktrace命令

3. 將blktrace抓出來的二進位制檔案轉成文字格式。
blkparse sdb.blktrace.* > 1.log

4. 開始分析日誌
grep ‘ A ‘ 1.log|head -n 5

8,16 0 39 0.001242727 2872 A WS 420143 + 8 <- (8,17) 420080
8,16 0 52 0.001361766 2872 A WS 420151 + 8 <- (8,17) 420088
8,16 0 65 0.001440210 2872 A WS 420159 + 8 <- (8,17) 420096
8,16 0 78 0.001518207 2872 A WS 420167 + 8 <- (8,17) 420104
8,16 0 91 0.001596083 2872 A WS 420175 + 8 <- (8,17) 420112

為啥要grep ‘ A ‘呢？因為這條資訊是上層一個讀寫請求進入到Linux IO協議棧的第一步，只有在這裡我們可以看到清晰的請求原始資訊。比如
8,16 0 39 0.001242727 2872 A WS 420143 + 8 <- (8,17) 420080
這條說明是裝置（8，17）也就是sdb1上產生的扇區為420080的寫請求（讀請求的話會在WS對應的位置出現‘R’），長度是8，它被對映到（8，16）上位置為420143。這個IO請求的完整生命週期是這樣的：
8,16 0 39 0.001242727 2872 A WS 420143 + 8 <- (8,17) 420080
8,16 0 41 0.001244984 2872 G WS 420143 + 8 [dd]
8,16 0 43 0.001246609 2872 I WS 420143 + 8 [dd]
8,16 0 45 0.001255064 2872 D WS 420143 + 8 [dd]
8,16 0 46 0.001325168 0 C WS 420143 + 8 [0]
可以看到從’ A ‘的下一條開始都是以整個裝置的扇區號為標識的，不方便我們找到對應的分割槽。

5. 下面就開始通過debugfs來分析這條讀寫請求的來源了。
(8, 17)是sdb1, 420080是扇區號(IO層的基本單位是扇區sector，大小是512bytes)，而檔案系統層是通過塊block來管理的，一般的ext3,ext4的塊block大小是4096[1]，由此可得這個請求對應到檔案系統的塊block號是420080/8=52510, debugfs提供了命令icheck可以通過block號找到它對應的檔案的inode。
#debugfs -R ‘icheck 52510′ /dev/sdb1
debugfs 1.43-WIP (1-Aug-2012)
BlockInode number
5251012

6. 通過inode number找到對應的檔名，很幸運，debugfs又提供了另外一條命令ncheck可以找到inode對應的檔名[2]。
#debugfs -R ‘ncheck 12′ /dev/sdb1
debugfs 1.43-WIP (1-Aug-2012)
InodePathname
12//test_file
大家可以看到，我們現在已經成功找到了test_file這個檔案啦，至此塊裝置層和檔案系統層的分析工作已經結束了，下面就可以結合應用看看為啥會對這個檔案有如此頻繁的讀寫操作了！

[1] 塊大小實際上也能夠通過debugfs來得到。
debugfs -R ‘stats’ /dev/sdb1|grep “Block size”
[2] 有的同學找到的inode number是8，然後卻無法找到對應的檔名。這是因為8是ext3/4檔案系統中的日誌檔案的inode，它是隱藏檔案，所以無法找到，可以再試試其他的block號哦！