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 树等各种算法，进一步优化单词处理的效率。
作者：罗阿红
出处：http://www.cnblogs.com/luoahong/
本文版权归作者和博客园共有，欢迎转载，但未经作者同意必须保留此段声明，且在文章页面明显位置给出原文连接。
