前兩節，學了文件系統和磁盤的 I/O 原理，復習一下。文件系統，是對存儲設備上的文件進行組織管理的一種機制。為了支持各類不同的文件系統，Linux 在各種文件系統上，抽象了一層虛擬文件系統 VFS。它定義了一組所有文件系統都支持的數據結構和標準接口。這樣，應用程序和內核中的其他子系統，就只需要跟 VFS 提供的統一接口進行交互。在文件系統的下層，為了支持各種不同類型的存儲設備，Linux 又在各種存儲設備的基礎上，抽象了一個通用塊層。通用塊層，為文件系統和應用程序提供了訪問塊設備的標準接口；同時，為各種塊設備的驅動程序提供了統一的框架。此外，通用塊層還會對文件系統和應用程序發送過來的 I/O 請求進行排隊，并通過重新排序、請求合并等方式，提高磁盤讀寫的效率。通用塊層的下一層，自然就是設備層了，包括各種塊設備的驅動程序以及物理存儲設備。文件系統、通用塊層以及設備層，就構成了 Linux 的存儲 I/O 棧。存儲系統的 I/O ，通常是整個系統中最慢的一環。所以，Linux 采用多種緩存機制，來優化 I/O 的效率，比方說，

• 為了優化文件訪問的性能，采用頁緩存、索引節點緩存、目錄項緩存等多種緩存機制，減少對下層塊設備的直接調用。
• 同樣的，為了優化塊設備的訪問效率，使用緩沖區來緩存塊設備的數據。

不過，在碰到文件系統和磁盤的 I/O 問題時，具體應該怎么定位和分析呢？今天，我就以一個最常見的應用程序記錄大量日志的案例，帶你來分析這種情況。

案例準備

本次案例還是基于 Ubuntu 18.04，同樣適用于其他的 Linux 系統。我使用的案例環境如下所示：

• 機器配置：2 CPU，8GB 內存
• 預先安裝 docker、sysstat 等工具，如 apt install docker.io sysstat

這里要感謝唯品會資深運維工程師陽祥義幫忙，分擔了今天的案例。這個案例，是一個用 Python 開發的小應用，為了方便運行，我把它打包成了一個 Docker 鏡像。這樣，你只要運行 Docker 命令，就可以啟動它。接下來，打開一個終端，SSH 登錄到案例所用的機器中，并安裝上述工具。跟以前一樣，案例中所有命令，都默認以 root 用戶運行。如果你是用普通用戶身份登陸系統，請運行 sudo su root 命令，切換到 root 用戶。到這里，準備工作就完成了。接下來，我們正式進入操作環節。溫馨提示：案例中 Python 應用的核心邏輯比較簡單，你可能一眼就能看出問題，但實際生產環境中的源碼就復雜多了。所以，我依舊建議，操作之前別看源碼，避免先入為主，要把它當成一個黑盒來分析。這樣，你可以更好把握住，怎么從系統的資源使用問題出發，分析出瓶頸所在的應用，以及瓶頸在應用中大概的位置。

案例分析

