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

• 為了優(yōu)化文件訪問的性能，采用頁緩存、索引節(jié)點緩存、目錄項緩存等多種緩存機制，減少對下層塊設(shè)備的直接調(diào)用。
• 同樣的，為了優(yōu)化塊設(shè)備的訪問效率，使用緩沖區(qū)來緩存塊設(shè)備的數(shù)據(jù)。

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

案例準備

本次案例還是基于 Ubuntu 18.04，同樣適用于其他的 Linux 系統(tǒng)。我使用的案例環(huán)境如下所示：

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

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

案例分析

首先，我們在終端中執(zhí)行下面的命令，運行今天的目標應(yīng)用：docker run -v /tmp:/tmp --name=app -itd feisky/logapp然后，在終端中運行 ps 命令，確認案例應(yīng)用正常啟動。如果操作無誤，你應(yīng)該可以在 ps 的輸出中，看到一個 app.py 的進程：ps -ef | grep /app.py root 18940 18921 73 14:41 pts/0 00:00:02 python /app.py接著，我們來看看系統(tǒng)有沒有性能問題。要觀察哪些性能指標呢？前面文章中，我們知道 CPU、內(nèi)存和磁盤 I/O 等系統(tǒng)資源，很容易出現(xiàn)資源瓶頸，這就是我們觀察的方向了。我們來觀察一下這些資源的使用情況。當然，動手之前你應(yīng)該想清楚，要用哪些工具來做，以及工具的使用順序又是怎樣的。你可以先回憶下前面的案例和思路，自己想一想，然后再繼續(xù)下面的步驟。我的想法是，我們可以先用 top ，來觀察 CPU 和內(nèi)存的使用情況；然后再用 iostat ，來觀察磁盤的 I/O 情況。所以，接下來，你可以在終端中運行 top 命令，觀察 CPU 和內(nèi)存的使用情況：# 按 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 的輸出，你會發(fā)現(xiàn)，CPU0 的使用率非常高，它的系統(tǒng) CPU 使用率(sys%)為 6%，而 iowait 超過了 90%。這說明 CPU0 上，可能正在運行 I/O 密集型的進程。不過，究竟是什么原因呢？這個疑問先保留著，我們先繼續(xù)看完。接著我們來看，進程部分的 CPU 使用情況。你會發(fā)現(xiàn)， python 進程的 CPU 使用率已經(jīng)達到了 6%，而其余進程的 CPU 使用率都比較低，不超過 0.3%。看起來 python 是個可疑進程。記下 python 進程的 PID 號 18940，我們稍后分析。最后再看內(nèi)存的使用情況，總內(nèi)存 8G，剩余內(nèi)存只有 730 MB，而 Buffer/Cache 占用內(nèi)存高達 6GB 之多，這說明內(nèi)存主要被緩存占用。雖然大部分緩存可回收，我們還是得了解下緩存的去處，確認緩存使用都是合理的。

iostat?

到這一步，你基本可以判斷出，CPU 使用率中的 iowait 是一個潛在瓶頸，而內(nèi)存部分的緩存占比較大，那磁盤 I/O 又是怎么樣的情況呢？我們在終端中按 Ctrl+C ，停止 top 命令，再運行 iostat 命令，觀察 I/O 的使用情況：# -d 表示顯示 I/O 性能指標，-x 表示顯示擴展統(tǒng)計(即所有 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還記得這些性能指標的含義嗎？先自己回憶一下，如果實在想不起來，查看上一節(jié)的內(nèi)容，或者用 man iostat 查詢。觀察 iostat 的最后一列，你會看到，磁盤 sda 的 I/O 使用率已經(jīng)高達 99%，很可能已經(jīng)接近 I/O 飽和。再看前面的各個指標，每秒寫磁盤請求數(shù)是 64 ，寫大小是 32 MB，寫請求的響應(yīng)時間為 7 秒，而請求隊列長度則達到了 1100。超慢的響應(yīng)時間和特長的請求隊列長度，進一步驗證了 I/O 已經(jīng)飽和的猜想。此時，sda 磁盤已經(jīng)遇到了嚴重的性能瓶頸。到這里，也就可以理解，為什么前面看到的 iowait 高達 90% 了，這正是磁盤 sda 的 I/O 瓶頸導致的。接下來的重點就是分析 I/O 性能瓶頸的根源了。那要怎么知道，這些 I/O 請求相關(guān)的進程呢？不知道你還記不記得，上一節(jié)我曾提到過，可以用 pidstat 或者 iotop ，觀察進程的 I/O 情況。這里，我就用 pidstat 來看一下。使用 pidstat 加上 -d 參數(shù)，就可以顯示每個進程的 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 的輸出，你可以發(fā)現(xiàn)，只有 python 進程的寫比較大，而且每秒寫的數(shù)據(jù)超過 45 MB，比上面 iostat 發(fā)現(xiàn)的 32MB 的結(jié)果還要大。很明顯，正是 python 進程導致了 I/O 瓶頸。再往下看 iodelay 項。雖然只有 python 在大量寫數(shù)據(jù)，但你應(yīng)該注意到了，有兩個進程 (kworker 和 jbd2 )的延遲，居然比 python 進程還大很多。這其中，kworker 是一個內(nèi)核線程，而 jbd2 是 ext4 文件系統(tǒng)中，用來保證數(shù)據(jù)完整性的內(nèi)核線程。他們都是保證文件系統(tǒng)基本功能的內(nèi)核線程，所以具體細節(jié)暫時就不用管了，我們只需要明白，它們延遲的根源還是大量 I/O。綜合 pidstat 的輸出來看，還是 python 進程的嫌疑最大。接下來，我們來分析 python 進程到底在寫什么。首先留意一下 python 進程的 PID 號， 18940。看到 18940 ，你有沒有覺得熟悉？其實前面在使用 top 時，我們記錄過的 CPU 使用率最高的進程，也正是它。不過，雖然在 top 中使用率最高，也不過是 6%，并不算高。所以，以 I/O 問題為分析方向還是正確的。知道了進程的 PID 號，具體要怎么查看寫的情況呢？

