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 树等各种算法，进一步优化单词处理的效率。