首先，我們在終端中執行下面的命令，運行今天的目標應用：docker run -v /tmp:/tmp --name=app -itd feisky/logapp然后，在終端中運行 ps 命令，確認案例應用正常啟動。如果操作無誤，你應該可以在 ps 的輸出中，看到一個 app.py 的進程：ps -ef | grep /app.py root 18940 18921 73 14:41 pts/0 00:00:02 python /app.py接著，我們來看看系統有沒有性能問題。要觀察哪些性能指標呢？前面文章中，我們知道 CPU、內存和磁盤 I/O 等系統資源，很容易出現資源瓶頸，這就是我們觀察的方向了。我們來觀察一下這些資源的使用情況。當然，動手之前你應該想清楚，要用哪些工具來做，以及工具的使用順序又是怎樣的。你可以先回憶下前面的案例和思路，自己想一想，然后再繼續下面的步驟。我的想法是，我們可以先用 top ，來觀察 CPU 和內存的使用情況；然后再用 iostat ，來觀察磁盤的 I/O 情況。所以，接下來，你可以在終端中運行 top 命令，觀察 CPU 和內存的使用情況：# 按 1 切換到每個 CPU 的使用情況 top top - 14:43:43 up 1 day, 1:39, 2 users, load average: 2.48, 1.09, 0.63 Tasks: 130 total, 2 running, 74 sleeping, 0 stopped, 0 zombie %Cpu0 : 0.7 us, 6.0 sy, 0.0 ni, 0.7 id, 92.7 wa, 0.0 hi, 0.0 si, 0.0 st %Cpu1 : 0.0 us, 0.3 sy, 0.0 ni, 92.3 id, 7.3 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 8169308 total, 747684 free, 741336 used, 6680288 buff/cache KiB Swap: 0 total, 0 free, 0 used. 7113124 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 18940 root 20 0 656108 355740 5236 R 6.3 4.4 0:12.56 python 1312 root 20 0 236532 24116 9648 S 0.3 0.3 9:29.80 python3觀察 top 的輸出，你會發現，CPU0 的使用率非常高，它的系統 CPU 使用率(sys%)為 6%，而 iowait 超過了 90%。這說明 CPU0 上，可能正在運行 I/O 密集型的進程。不過，究竟是什么原因呢？這個疑問先保留著，我們先繼續看完。接著我們來看，進程部分的 CPU 使用情況。你會發現， python 進程的 CPU 使用率已經達到了 6%，而其余進程的 CPU 使用率都比較低，不超過 0.3%。看起來 python 是個可疑進程。記下 python 進程的 PID 號 18940，我們稍后分析。最后再看內存的使用情況，總內存 8G，剩余內存只有 730 MB，而 Buffer/Cache 占用內存高達 6GB 之多，這說明內存主要被緩存占用。雖然大部分緩存可回收，我們還是得了解下緩存的去處，確認緩存使用都是合理的。

iostat?

到這一步，你基本可以判斷出，CPU 使用率中的 iowait 是一個潛在瓶頸，而內存部分的緩存占比較大，那磁盤 I/O 又是怎么樣的情況呢？我們在終端中按 Ctrl+C ，停止 top 命令，再運行 iostat 命令，觀察 I/O 的使用情況：# -d 表示顯示 I/O 性能指標，-x 表示顯示擴展統計(即所有 I/O 指標) iostat -x -d 1 Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util loop0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sda 0.00 64.00 0.00 32768.00 0.00 0.00 0.00 0.00 0.00 7270.44 1102.18 0.00 512.00 15.50 99.20還記得這些性能指標的含義嗎？先自己回憶一下，如果實在想不起來，查看上一節的內容，或者用 man iostat 查詢。觀察 iostat 的最后一列，你會看到，磁盤 sda 的 I/O 使用率已經高達 99%，很可能已經接近 I/O 飽和。再看前面的各個指標，每秒寫磁盤請求數是 64 ，寫大小是 32 MB，寫請求的響應時間為 7 秒，而請求隊列長度則達到了 1100。超慢的響應時間和特長的請求隊列長度，進一步驗證了 I/O 已經飽和的猜想。此時，sda 磁盤已經遇到了嚴重的性能瓶頸。到這里，也就可以理解，為什么前面看到的 iowait 高達 90% 了，這正是磁盤 sda 的 I/O 瓶頸導致的。接下來的重點就是分析 I/O 性能瓶頸的根源了。那要怎么知道，這些 I/O 請求相關的進程呢？不知道你還記不記得，上一節我曾提到過，可以用 pidstat 或者 iotop ，觀察進程的 I/O 情況。這里，我就用 pidstat 來看一下。使用 pidstat 加上 -d 參數，就可以顯示每個進程的 I/O 情況。所以，你可以在終端中運行如下命令來觀察：pidstat -d 1 15:08:35 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 15:08:36 0 18940 0.00 45816.00 0.00 96 python 15:08:36 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command 15:08:37 0 354 0.00 0.00 0.00 350 jbd2/sda1-8 15:08:37 0 18940 0.00 46000.00 0.00 96 python 15:08:37 0 20065 0.00 0.00 0.00 1503 kworker/u4:2從 pidstat 的輸出，你可以發現，只有 python 進程的寫比較大，而且每秒寫的數據超過 45 MB，比上面 iostat 發現的 32MB 的結果還要大。很明顯，正是 python 進程導致了 I/O 瓶頸。再往下看 iodelay 項。雖然只有 python 在大量寫數據，但你應該注意到了，有兩個進程 (kworker 和 jbd2 )的延遲，居然比 python 進程還大很多。這其中，kworker 是一個內核線程，而 jbd2 是 ext4 文件系統中，用來保證數據完整性的內核線程。他們都是保證文件系統基本功能的內核線程，所以具體細節暫時就不用管了，我們只需要明白，它們延遲的根源還是大量 I/O。綜合 pidstat 的輸出來看，還是 python 進程的嫌疑最大。接下來，我們來分析 python 進程到底在寫什么。首先留意一下 python 進程的 PID 號， 18940。看到 18940 ，你有沒有覺得熟悉？其實前面在使用 top 時，我們記錄過的 CPU 使用率最高的進程，也正是它。不過，雖然在 top 中使用率最高，也不過是 6%，并不算高。所以，以 I/O 問題為分析方向還是正確的。知道了進程的 PID 號，具體要怎么查看寫的情況呢？

