上一節，我們研究了一個狂打日志引發 I/O 性能問題的案例，先來簡單回顧一下。
日志，是了解應用程序內部運行情況，最常用也是最有效的工具。
日志一般會分為調試、信息、警告、錯誤等多個不同級別。
通常，生產環境只用開啟警告級別的日志，這一般不會導致 I/O 問題。但在偶爾排查問題時，可能需要我們開啟調試日志。調試結束后，很可能忘了把日志級別調回去。這時，大量的調試日志就可能會引發 I/O 性能問題。
你可以用 iostat ，確認是否有 I/O 性能瓶頸。再用 strace 和 lsof ，來定位應用程序以及它正在寫入的日志文件路徑。最后通過應用程序的接口調整日志級別，完美解決 I/O 問題。
不過，如果應用程序沒有動態調整日志級別的功能，你還需要修改應用配置並重啟應用，以便讓配置生效。
今天，我們再來看一個新的案例。這次案例是一個基於 Python Flask 框架的 Web 應用，它提供了一個查詢單詞熱度的 API，但是 API 的響應速度並不讓人滿意。
非常感謝攜程系統研發部資深后端工程師董國星，幫助提供了今天的案例。
案例准備
本次案例還是基於 Ubuntu 18.04，同樣適用於其他的 Linux 系統。我使用的案例環境如下所示：
- 機器配置：2 CPU，8GB 內存
- 預先安裝 docker、sysstat 等工具，如 apt install docker.io sysstat
為了方便你運行今天的案例，我把它打包成了一個 Docker 鏡像。這樣，你就只需要運行 Docker 命令就可以啟動它。
今天的案例需要兩台虛擬機，其中一台是案例分析的目標機器，運行 Flask 應用，它的 IP 地址是 192.168.0.10；而另一台作為客戶端，請求單詞的熱度。我畫了一張圖表示它們的關系，如下所示：
接下來，打開兩個終端，分別 SSH 登錄到這兩台虛擬機中，並在第一台虛擬機中，安裝上述工具。
跟以前一樣，案例中所有命令都默認以 root 用戶運行，如果你是用普通用戶身份登陸系統，請運行 sudo su root 命令切換到 root 用戶。
到這里，准備工作就完成了。接下來，我們正式進入操作環節。
溫馨提示：案例中 Python 應用的核心邏輯比較簡單，你可能一眼就能看出問題，但實際生產環境中的源碼就復雜多了。所以，我依舊建議，操作之前別看源碼，避免先入為主，而要把它當成一個黑盒來分析。這樣，你可以更好把握，怎么從系統的資源使用問題出發，分析出瓶頸所在的應用，以及瓶頸在應用中大概的位置。
案例分析
首先，我們在第一個終端中執行下面的命令，運行本次案例要分析的目標應用：
docker run --name=app -p 10000:80 -itd feisky/word-pop
然后，在第二個終端中運行 curl 命令，訪問 http://192.168.0.10:1000/，確認案例正常啟動。你應該可以在 curl 的輸出界面里，看到一個 hello world 的輸出：
curl http://192.168.0.10:10000/
hello world
接下來，在第二個終端中，訪問案例應用的單詞熱度接口，也就是 http://192.168.0.10:1000/popularity/word。
curl http://192.168.0.10:1000/popularity/word
稍等一會兒，你會發現，這個接口居然這么長時間都沒響應，究竟是怎么回事呢？我們先回到終端一來分析一下。
我們試試在第一個終端里，隨便執行一個命令，比如執行 df 命令，查看一下文件系統的使用情況。奇怪的是，這么簡單的命令，居然也要等好久才有輸出。
df
Filesystem 1K-blocks Used Available Use% Mounted on
udev 4073376 0 4073376 0% /dev
tmpfs 816932 1188 815744 1% /run
/dev/sda1 30308240 8713640 21578216 29% /
通過 df 我們知道，系統還有足夠多的磁盤空間。那為什么響應會變慢呢？看來還是得觀察一下，系統的資源使用情況，像是 CPU、內存和磁盤 I/O 等的具體使用情況。
這里的思路其實跟上一個案例比較類似，我們可以先用 top 來觀察 CPU 和內存的使用情況，然后再用 iostat 來觀察磁盤的 I/O 情況。
為了避免分析過程中 curl 請求突然結束，我們回到終端二，按 Ctrl+C 停止剛才的應用程序；然后，把 curl 命令放到一個循環里執行；這次我們還要加一個 time 命令，觀察每次的執行時間：
while true; do time curl http://192.168.0.10:10000/popularity/word; sleep 1; done
繼續回到終端一來分析性能。我們在終端一中運行 top 命令，觀察 CPU 和內存的使用情況：
top
top - 14:27:02 up 10:30, 1 user, load average: 1.82, 1.26, 0.76
Tasks: 129 total, 1 running, 74 sleeping, 0 stopped, 0 zombie
%Cpu0 : 3.5 us, 2.1 sy, 0.0 ni, 0.0 id, 94.4 wa, 0.0 hi, 0.0 si, 0.0 st
%Cpu1 : 2.4 us, 0.7 sy, 0.0 ni, 70.4 id, 26.5 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 8169300 total, 3323248 free, 436748 used, 4409304 buff/cache
KiB Swap: 0 total, 0 free, 0 used. 7412556 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
12280 root 20 0 103304 28824 7276 S 14.0 0.4 0:08.77 python
16 root 20 0 0 0 0 S 0.3 0.0 0:09.22 ksoftirqd/1
1549 root 20 0 236712 24480 9864 S 0.3 0.3 3:31.38 python3
觀察 top 的輸出可以發現，兩個 CPU 的 iowait 都非常高。特別是 CPU0， iowait 已經高達 94 %，而剩余內存還有 3GB，看起來也是充足的。
再往下看，進程部分有一個 python 進程的 CPU 使用率稍微有點高，達到了 14%。雖然 14% 並不能成為性能瓶頸，不過有點嫌疑——可能跟 iowait 的升高有關。
那這個 PID 號為 12280 的 python 進程，到底是不是我們的案例應用呢？
我們在第一個終端中，按下 Ctrl+C，停止 top 命令；然后執行下面的 ps 命令，查找案例應用 app.py 的 PID 號：
ps aux | grep app.py
root 12222 0.4 0.2 96064 23452 pts/0 Ss+ 14:37 0:00 python /app.py
root 12280 13.9 0.3 102424 27904 pts/0 Sl+ 14:37 0:09 /usr/local/bin/python /app.py
從 ps 的輸出，你可以看到，這個 CPU 使用率較高的進程，正是我們的案例應用。不過先別着急分析 CPU 問題，畢竟 iowait 已經高達 94%， I/O 問題才是我們首要解決的。
iostat
接下來，我們在終端一中，運行下面的 iostat 命令，其中:
- -d 選項是指顯示出 I/O 的性能指標；
- -x 選項是指顯示出擴展統計信息（即顯示所有 I/O 指標）。
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
sda 0.00 71.00 0.00 32912.00 0.00 0.00 0.00 0.00 0.00 18118.31 241.89 0.00 463.55 13.86 98.40
再次看到 iostat 的輸出，你還記得這個界面中的性能指標含義嗎？先自己回憶一下，如果實在想不起來，一定要先查看上節內容，或者用 man iostat 查明白。
明白了指標含義，再來具體觀察 iostat 的輸出。你可以發現，磁盤 sda 的 I/O 使用率已經達到 98% ，接近飽和了。而且，寫請求的響應時間高達 18 秒，每秒的寫數據為 32 MB，顯然寫磁盤碰到了瓶頸。
那要怎么知道，這些 I/O 請求到底是哪些進程導致的呢？我想，你已經還記得上一節我們用到的 pidstat。
在終端一中，運行下面的 pidstat 命令，觀察進程的 I/O 情況：
pidstat -d 1
14:39:14 UID PID kB_rd/s kB_wr/s kB_ccwr/s iodelay Command
14:39:15 0 12280 0.00 335716.00 0.00 0 python
從 pidstat 的輸出，我們再次看到了 PID 號為 12280 的結果。這說明，正是案例應用引發 I/O 的性能瓶頸。
走到這一步，你估計覺得，接下來就很簡單了，上一個案例不剛剛學過嗎？無非就是，先用 strace 確認它是不是在寫文件，再用 lsof 找出文件描述符對應的文件即可。
到底是不是這樣呢？我們不妨來試試。還是在終端一中，執行下面的 strace 命令：
strace -p 12280
strace: Process 12280 attached
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=567708}) = 0 (Timeout)
stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {st_mode=S_IFREG|0644, st_size=39278, ...}) = 0
stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {st_mode=S_IFREG|0644, st_size=39278, ...}) = 0
從 strace 中，你可以看到大量的 stat 系統調用，並且大都為 python 的文件，但是，請注意，這里並沒有任何 write 系統調用。
由於 strace 的輸出比較多，我們可以用 grep ，來過濾一下 write，比如：
strace -p 12280 2>&1 | grep write
遺憾的是，這里仍然沒有任何輸出。
難道此時已經沒有性能問題了嗎？重新執行剛才的 top 和 iostat 命令，你會不幸地發現，性能問題仍然存在。
我們只好綜合 strace、pidstat 和 iostat 這三個結果來分析了。很明顯，你應該發現了這里的矛盾：iostat 已經證明磁盤 I/O 有性能瓶頸，而 pidstat 也證明了，這個瓶頸是由 12280 號進程導致的，但 strace 跟蹤這個進程，卻沒有找到任何 write 系統調用。
這就奇怪了。難道因為案例使用的編程語言是 Python ，而 Python 是解釋型的，所以找不到？還是說，因為案例運行在 Docker 中呢？這里留個懸念，你自己想想。
文件寫，明明應該有相應的 write 系統調用，但用現有工具卻找不到痕跡，這時就該想想換工具的問題了。怎樣才能知道哪里在寫文件呢？
filetop
這里我給你介紹一個新工具， filetop。它是 bcc 軟件包的一部分，基於 Linux 內核的 eBPF（extended Berkeley Packet Filters）機制，主要跟蹤內核中文件的讀寫情況，並輸出線程 ID（TID）、讀寫大小、讀寫類型以及文件名稱。
eBPF 的工作原理，你暫時不用深究，后面內容我們會逐漸接觸到，先會使用就可以了。
至於老朋友 bcc 的安裝方法，可以參考它的 Github 網站 https://github.com/iovisor/bcc。比如在 Ubuntu 16 以上的版本中，你可以運行下面的命令來安裝它：
sudo apt-key adv --keyserver keyserver.ubuntu.com --recv-keys 4052245BD4284CDD
echo "deb https://repo.iovisor.org/apt/$(lsb_release -cs) $(lsb_release -cs) main" | sudo tee /etc/apt/sources.list.d/iovisor.list
sudo apt-get update
sudo apt-get install bcc-tools libbcc-examples linux-headers-$(uname -r)
安裝后，bcc 提供的所有工具，就全部安裝到了 /usr/share/bcc/tools 這個目錄中。接下來我們就用這個工具，觀察一下文件的讀寫情況。
首先，在終端一中運行下面的命令：
# 切換到工具目錄
cd /usr/share/bcc/tools
# -C 選項表示輸出新內容時不清空屏幕
./filetop -C
TID COMM READS WRITES R_Kb W_Kb T FILE
514 python 0 1 0 2832 R 669.txt
514 python 0 1 0 2490 R 667.txt
514 python 0 1 0 2685 R 671.txt
514 python 0 1 0 2392 R 670.txt
514 python 0 1 0 2050 R 672.txt
...
TID COMM READS WRITES R_Kb W_Kb T FILE
514 python 2 0 5957 0 R 651.txt
514 python 2 0 5371 0 R 112.txt
514 python 2 0 4785 0 R 861.txt
514 python 2 0 4736 0 R 213.txt
514 python 2 0 4443 0 R 45.txt
你會看到，filetop 輸出了 8 列內容，分別是線程 ID、線程命令行、讀寫次數、讀寫的大小（單位 KB）、文件類型以及讀寫的文件名稱。
這些內容里，你可能會看到很多動態鏈接庫，不過這不是我們的重點，暫且忽略即可。我們的重點，是一個 python 應用，所以要特別關注 python 相關的內容。
多觀察一會兒，你就會發現，每隔一段時間，線程號為 514 的 python 應用就會先寫入大量的 txt 文件，再大量地讀。
線程號為 514 的線程，屬於哪個進程呢？我們可以用 ps 命令查看。先在終端一中，按下 Ctrl+C ，停止 filetop ；然后，運行下面的 ps 命令。這個輸出的第二列內容，就是我們想知道的進程號：
ps -efT | grep 514
root 12280 514 14626 33 14:47 pts/0 00:00:05 /usr/local/bin/python /app.py
我們看到，這個線程正是案例應用 12280 的線程。終於可以先松一口氣，不過還沒完，filetop 只給出了文件名稱，卻沒有文件路徑，還得繼續找啊。
opensnoop
我再介紹一個好用的工具，opensnoop 。它同屬於 bcc 軟件包，可以動態跟蹤內核中的 open 系統調用。這樣，我們就可以找出這些 txt 文件的路徑。
接下來，在終端一中，運行下面的 opensnoop 命令：
opensnoop
12280 python 6 0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/650.txt
12280 python 6 0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/651.txt
12280 python 6 0 /tmp/9046db9e-fe25-11e8-b13f-0242ac110002/652.txt
這次，通過 opensnoop 的輸出，你可以看到，這些 txt 路徑位於 /tmp 目錄下。你還能看到，它打開的文件數量，按照數字編號，從 0.txt 依次增大到 999.txt，這可遠多於前面用 filetop 看到的數量。
綜合 filetop 和 opensnoop ，我們就可以進一步分析了。我們可以大膽猜測，案例應用在寫入 1000 個 txt 文件后，又把這些內容讀到內存中進行處理。我們來檢查一下，這個目錄中是不是真的有 1000 個文件：
ls /tmp/9046db9e-fe25-11e8-b13f-0242ac110002 | wc -l
ls: cannot access '/tmp/9046db9e-fe25-11e8-b13f-0242ac110002': No such file or directory
0
操作后卻發現，目錄居然不存在了。怎么回事呢？我們回到 opensnoop 再觀察一會兒：
opensnoop
12280 python 6 0 /tmp/defee970-fe25-11e8-b13f-0242ac110002/261.txt
12280 python 6 0 /tmp/defee970-fe25-11e8-b13f-0242ac110002/840.txt
12280 python 6 0 /tmp/defee970-fe25-11e8-b13f-0242ac110002/136.txt
原來，這時的路徑已經變成了另一個目錄。這說明，這些目錄都是應用程序動態生成的，用完就刪了。
結合前面的所有分析，我們基本可以判斷，案例應用會動態生成一批文件，用來臨時存儲數據，用完就會刪除它們。但不幸的是，正是這些文件讀寫，引發了 I/O 的性能瓶頸，導致整個處理過程非常慢。
當然，我們還需要驗證這個猜想。老辦法，還是查看應用程序的源碼 app.py，
@app.route("/popularity/<word>")
def word_popularity(word):
dir_path = '/tmp/{}'.format(uuid.uuid1())
count = 0
sample_size = 1000
def save_to_file(file_name, content):
with open(file_name, 'w') as f:
f.write(content)
try:
# initial directory firstly
os.mkdir(dir_path)
# save article to files
for i in range(sample_size):
file_name = '{}/{}.txt'.format(dir_path, i)
article = generate_article()
save_to_file(file_name, article)
# count word popularity
for root, dirs, files in os.walk(dir_path):
for file_name in files:
with open('{}/{}'.format(dir_path, file_name)) as f:
if validate(word, f.read()):
count += 1
finally:
# clean files
shutil.rmtree(dir_path, ignore_errors=True)
return jsonify({'popularity': count / sample_size * 100, 'word': word})
源碼中可以看到，這個案例應用，
在每個請求的處理過程中，都會生成一批臨時文件，然后讀入內存處理，最后再把整個目錄刪除掉。
這是一種常見的利用磁盤空間處理大量數據的技巧，不過，本次案例中的 I/O 請求太重，導致磁盤 I/O 利用率過高。
要解決這一點，其實就是算法優化問題了。
比如在內存充足時，就可以把所有數據都放到內存中處理，這樣就能避免 I/O 的性能問題。
你可以檢驗一下，在終端二中分別訪問 http://192.168.0.10:10000/popularity/word 和 http://192.168.0.10:10000/popular/word ，對比前后的效果：
time curl http://192.168.0.10:10000/popularity/word
{
"popularity": 0.0,
"word": "word"
}
real 2m43.172s
user 0m0.004s
sys 0m0.007s
time curl http://192.168.0.10:10000/popular/word
{
"popularity": 0.0,
"word": "word"
}
real 0m8.810s
user 0m0.010s
sys 0m0.000s
新的接口只要 8 秒就可以返回，明顯比一開始的 3 分鍾好很多。
當然，這只是優化的第一步，並且方法也不算完善，還可以做進一步的優化。不過，在實際系統中，我們大都是類似的做法，先用最簡單的方法，盡早解決線上問題，然后再繼續思考更好的優化方法。
小結
今天，我們分析了一個響應過慢的單詞熱度案例。
首先，我們用 top、iostat，分析了系統的 CPU 和磁盤使用情況。我們發現了磁盤 I/O 瓶頸，也知道了這個瓶頸是案例應用導致的。
接着，我們試着照搬上一節案例的方法，用 strace 來觀察進程的系統調用，不過這次很不走運，沒找到任何 write 系統調用。
於是，我們又用了新的工具，借助動態追蹤工具包 bcc 中的 filetop 和 opensnoop ，找出了案例應用的問題，發現這個根源是大量讀寫臨時文件。
找出問題后，優化方法就相對比較簡單了。如果內存充足時，最簡單的方法，就是把數據都放在速度更快的內存中，這樣就沒有磁盤 I/O 的瓶頸了。當然，再進一步，你可以還可以利用 Trie 樹等各種算法，進一步優化單詞處理的效率。
思考
最后，給你留一個思考題，也是我在文章中提到過的，讓你思考的問題。
今天的案例中，iostat 已經證明，磁盤 I/O 出現了性能瓶頸， pidstat 也證明了這個瓶頸是由 12280 號進程導致的。但是，strace 跟蹤這個進程，卻沒有發現任何 write 系統調用。
這究竟是怎么回事？難道是因為案例使用的編程語言 Python 本身是解釋型？還是說，因為案例運行在 Docker 中呢？
這里我小小提示一下。當你發現性能工具的輸出無法解釋時，最好返回去想想，是不是分析中漏掉了什么線索，或者去翻翻工具手冊，看看是不是某些默認選項導致的。
寫文件是由子線程執行的，所以直接strace跟蹤進程沒有看到write系統調用，可以通過pstree查看進程的線程信息，再用strace跟蹤。或者，通過strace -fp pid 跟蹤所有線程。
作者回復: 👍 默認選項是不開啟線程的