碼上快樂

相關內容    簡體    繁體

27-案例篇：為什么我的磁盤I/O延遲很高？

本文轉載自   查看原文   2021-12-20 15:41   944    Linux性能優化

案例

  1. 環境准備

    # 服務器
# 機器配置：2cpu，4GB內存
# 預先安裝docker、sysstat包

# 客戶端
# 任意linux服務器即可

    image-20211220110216620


  2. 在服務端執行下面的命令，模擬案例

    [root@local_sa_192-168-1-6 ~]# docker run --name=app -p 10000:80 -itd feisky/word-pop

[root@local_sa_192-168-1-6 ~]# docker ps
CONTAINER ID   IMAGE             COMMAND            CREATED         STATUS         PORTS                                     NAMES
ad3887e297e3   feisky/word-pop   "python /app.py"   8 seconds ago   Up 6 seconds   0.0.0.0:10000->80/tcp, :::10000->80/tcp   app

[root@local_sa_192-168-1-6 ~]# curl http://192.168.1.6:10000/
hello world

  3. 在客戶端訪問服務端接口

    # 發現訪問接口很慢
[root@local_deploy_192-168-1-5 ~]# curl http://192.168.1.6:10000/popularity/word

# 訪問一個接口居然要2分多鍾
[root@local_deploy_192-168-1-5 ~]# time curl http://192.168.1.6:10000/popularity/word
{
  "popularity": 0.0,
  "word": "word"
}

real	2m45.296s
user	0m0.009s
sys	0m0.002s

# 一直訪問，便於分析
[root@local_deploy_192-168-1-5 ~]# while true; do time curl http://192.168.1.6:10000/popularity/word; sleep 1; done

  4. 在服務端，執行df命令，查看一下文件系統的使用情況

    [root@local_sa_192-168-1-6 ~]# df -h
文件系統                 容量  已用  可用 已用% 掛載點
devtmpfs                 2.0G     0  2.0G    0% /dev
tmpfs                    2.0G     0  2.0G    0% /dev/shm
tmpfs                    2.0G  8.6M  2.0G    1% /run
tmpfs                    2.0G     0  2.0G    0% /sys/fs/cgroup
/dev/mapper/centos-root   98G   20G   79G   20% /
/dev/sda1               1014M  256M  759M   26% /boot
tmpfs                    394M     0  394M    0% /run/user/1007
overlay                   98G   20G   79G   20% 
##
系統還有足夠多的磁盤空間，那為什么響應會變慢呢？

  5. 在服務端，用top來觀察CPU和內存的使用情況

    [root@local_sa_192-168-1-6 ~]# top
top - 14:36:02 up 1 day,  1:22,  1 user,  load average: 1.98, 1.18, 0.66
Tasks: 117 total,   1 running,  57 sleeping,   0 stopped,   0 zombie
%Cpu0  :  1.7 us,  1.0 sy,  0.0 ni, 29.5 id, 67.8 wa,  0.0 hi,  0.0 si,  0.0 st
%Cpu1  :  2.7 us,  1.0 sy,  0.0 ni, 24.9 id, 71.4 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  4027996 total,  1778052 free,   284884 used,  1965060 buff/cache
KiB Swap:  8388604 total,  8388604 free,        0 used.  3508532 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
 5890 root      20   0  105912  31372   7312 S   6.6  0.8   0:19.76 python
##
兩個 CPU 的 iowait 都非常高
##
剩余內存還有3GB，看起來也是充足的
##
還有python這個進程目前是使用CPU最高的進程之一，首先要分析一下它

  6. 用iostat來觀察磁盤的I/O情況

    # -d 選項是指顯示出IO的性能指標
# -x 選項是指顯示出擴展統計信息（即顯示所有IO指標）
[root@local_sa_192-168-1-6 ~]# iostat -d -x 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月20日 	_x86_64_	(2 CPU)
Device:         rrqm/s   wrqm/s     r/s     w/s    rkB/s    wkB/s avgrq-sz avgqu-sz   await r_await w_await  svctm  %util
sda               0.00     0.00    0.00   20.00     0.00 15382.50  1538.25     0.96   48.15    0.00   48.15  47.70  95.40
scd0              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
dm-0              0.00     0.00    0.00    8.00     0.00 15813.00  3953.25     1.44  179.38    0.00  179.38  42.00  33.60
dm-1              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的I/O使用率已經達到95%，接近飽和了
而且，寫請求的響應時間高達20秒，每秒的寫數據為15MB
這些I/O請求到底是哪些進程導致的呢？

  7. pidstat觀察進程IO情況

    [root@local_sa_192-168-1-6 ~]# pidstat -d 1