strace?

其實，我在系統調用的案例中講過，讀寫文件必須通過系統調用完成。觀察系統調用情況，就可以知道進程正在寫的文件。想起 strace 了嗎，它正是我們分析系統調用時最常用的工具。接下來，我們在終端中運行 strace 命令，并通過 -p 18940 指定 python 進程的 PID 號：strace -p 18940 strace: Process 18940 attached ... mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f7aee9000 mmap(NULL, 314576896, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f0f682e8000 write(3, "2018-12-05 15:23:01,709 - __main"..., 314572844 ) = 314572844 munmap(0x7f0f682e8000, 314576896) = 0 write(3, "\n", 1) = 1 munmap(0x7f0f7aee9000, 314576896) = 0 close(3) = 0 stat("/tmp/logtest.txt.1", {st_mode=S_IFREG|0644, st_size=943718535, ...}) = 0從 write() 系統調用上，我們可以看到，進程向文件描述符編號為 3 的文件中，寫入了 300MB 的數據。看來，它應該是我們要找的文件。不過，write() 調用中只能看到文件的描述符編號，文件名和路徑還是未知的。再觀察后面的 stat() 調用，你可以看到，它正在獲取 /tmp/logtest.txt.1 的狀態。 這種“點 + 數字格式”的文件，在日志回滾中非常常見。我們可以猜測，這是第一個日志回滾文件，而正在寫的日志文件路徑，則是 /tmp/logtest.txt。

lsof?

當然，這只是我們的猜測，自然還需要驗證。這里，我再給你介紹一個新的工具 lsof。它專門用來查看進程打開文件列表，不過，這里的“文件”不只有普通文件，還包括了目錄、塊設備、動態庫、網絡套接字等。接下來，我們在終端中運行下面的 lsof 命令，看看進程 18940 都打開了哪些文件：lsof -p 18940 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME python 18940 root cwd DIR 0,50 4096 1549389 / python 18940 root rtd DIR 0,50 4096 1549389 / … python 18940 root 2u CHR 136,0 0t0 3 /dev/pts/0 python 18940 root 3w REG 8,1 117944320 303 /tmp/logtest.txt這個輸出界面中，有幾列我簡單介紹一下，FD 表示文件描述符號，TYPE 表示文件類型，NAME 表示文件路徑。這也是我們需要關注的重點。再看最后一行，這說明，這個進程打開了文件 /tmp/logtest.txt，并且它的文件描述符是 3 號，而 3 后面的 w ，表示以寫的方式打開。這跟剛才 strace 完我們猜測的結果一致，看來這就是問題的根源：進程 18940 以每次 300MB 的速度，在“瘋狂”寫日志，而日志文件的路徑是 /tmp/logtest.txt。既然找出了問題根源，接下來按照慣例，就該查看源代碼，然后分析為什么這個進程會狂打日志了。你可以運行 docker cp 命令，把案例應用的源代碼拷貝出來，然后查看它的內容。(你也可以點擊這里查看案例應用的源碼)：# 拷貝案例應用源代碼到當前目錄docker cp app:/app.py . # 查看案例應用的源代碼cat app.py logger = logging.getLogger(__name__) logger.setLevel(level=logging.INFO) rHandler = RotatingFileHandler("/tmp/logtest.txt", maxBytes=1024 * 1024 * 1024, backupCount=1) rHandler.setLevel(logging.INFO) def write_log(size): '''Write logs to file''' message = get_message(size) while True: logger.info(message) time.sleep(0.1) if __name__ == '__main__': msg_size = 300 * 1024 * 1024 write_log(msg_size)分析這個源碼，我們發現，它的日志路徑是 /tmp/logtest.txt，默認記錄 INFO 級別以上的所有日志，而且每次寫日志的大小是 300MB。這跟我們上面的分析結果是一致的。一般來說，生產系統的應用程序，應該有動態調整日志級別的功能。繼續查看源碼，你會發現，這個程序也可以調整日志級別。如果你給它發送 SIGUSR1 信號，就可以把日志調整為 INFO 級；發送 SIGUSR2 信號，則會調整為 WARNING 級：def set_logging_info(signal_num, frame): '''Set loging level to INFO when receives SIGUSR1''' logger.setLevel(logging.INFO) def set_logging_warning(signal_num, frame): '''Set loging level to WARNING when receives SIGUSR2''' logger.setLevel(logging.WARNING) signal.signal(signal.SIGUSR1, set_logging_info) signal.signal(signal.SIGUSR2, set_logging_warning)根據源碼中的日志調用 logger. info(message) ，我們知道，它的日志是 INFO 級，這也正是它的默認級別。那么，只要把默認級別調高到 WARNING 級，日志問題應該就解決了。接下來，我們就來檢查一下，剛剛的分析對不對。在終端中運行下面的 kill 命令，給進程 18940 發送 SIGUSR2 信號：kill -SIGUSR2 18940然后，再執行 top 和 iostat 觀察一下：top ... %Cpu(s): 0.3 us, 0.2 sy, 0.0 ni, 99.5 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st iostat -d -x 1 Device r/s w/s rkB/s wkB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util loop0 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sdb 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00觀察 top 和 iostat 的輸出，你會發現，稍等一段時間后，iowait 會變成 0，而 sda 磁盤的 I/O 使用率也會逐漸減少到 0。到這里，我們不僅定位了狂打日志的應用程序，并通過調高日志級別的方法，完美解決了 I/O 的性能瓶頸。案例最后，當然不要忘了運行下面的命令，停止案例應用：

docker rm -f app

小結

日志，是了解應用程序內部運行情況，最常用、也最有效的工具。無論是操作系統，還是應用程序，都會記錄大量的運行日志，以便事后查看歷史記錄。這些日志一般按照不同級別來開啟，比如，開發環境通常打開調試級別的日志，而線上環境則只記錄警告和錯誤日志。在排查應用程序問題時，我們可能需要，在線上環境臨時開啟應用程序的調試日志。有時候，事后一不小心就忘了調回去。沒把線上的日志調高到警告級別，可能會導致 CPU 使用率、磁盤 I/O 等一系列的性能問題，嚴重時，甚至會影響到同一臺服務器上運行的其他應用程序。今后，在碰到這種“狂打日志”的場景時，你可以用 iostat、strace、lsof 等工具來定位狂打日志的進程，找出相應的日志文件，再通過應用程序的接口，調整日志級別來解決問題。如果應用程序不能動態調整日志級別，你可能還需要修改應用的配置，并重啟應用讓配置生效。思考最后，給你留一個思考題。在今天的案例開始時，我們用 top 和 iostat 查看了系統資源的使用情況。除了 CPU 和磁盤 I/O 外，剩余內存也比較少，而內存主要被 Buffer/Cache 占用。那么，今天的問題就是，這些內存到底是被 Buffer 還是 Cache 占用了呢？有沒有什么方法來確認你的分析結果呢？歡迎在留言區和我討論，也歡迎把這篇文章分享給你的同事、朋友。我們一起在實戰中演練，在交流中進步。

總結

以上是生活随笔為你收集整理的26 | 案例篇：如何找出狂打日志的“内鬼”？的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。