strace?

其實，我在系統(tǒng)調(diào)用的案例中講過，讀寫文件必須通過系統(tǒng)調(diào)用完成。觀察系統(tǒng)調(diào)用情況，就可以知道進程正在寫的文件。想起 strace 了嗎，它正是我們分析系統(tǒng)調(diào)用時最常用的工具。接下來，我們在終端中運行 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() 系統(tǒng)調(diào)用上，我們可以看到，進程向文件描述符編號為 3 的文件中，寫入了 300MB 的數(shù)據(jù)?？磥?#xff0c;它應(yīng)該是我們要找的文件。不過，write() 調(diào)用中只能看到文件的描述符編號，文件名和路徑還是未知的。再觀察后面的 stat() 調(diào)用，你可以看到，它正在獲取 /tmp/logtest.txt.1 的狀態(tài)。 這種“點 + 數(shù)字格式”的文件，在日志回滾中非常常見。我們可以猜測，這是第一個日志回滾文件，而正在寫的日志文件路徑，則是 /tmp/logtest.txt。

lsof?

當然，這只是我們的猜測，自然還需要驗證。這里，我再給你介紹一個新的工具 lsof。它專門用來查看進程打開文件列表，不過，這里的“文件”不只有普通文件，還包括了目錄、塊設(shè)備、動態(tài)庫、網(wǎng)絡(luò)套接字等。接下來，我們在終端中運行下面的 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 表示文件路徑。這也是我們需要關(guān)注的重點。再看最后一行，這說明，這個進程打開了文件 /tmp/logtest.txt，并且它的文件描述符是 3 號，而 3 后面的 w ，表示以寫的方式打開。這跟剛才 strace 完我們猜測的結(jié)果一致，看來這就是問題的根源：進程 18940 以每次 300MB 的速度，在“瘋狂”寫日志，而日志文件的路徑是 /tmp/logtest.txt。既然找出了問題根源，接下來按照慣例，就該查看源代碼，然后分析為什么這個進程會狂打日志了。你可以運行 docker cp 命令，把案例應(yīng)用的源代碼拷貝出來，然后查看它的內(nèi)容。(你也可以點擊這里查看案例應(yīng)用的源碼)：# 拷貝案例應(yīng)用源代碼到當前目錄docker cp app:/app.py . # 查看案例應(yīng)用的源代碼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)分析這個源碼，我們發(fā)現(xiàn)，它的日志路徑是 /tmp/logtest.txt，默認記錄 INFO 級別以上的所有日志，而且每次寫日志的大小是 300MB。這跟我們上面的分析結(jié)果是一致的。一般來說，生產(chǎn)系統(tǒng)的應(yīng)用程序，應(yīng)該有動態(tài)調(diào)整日志級別的功能。繼續(xù)查看源碼，你會發(fā)現(xiàn)，這個程序也可以調(diào)整日志級別。如果你給它發(fā)送 SIGUSR1 信號，就可以把日志調(diào)整為 INFO 級；發(fā)送 SIGUSR2 信號，則會調(diào)整為 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)根據(jù)源碼中的日志調(diào)用 logger. info(message) ，我們知道，它的日志是 INFO 級，這也正是它的默認級別。那么，只要把默認級別調(diào)高到 WARNING 級，日志問題應(yīng)該就解決了。接下來，我們就來檢查一下，剛剛的分析對不對。在終端中運行下面的 kill 命令，給進程 18940 發(fā)送 SIGUSR2 信號：kill -SIGUSR2 18940然后，再執(zhí)行 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 的輸出，你會發(fā)現(xiàn)，稍等一段時間后，iowait 會變成 0，而 sda 磁盤的 I/O 使用率也會逐漸減少到 0。到這里，我們不僅定位了狂打日志的應(yīng)用程序，并通過調(diào)高日志級別的方法，完美解決了 I/O 的性能瓶頸。案例最后，當然不要忘了運行下面的命令，停止案例應(yīng)用：

docker rm -f app

小結(jié)

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

總結(jié)

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

如果覺得生活随笔網(wǎng)站內(nèi)容還不錯，歡迎將生活随笔推薦給好友。