Linux 5.15.7-1.el7.elrepo.x86_64 (local_sa_192-168-1-6) 	2021年12月20日 	_x86_64_	(2 CPU)

14時44分49秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14時44分50秒     0      5890      0.00  18043.56      0.00  python

14時44分50秒   UID       PID   kB_rd/s   kB_wr/s kB_ccwr/s  Command
14時44分51秒     0      5890      0.00  17952.00      0.00  python
##
從pidstat的輸出，看到了PID號為5890的結果
這說明，正是案例應用引發I/O的性能瓶頸

  8. 先用strace確認它是不是在寫文件

    [root@local_sa_192-168-1-6 ~]# strace -p 5890 -f
[pid  5890] stat("/usr/local/lib/python3.7/lib-dynload/select.cpython-37m-x86_64-linux-gnu.so", {st_mode=S_IFREG|0755, st_size=87240, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/lib-dynload/select.cpython-37m-x86_64-linux-gnu.so", {st_mode=S_IFREG|0755, st_size=87240, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/lib-dynload/select.cpython-37m-x86_64-linux-gnu.so", {st_mode=S_IFREG|0755, st_size=87240, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/urllib/__init__.py", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/urllib/__init__.py", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/urllib/__init__.py", {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/urllib/parse.py", {st_mode=S_IFREG|0644, st_size=36925, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/urllib/parse.py", {st_mode=S_IFREG|0644, st_size=36925, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/urllib/parse.py", {st_mode=S_IFREG|0644, st_size=36925, ...}) = 0
[pid  5890] stat("/usr/local/lib/python3.7/email/_parseaddr.py", {st_mode=S_IFREG|0644, 
##
從strace中，可以看到大量的stat系統調用，並且大都為python的文件，但是這里並沒有任何write系統調用

## 由於strace的輸出比較多，可以用grep，來過濾一下write
[root@local_sa_192-168-1-6 ~]# strace -p 5890 2>&1 | grep write
##
仍然沒有任何輸出

  9. 只好綜合strace、pidstat和iostat這三個結果來分析了
    iostat已經證明磁盤I/O有性能瓶頸，而pidstat也證明了，這個瓶頸是由5890號進程導致的
    但strace跟蹤這個進程，卻沒有找到任何write系統調用文件寫，
    明明應該有相應的write系統調用，但用現有工具卻找不到痕跡，這時就該想想換工具的問題了

    filetop是bcc軟件包的一部分，主要跟蹤內核中文件的讀寫情況，並輸出線程ID、讀寫大小、讀寫類型以及文件名稱

    # -C 選項表示輸出新內容時不清空屏幕
[root@local_sa_192-168-1-6 ~]# filetop -C
TID     COMM             READS  WRITES R_Kb    W_Kb    T FILE
5968    python           0      1      0       4199    R 711.txt
5968    python           0      1      0       3369    R 707.txt
5968    python           0      1      0       3222    R 710.txt
5968    python           0      1      0       2636    R 708.txt
5968    python           0      1      0       2392    R 709.txt
5969    filetop          1      0      4       0       R type
5969    filetop          1      0      4       0       R retprobe
5969    filetop          2      0      2       0       R loadavg
656     auditd           0      5      0       0       R audit.log
......
TID     COMM             READS  WRITES R_Kb    W_Kb    T FILE
5968    python           0      1      0       3369    R 714.txt
5968    python           0      1      0       2685    R 712.txt
5968    python           0      1      0       2587    R 718.txt
5968    python           0      1      0       2490    R 716.txt
5968    python           0      1      0       2099    R 717.txt
5968    python           0      1      0       1904    R 715.txt
5968    python           0      1      0       1757    R 713.txt
5969    filetop          2      0      2       0       R loadavg

##
filetop輸出了8列內容，分別是線程ID、線程命令行、讀寫次數、讀寫的大小、文件類型以及讀寫的文件名稱
##
多觀察一會兒會發現，每隔一段時間，線程號為5968的python應用就會先寫入大量的txt文件，再大量地讀

##
線程號為5968的線程，屬於哪個進程呢？可以用ps命令查看
[root@local_sa_192-168-1-6 ~]# ps -efT|grep 5968
root      5890  5968  5860  8 14:54 pts/0    00:00:07 /usr/local/bin/python /app.py
root      5985  5985  5348  0 14:55 pts/0    00:00:00 grep --color=auto 5971
##
這個線程正是案例應用5890的線程
filetop只給出了文件名稱，卻沒有文件路徑

  10. opensnoop屬於bcc軟件包，可以動態跟蹤內核中的open系統調用，這樣就可以找出這些 txt 文件的路徑

    [root@local_sa_192-168-1-6 ~]# opensnoop
libbpf: failed to find valid kernel BTF
libbpf: vmlinux BTF is not found
PID    COMM               FD ERR PATH
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/454.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/455.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/456.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/457.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/458.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/459.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/460.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/461.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/462.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/463.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/464.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/465.txt
5890   python              6   0 /tmp/0a9f7e26-6162-11ec-b257-0242ac110002/466.txt
##
通過opensnoop的輸出可以看到，這些txt路徑位於/tmp目錄下
它打開的文件數量，按照數字編號，從0.txt依次增大到999.txt，這可遠多於前面用filetop看到的數量
##
綜合filetop和opensnoop就可以進一步分析了
可以大膽猜測，案例應用在寫入1000個txt文件后，又把這些內容讀到內存中進行處理。
來檢查一下，這個目錄中是不是真的有1000個文件
[root@local_sa_192-168-1-6 ~]# ls /tmp/0a9f7e26-6162-11ec-b257-0242ac110002|wc -l
ls: 無法訪問/tmp/0a9f7e26-6162-11ec-b257-0242ac110002: 沒有那個文件或目錄
0
##
操作后卻發現，目錄居然不存在了。怎么回事呢？回到opensnoop再觀察一會兒
[root@local_sa_192-168-1-6 ~]# opensnoop
libbpf: failed to find valid kernel BTF
libbpf: vmlinux BTF is not found
PID    COMM               FD ERR PATH
5890   python              6   0 /tmp/6ab71080-6162-11ec-b257-0242ac110002/309.txt
5890   python              6   0 /tmp/6ab71080-6162-11ec-b257-0242ac110002/310.txt
5890   python              6   0 /tmp/6ab71080-6162-11ec-b257-0242ac110002/311.txt
5890   python              6   0 /tmp/6ab71080-6162-11ec-b257-0242ac110002/312.txt
5890   python              6   0 /tmp/6ab71080-6162-11ec-b257-0242ac110002/313.txt
##
原來，這時的路徑已經變成了另一個目錄。這說明，這些目錄都是應用程序動態生成的，用完就刪了
##
結合前面的所有分析，基本可以判斷，案例應用會動態生成一批文件，用來臨時存儲數據，用完就會刪除它們
但不幸的是，正是這些文件讀寫，引發了I/O的性能瓶頸，導致整個處理過程非常慢

  11. 查看應用程序的源碼 app.py

    # 拷貝代碼到本地目錄
[root@local_sa_192-168-1-6 ~]# docker cp app:/app.py .
[root@local_sa_192-168-1-6 ~]# ls
app.py

# 查看源碼
[root@local_sa_192-168-1-6 ~]# cat app.py
#!/usr/bin/env python
# -*- coding: UTF-8 -*-

import os
import uuid
import random
import shutil
from concurrent.futures import ThreadPoolExecutor
from flask import Flask, jsonify

app = Flask(__name__)


def validate(word, sentence):
    return word in sentence


def generate_article():
    s_nouns = [
        "A dude", "My mom", "The king", "Some guy", "A cat with rabies",
        "A sloth", "Your homie", "This cool guy my gardener met yesterday",
        "Superman"
    ]
    p_nouns = [
        "These dudes", "Both of my moms", "All the kings of the world",
        "Some guys", "All of a cattery's cats",
        "The multitude of sloths living under your bed", "Your homies",
        "Like, these, like, all these people", "Supermen"
    ]
    s_verbs = [
        "eats", "kicks", "gives", "treats", "meets with", "creates", "hacks",
        "configures", "spies on", "retards", "meows on", "flees from",
        "tries to automate", "explodes"
    ]
    infinitives = [
        "to make a pie.", "for no apparent reason.",
        "because the sky is green.", "for a disease.",
        "to be able to make toast explode.", "to know more about archeology."
    ]
    sentence = '{} {} {} {}'.format(
        random.choice(s_nouns), random.choice(s_verbs),
        random.choice(s_nouns).lower() or random.choice(p_nouns).lower(),
        random.choice(infinitives))
    return '\n'.join([sentence for i in range(50000)])


@app.route('/')
def hello_world():
    return 'hello world'


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


@app.route("/popular/<word>")
def word_popular(word):
    count = 0
    sample_size = 1000
    articles = []

    try:
        for i in range(sample_size):
            articles.append(generate_article())

        for article in articles:
            if validate(word, article):
                count += 1
    finally:
        pass

    return jsonify({'popularity': count / sample_size * 100, 'word': word})


if __name__ == '__main__':
    app.run(debug=True, host='0.0.0.0', port=80)
    
##
源碼中可以看到，這個案例應用，在每個請求的處理過程中，都會生成一批臨時文件
然后讀入內存處理，最后再把整個目錄刪除掉
##
這是一種常見的利用磁盤空間處理大量數據的技巧，不過，本次案例中的I/O請求太重，導致磁盤I/O利用率過高
##
要解決這一點，其實就是算法優化問題了
比如在內存充足時，就可以把所有數據都放到內存中處理，這樣就能避免I/O的性能問題

  12. 在終端二中分別訪問http://192.168.1.6:10000/popularity/word和http://192.168.1.6:10000/popular/word ，對比前后的效果

    [root@local_deploy_192-168-1-5 ~]# time curl  http://192.168.1.6:10000/popular/word
{
  "popularity": 0.0,
  "word": "word"
}

real	0m30.063s
user	0m0.002s
sys	0m0.002s

[root@local_deploy_192-168-1-5 ~]# time curl http://192.168.1.6:10000/popularity/word
{
  "popularity": 0.0,
  "word": "word"
}

real	2m45.296s
user	0m0.009s
sys	0m0.002s
##
新的接口只要30秒就可以返回，明顯比一開始的3分鍾好很多
##
當然，這只是優化的第一步，並且方法也不算完善，還可以做進一步的優化
不過，在實際系統中，大都是類似的做法，先用最簡單的方法，盡早解決線上問題，然后再繼續思考更好的優化方法

小結

今天分析了一個響應過慢的單詞熱度案例

首先，用top、iostat分析了系統的CPU和磁盤使用情況，發現了磁盤I/O瓶頸，也知道了這個瓶頸是案例應用導致的
接着用strace來觀察進程的系統調用，沒找到任何write系統調用
於是用新的工具，借助動態追蹤工具包bcc中的filetop和opensnoop，找出了案例應用的問題，發現這個根源是大量讀寫臨時文件

找出問題后，優化方法就相對比較簡單了
如果內存充足時，最簡單的方法，就是把數據都放在速度更快的內存中，這樣就沒有磁盤I/O的瓶頸了
當然，再進一步，還可以利用Trie樹等各種算法，進一步優化單詞處理的效率



免責聲明！

本站轉載的文章為個人學習借鑒使用，本站對版權不負任何法律責任。如果侵犯了您的隱私權益，請聯系本站郵箱yoyou2525@163.com刪除。



猜您在找 27 | 案例篇：為什么我的磁盤I/O延遲很高？ 性能案例分析 | 查看哪些進程在大量讀寫磁盤－I/O很高問題排查 31 | 套路篇：磁盤 I/O 性能優化的幾個思路 磁盤I/O高居不下，通過什么來查看占用I/O的進程？ SQL Server磁盤I/O性能分析 Zabbix監控Linux磁盤I/O 使用fio測試磁盤I/O性能 磁盤I/O的三種方式對比：標准I/O、直接 I/O、mmap 磁盤I/O的三種方式對比：標准I/O、直接 I/O、mmap 查看磁盤I/O命令iostat詳解
 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM