Linux性能優化實戰學習筆記：第二十七講

一、案例環境描述

1、環境准備

2CPU,4GB內存

預先安裝docker sysstat工具

2、溫馨提示

案例中 Python 應用的核心邏輯比較簡單，你可能一眼就能看出問題，但實際生產環境中的源碼就復雜多了。所以，
我依舊建議，操作之前別看源碼，避免先入為主，要把它當成一個黑盒來分析。這樣 你可以更好把握住，怎么從系統的資源使用問題出發，分析出瓶頸
所在的應用，以及瓶頸在應用中大概的位置

3、測試環境准備

1、運行目標應用

docker run --name=app -p 10000:80 -itd feisky/word-pop 

2、確認應用正常啟動

[root@luoahong ~]# ps aux | grep app.py
root      10130  0.0  0.5  95700 23392 pts/0    Ss+  10:29   0:00 python /app.py
root      10167 30.8  0.7 104924 30372 pts/0    Sl+  10:29   4:32 /usr/local/bin/python /app.py
root      10256  0.0  0.0 112716  2288 pts/1    S+   10:44   0:00 grep --color=auto app.py

二、故障現象

1、發現故障

1、接下來，在第二個終端中，訪問案例應用的單詞熱度接口

[root@luoahong ~]# curl http://192.168.118.115:10000
hello world[root@luoahong ~]# curl http://192.168.118.115:10000/popularity/word
{
  "popularity": 0.0, 
  "word": "word"
}

稍等一會兒，你會發現，這個接口居然這么長時間都沒響應，究竟是怎么回事呢？我們先回到終端一來分析一下。

2、我們試試在第一個終端里，隨便執行一個命令，居然也要等好久才能輸出

[root@luoahong ~]# df
Filesystem     1K-blocks     Used Available Use% Mounted on
devtmpfs         1995624        0   1995624   0% /dev
tmpfs            2007620        0   2007620   0% /dev/shm
tmpfs            2007620     9336   1998284   1% /run
tmpfs            2007620        0   2007620   0% /sys/fs/cgroup
/dev/sda2       50306052 29273120  21032932  59% /
tmpfs             401524        0    401524   0% /run/user/0
overlay         50306052 29273120  21032932  59% /var/lib/docker/overlay2/0bc7de96c86ea3d2fe1059ccf2dea175b05a5434cc0a73858b5292b610699530/merged
shm                65536        0     65536   0% /var/lib/docker/containers/f0b72f14052f48a2a6eaf034d11e2fea77b76250bd87863e50d2f8aeb22c9918/mounts/shm

2、故障現象

1、top

進程部分有一個 python 進程的 CPU 使用率稍微有點達到了 40.4%。雖然 40.1%並不能成為性能瓶頸，不過有點嫌疑——可能跟 iowait 的升高有關

那這個 PID 號為 10167 的 python 進程，到底是不是我們的案例應用呢？

2、然后執行下面的 ps 命令，查找案例應用 app.py 的 PID 號：

[root@luoahong ~]# ps aux | grep app.py
root      10130  0.0  0.5  95700 23392 pts/0    Ss+  10:29   0:00 python /app.py
root      10167 30.8  0.7 104924 30372 pts/0    Sl+  10:29   4:32 /usr/local/bin/python /app.py
root      10256  0.0  0.0 112716  2288 pts/1    S+   10:44   0:00 grep --color=auto app.py

從 ps 的輸出，你可以看到，這個 CPU 使用率較高的進程，不過先別着急分析 CPU 問題，畢竟 iowait 已經高達92%

三、分析過程

1、觀察系統I/O使用情況

1、案例

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 

2、實際測試

root@luoahong ~]# iostat -d -x 1
Linux 5.1.0-1.el7.elrepo.x86_64 (luoahong) 	05/30/2019 	_x86_64_	(2 CPU)

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz  aqu-sz  %util
sda              2.14    834.77     0.01   0.44   23.88   390.85   75.84  85205.18     0.60   0.79  191.95  1123.42    0.00      0.00     0.00   0.00    0.00     0.00   14.57  10.79

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz  aqu-sz  %util
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   0.00    0.00     0.00    0.00   0.00

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz  aqu-sz  %util
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   0.00    0.00     0.00    0.00   0.00

