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

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

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

案例準(zhǔn)備

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

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

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

案例分析

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

iostat?

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

strace?

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

lsof?

當(dāng)然，這只是我們的猜測，自然還需要驗(yàn)證。這里，我再給你介紹一個新的工具 lsof。它專門用來查看進(jìn)程打開文件列表，不過，這里的“文件”不只有普通文件，還包括了目錄、塊設(shè)備、動態(tài)庫、網(wǎng)絡(luò)套接字等。接下來，我們在終端中運(yùn)行下面的 lsof 命令，看看進(jìn)程 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)注的重點(diǎn)。再看最后一行，這說明，這個進(jìn)程打開了文件 /tmp/logtest.txt，并且它的文件描述符是 3 號，而 3 后面的 w ，表示以寫的方式打開。這跟剛才 strace 完我們猜測的結(jié)果一致，看來這就是問題的根源：進(jìn)程 18940 以每次 300MB 的速度，在“瘋狂”寫日志，而日志文件的路徑是 /tmp/logtest.txt。既然找出了問題根源，接下來按照慣例，就該查看源代碼，然后分析為什么這個進(jìn)程會狂打日志了。你可以運(yùn)行 docker cp 命令，把案例應(yīng)用的源代碼拷貝出來，然后查看它的內(nèi)容。(你也可以點(diǎn)擊這里查看案例應(yīng)用的源碼)：# 拷貝案例應(yīng)用源代碼到當(dā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，默認(rèn)記錄 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 級，這也正是它的默認(rèn)級別。那么，只要把默認(rèn)級別調(diào)高到 WARNING 級，日志問題應(yīng)該就解決了。接下來，我們就來檢查一下，剛剛的分析對不對。在終端中運(yùn)行下面的 kill 命令，給進(jìn)程 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 的性能瓶頸。案例最后，當(dāng)然不要忘了運(yùn)行下面的命令，停止案例應(yīng)用：

docker rm -f app

小結(jié)

日志，是了解應(yīng)用程序內(nèi)部運(yùn)行情況，最常用、也最有效的工具。無論是操作系統(tǒng)，還是應(yīng)用程序，都會記錄大量的運(yùn)行日志，以便事后查看歷史記錄。這些日志一般按照不同級別來開啟，比如，開發(fā)環(huán)境通常打開調(diào)試級別的日志，而線上環(huán)境則只記錄警告和錯誤日志。在排查應(yīng)用程序問題時，我們可能需要，在線上環(huán)境臨時開啟應(yīng)用程序的調(diào)試日志。有時候，事后一不小心就忘了調(diào)回去。沒把線上的日志調(diào)高到警告級別，可能會導(dǎo)致 CPU 使用率、磁盤 I/O 等一系列的性能問題，嚴(yán)重時，甚至?xí)绊懙酵慌_服務(wù)器上運(yùn)行的其他應(yīng)用程序。今后，在碰到這種“狂打日志”的場景時，你可以用 iostat、strace、lsof 等工具來定位狂打日志的進(jìn)程，找出相應(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 占用了呢？有沒有什么方法來確認(rèn)你的分析結(jié)果呢？歡迎在留言區(qū)和我討論，也歡迎把這篇文章分享給你的同事、朋友。我們一起在實(shí)戰(zhàn)中演練，在交流中進(jìn)步。

總結(jié)

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

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