Device            r/s     rkB/s   rrqm/s  %rrqm r_await rareq-sz     w/s     wkB/s   wrqm/s  %wrqm w_await wareq-sz     d/s     dkB/s   drqm/s  %drqm d_await dareq-sz  aqu-sz  %util
sda              0.00      0.00     0.00   0.00    0.00     0.00  125.00 103592.00     1.00   0.79   39.18   828.74    0.00      0.00     0.00   0.00    0.00     0.00    4.83  14.90

-d 選項是指顯示出I/O的性能指標；

-x 選項是指顯示出擴展統計信息（即顯示所有I/O指標）

1、你可以發現，磁盤 sda 的 I/O 使用率已經達到 98%接近飽和了
2、而且，寫請求的響應時間高達 18 秒，每秒的寫數據為32MB，雖然寫磁盤碰到了瓶頸
3、這些I/O請求到底是那些進程導致的呢？

2、知道了進程PID，具體要怎么查看寫的情況呢？

[root@luoahong ~]# pidstat -d 1
Linux 5.1.0-1.el7.elrepo.x86_64 (luoahong) 	05/30/2019 	_x86_64_	(2 CPU)

11:19:22 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
11:19:23 AM     0     10167      0.00 124549.02      0.00       0  python
11:19:23 AM     0     10191      0.00      0.00      0.00     108  kworker/u256:1+flush-8:0

11:19:23 AM   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s iodelay  Command
11:19:24 AM     0     10167      0.00 126168.00      0.00       0  python
11:19:24 AM     0     10191      0.00      0.00      0.00     100  kworker/u256:1+flush-8:0

走到這一步，你估計覺得，接下來就很簡單了，上一個案例不剛剛學過嗎？無非就是，先用 strace 確認它是不是在寫文件，再用 lsof 找出文件描述符對應的文件即可。

1、strace查看制定PID調用情況

[root@luoahong ~]# strace -p 10167
strace: Process 10167 attached
select(0, NULL, NULL, NULL, {0, 403619}) = 0 (Timeout)
......
stat("/usr/local/lib/python3.7/stringprep.py", {st_mode=S_IFREG|0644, st_size=12917, ...}) = 0
stat("/usr/local/lib/python3.7/stringprep.py", {st_mode=S_IFREG|0644, st_size=12917, ...}) = 0
stat("/usr/local/lib/python3.7/_bootlocale.py", {st_mode=S_IFREG|0644, st_size=1801, ...}) = 0
stat("/usr/local/lib/python3.7/_bootlocale.py", {st_mode=S_IFREG|0644, st_size=1801, ...}) = 

由於 strace 的輸出比較多，我們可以用 grep ，來過濾一下 write，比如：

[root@luoahong ~]# strace -p 10167 2>&1 |grep write

遺憾的是沒有任何輸出

2、filetop

它是 bcc 軟件包的一部分，基於 Linux 內核的eBPF（extended Berkeley Packet Filters）機制，主要跟蹤內核中文件的讀寫情況，並輸出線
程 ID（TID）、讀寫大小、讀寫類型以及文件名稱。

bcc的安裝方法：https://github.com/iovisor/bcc

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 這個目錄中接下來我們就用這個工具，觀察一下文件的讀寫情況。

[root@luoahong tools]# ./filetop -C
Tracing... Output every 1 secs. Hit Ctrl-C to end

11:54:58 loadavg: 2.37 1.27 0.54 2/185 9851

TID    COMM             READS  WRITES R_Kb    W_Kb    T FILE
9850   python           2      0      3662    0       R 995.txt
9850   python           2      0      3564    0       R 998.txt
9850   python           2      0      3466    0       R 986.txt
9850   python           2      0      3466    0       R 994.txt
9850   python           2      0      3222    0       R 988.txt
9850   python           2      0      3173    0       R 993.txt
9850   python           2      0      2929    0       R 992.txt
9850   python           2      0      2832    0       R 990.txt
9850   python           2      0      2734    0       R 989.txt
9850   python           2      0      2490    0       R 997.txt
9850   python           2      0      2441    0       R 999.txt
9850   python           2      0      2294    0       R 987.txt
9850   python           2      0      2246    0       R 996.txt
9850   python           2      0      2099    0       R 984.txt
9850   python           2      0      1806    0       R 985.txt
9850   python           2      0      1660    0       R 991.txt
9847   filetop          1      0      4       0       R retprobe
9847   filetop          1      0      4       0       R type
9847   filetop          2      0      2       0       R loadavg
9851   sleep            1      0      0       0       R libc-2.17.so

線程號為 514 的線程，屬於哪個進程呢？

[root@luoahong tools]# ps -efT|grep 9891
root       9798   9891   9755 46 11:59 pts/0    00:00:07 /usr/local/bin/python /app.py
root       9894   9894   9805  0 12:00 pts/1    00:00:00 grep --color=auto 9891

filetop 只給出了文件名稱，卻沒有文件路徑，還得繼續找啊

3、opensnoop 

它同屬於 bcc 軟件包，可以動態跟蹤內核中的 open 系統調用。這樣，我們可以找出這些txt文件的路徑

[root@luoahong tools]# ./opensnoop
PID    COMM               FD ERR PATH
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/898.txt
9921   opensnoop          -1   2 /usr/lib64/python2.7/encodings/ascii.so
9921   opensnoop          -1   2 /usr/lib64/python2.7/encodings/asciimodule.so
9921   opensnoop          12   0 /usr/lib64/python2.7/encodings/ascii.py
9921   opensnoop          13   0 /usr/lib64/python2.7/encodings/ascii.pyc
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/899.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/900.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/901.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/902.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/903.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/904.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/905.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/906.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/907.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/908.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/909.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/910.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/911.txt
9798   python              6   0 /tmp/9ef81916-828f-11e9-960a-0242ac110002/912.txt

綜合 filetop 和 opensnoop ，我們就可以進一步分析了。我們可以大膽猜測，案例應用在寫入1000 個 txt 文件后又把這些內容讀到內存中進行處理
我們來檢查一下，這個目錄中是不是真的有 1000 個文件：

[root@luoahong tools]# ls /tmp/9ef81916-828f-11e9-960a-0242ac110002 |wc -l
ls: cannot access /tmp/9ef81916-828f-11e9-960a-0242ac110002: No such file or directory
0

操作后卻發現，目錄居然不存在了，怎么回事呢？我們回到 opensnoop 再觀察一會兒

[root@luoahong tools]# ./opensnoop
PID    COMM               FD ERR PATH
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/351.txt
10589  opensnoop          -1   2 /usr/lib64/python2.7/encodings/ascii.so
10589  opensnoop          -1   2 /usr/lib64/python2.7/encodings/asciimodule.so
10589  opensnoop          12   0 /usr/lib64/python2.7/encodings/ascii.py
10589  opensnoop          13   0 /usr/lib64/python2.7/encodings/ascii.pyc
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/352.txt
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/353.txt
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/354.txt
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/355.txt
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/356.txt
9798   python              6   0 /tmp/d94f7bec-829c-11e9-960a-0242ac110002/357.txt

原來，這時的路徑已經變成了另一個目錄，這說明，這些目錄都是應用程序動態生成的，用完就刪了。

結合前面的所有分析，我們基本可以判斷，案例應用會動態生成一批文件，用來臨時存儲數據，用完就會刪除它們。但不幸的是，正是這些文件讀寫，引發了 I/O 的性能瓶頸，

導致整個處理過程非常慢

4、確認猜想（查看源代碼）

@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}) 

四、解決方案

1、問題總結

源碼中可以看到，這個案例應用

1、在每個請求的處理過程中毛都會生成一批臨時文件。
2、然后讀入內存處理，
3、最后把整個目錄刪除掉

這是一種常見的利用磁盤空間處理大量數據技巧，不過，本次案例中I/O請求太重。導致磁盤I/O利用率過高

2、算法優化

要解決這一點其實就是算法優化問題，比如在內存充足時，就可以把所有的數據存放到內存中處理，這樣就避免I/O的性能問題

你可以檢驗一下，在中斷二中分別訪問：http://192.168.0.10:10000/popularity/word和http://192.168.0.10:10000/popular/word對比前后的效果

http://192.168.0.10:10000/popularity/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

http://192.168.0.10:10000/popular/word

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 樹等各種算法，進一步優化單詞處理的效率。