一则利用bcc工具包的filetop和opensnoop工具跟踪IO的案例
Contents [hide]
一 背景说明
两台机器，在server1上运行一个Docker容器，跑的是Python程序的Flask应用，提供一个访问单词热度的接口；server2(172.16.17.36)向server1发起请求调用。
这个案例有意思的是，从server1上明明看到有消耗高CPU资源和磁盘IO的进程，但是，不太直观的看到该进程具体读写的是哪个文件。于是，这里给出不同的分析思路和解决方案。
server1: 172.16.17.7，4C 8G；
server2: 172.16.11.36，24C 64G；
二 分析步骤和思路
1 server1启动container
x
1
docker run --name=app -p 10000:80 -itd feisky/word-pop2
[root@guoxin7 ~]# docker run --name=app -p 10000:80 -itd feisky/word-pop3
3ea1b081cf6d9565b487a56481d0e1182b96d58ae6a33b0f14b1ccc57400ee5f4
[root@guoxin7 ~]# 2 server2验证服务正常
1
1
[root@centos-master ~]# curl http://172.16.17.7:100002
hello world3
[root@centos-master ~]# 3 server2向server1发起请求
curl http://172.16.17.7:10000/popularity/word
发现响应特别慢。
4 server1 查看top
1
10
1
Tasks: 244 total, 1 running, 243 sleeping, 0 stopped, 0 zombie2
%Cpu(s): 11.3 us, 13.8 sy, 0.0 ni, 74.8 id, 0.0 wa, 0.0 hi, 0.1 si, 0.0 st3
KiB Mem : 41037092 total, 35284336 free, 951280 used, 4801476 buff/cache4
KiB Swap: 8257532 total, 8257532 free, 0 used. 38038384 avail Mem 5
•6
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 7
26611 root 20 0 97048 20532 4056 S 98.2 0.1 1:10.09 /usr/local/bin/python /app.py 8
6 root 20 0 0 0 0 S 0.4 0.0 0:00.13 [ksoftirqd/0] 9
9 root 20 0 0 0 0 S 0.4 0.0 0:09.86 [rcu_sched] 10
...发现server1 的进程26611耗费了比较高的CPU资源，top界面按下c字符键，调出进程执行的命令，看到该进程执行了/usr/local/bin/python /app.py 。
5 server1通过iostat查看系统IO资源情况
通过iostat -dx 1; -d 列出磁盘设备利用率；-x 列出extended statistics ；数字1,每秒输出1个报告；
1
44
1
[root@guoxin7 ~]# iostat -dx 12
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7) 2022年03月21日 _x86_64_ (4 CPU)3
•4
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util5
sda 0.02 0.24 4.36 18.55 433.67 6473.81 603.08 10.89 474.14 16.02 581.70 6.01 13.776
scd0 0.00 0.00 0.00 0.00 0.15 0.00 114.22 0.00 6.89 6.89 0.00 6.67 0.007
dm-0 0.00 0.00 4.28 18.80 430.82 6481.31 598.76 11.02 476.23 16.71 580.93 5.96 13.758
dm-1 0.00 0.00 0.01 0.00 0.33 0.00 50.09 0.00 1.77 1.77 0.00 1.57 0.009
•10
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util11
sda 0.00 0.00 0.00 156.00 0.00 73668.00 944.46 144.42 1061.29 0.00 1061.29 6.42 100.1012
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.0013
dm-0 0.00 0.00 0.00 160.00 0.00 75732.00 946.65 145.41 1039.44 0.00 1039.44 6.26 100.1014
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.0015
•16
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util17
sda 0.00 0.00 0.00 257.00 0.00 123472.00 960.87 143.15 929.06 0.00 929.06 3.89 100.0018
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.0019
dm-0 0.00 0.00 0.00 256.00 0.00 122032.00 953.38 145.58 938.41 0.00 938.41 3.95 101.0020
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.0021
•22
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util23
sda 0.00 0.00 1.00 183.00 8.00 85364.00 927.96 144.19 474.96 119.00 476.90 5.43 100.0024
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.0025
dm-0 0.00 0.00 1.00 194.00 8.00 89984.00 922.99 145.18 451.15 119.00 452.86 5.13 100.0026
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.0027
•28
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util29
sda 0.00 0.00 0.00 184.00 0.00 85640.00 930.87 146.85 1091.28 0.00 1091.28 5.43 100.0030
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.0031
dm-0 0.00 0.00 0.00 161.00 0.00 75776.00 941.32 147.84 1253.72 0.00 1253.72 6.21 100.0032
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.0033
•34
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util35
sda 0.00 0.00 0.00 318.00 0.00 148888.00 936.40 144.58 520.76 0.00 520.76 3.14 100.0036
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.0037
dm-0 0.00 0.00 0.00 323.00 0.00 150236.00 930.25 145.55 517.09 0.00 517.09 3.10 100.0038
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.0039
•40
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util41
sda 0.00 0.00 0.00 157.00 0.00 71612.00 912.25 147.31 453.65 0.00 453.65 6.37 100.0042
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.0043
dm-0 0.00 0.00 0.00 163.00 0.00 74660.00 916.07 148.31 438.91 0.00 438.91 6.13 100.0044
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持续观察，可以看到，系统的磁盘使用率有抖动，%util有时会达到100%，如上。iops（r/s+w/s）以及throughout(rkB/s+wkB/s)也会明显的变化。这意味着，系统的磁盘IO使用率会随着客户端发起请求，持续升高。那么，究竟是哪个进程在消耗较高的磁盘IO呢？
6 pidstat跟踪server1上进程的IO使用情况
1
19
1
[root@guoxin7 ~]# pidstat -p 26611 12
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7) 2022年03月21日 _x86_64_ (4 CPU)3
•4
13时49分22秒 UID PID %usr %system %guest %CPU CPU Command5
13时49分23秒 0 26611 63.00 38.00 0.00 100.00 0 python6
13时49分24秒 0 26611 62.00 38.00 0.00 100.00 0 python7
13时49分25秒 0 26611 44.00 29.00 0.00 73.00 0 python8
13时49分26秒 0 26611 0.00 7.00 0.00 7.00 2 python9
13时49分27秒 0 26611 2.00 48.00 0.00 50.00 2 python10
13时49分28秒 0 26611 30.00 19.00 0.00 49.00 2 python11
13时49分29秒 0 26611 62.00 39.00 0.00 100.00 0 python12
13时49分30秒 0 26611 64.00 36.00 0.00 100.00 2 python13
13时49分31秒 0 26611 62.00 38.00 0.00 100.00 3 python14
13时49分32秒 0 26611 64.00 37.00 0.00 100.00 1 python15
13时49分33秒 0 26611 63.00 38.00 0.00 100.00 1 python16
13时49分34秒 0 26611 62.00 37.00 0.00 99.00 1 python17
^C18
平均时间: 0 26611 48.17 33.67 0.00 81.83 - python19
[root@guoxin7 ~]# pidstat -d，列出进程磁盘使用率信息：
1
31
1
[root@guoxin7 ~]# pidstat -d -p 26611 12
Linux 3.10.0-1160.59.1.el7.x86_64 (guoxin7) 2022年03月21日 _x86_64_ (4 CPU)3
•4
13时50分12秒 UID PID kB_rd/s kB_wr/s kB_ccwr/s Command5
13时50分13秒 0 26611 0.00 169382.18 0.00 python6
13时50分14秒 0 26611 0.00 109853.47 0.00 python7
13时50分15秒 0 26611 0.00 134661.39 0.00 python8
13时50分16秒 0 26611 0.00 122948.00 0.00 python9
13时50分17秒 0 26611 0.00 259640.00 0.00 python10
13时50分18秒 0 26611 0.00 284580.00 0.00 python11
13时50分19秒 0 26611 0.00 293028.00 0.00 python12
13时50分20秒 0 26611 0.00 299768.00 0.00 python13
13时50分21秒 0 26611 0.00 279688.00 0.00 python14
13时50分22秒 0 26611 0.00 286160.00 0.00 python15
13时50分23秒 0 26611 0.00 288036.00 0.00 python16
13时50分24秒 0 26611 0.00 291524.00 0.00 python17
13时50分25秒 0 26611 0.00 22760.00 0.00 python18
13时50分26秒 0 26611 0.00 0.00 0.00 python19
13时50分27秒 0 26611 0.00 0.00 0.00 python20
13时50分28秒 0 26611 0.00 0.00 0.00 python21
13时50分29秒 0 26611 0.00 0.00 0.00 python22
13时50分30秒 0 26611 0.00 0.00 0.00 python23
13时50分31秒 0 26611 0.00 0.00 778244.00 python24
13时50分32秒 0 26611 0.00 0.00 2025068.00 python25
13时50分33秒 0 26611 0.00 162403.96 0.00 python26
13时50分34秒 0 26611 0.00 282608.00 0.00 python27
13时50分35秒 0 26611 0.00 282020.00 0.00 python28
13时50分36秒 0 26611 0.00 278336.00 0.00 python29
^C30
平均时间: 0 26611 0.00 160281.20 116610.32 python31
[root@guoxin7 ~]# 的确，看到26611进程的磁盘IO比较高。
7 strace跟踪进程26611的读写文件
1
28
1
[root@guoxin7 ~]# strace -p 266112
strace: Process 26611 attached3
select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=62570}) = 0 (Timeout)4
futex(0x7ffcab9dd974, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4998819}) = -1 EAGAIN (资源暂时不可用)5
futex(0x7ffcab9dd974, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4999436}) = 06
stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {st_mode=S_IFREG|0644, st_size=39278, ...}) = 07
stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {st_mode=S_IFREG|0644, st_size=39278, ...}) = 08
stat("/usr/local/lib/python3.7/importlib/_bootstrap.py", {st_mode=S_IFREG|0644, st_size=39278, ...}) = 09
stat("/usr/local/lib/python3.7/importlib/_bootstrap_external.py", {st_mode=S_IFREG|0644, st_size=59012, ...}) = 010
stat("/usr/local/lib/python3.7/importlib/_bootstrap_external.py", {st_mode=S_IFREG|0644, st_size=59012, ...}) = 011
stat("/usr/local/lib/python3.7/importlib/_bootstrap_external.py", {st_mode=S_IFREG|0644, st_size=59012, ...}) = 012
stat("/usr/local/lib/python3.7/encodings/__init__.py", {st_mode=S_IFREG|0644, st_size=5668, ...}) = 013
stat("/usr/local/lib/python3.7/encodings/__init__.py", {st_mode=S_IFREG|0644, st_size=5668, ...}) = 014
stat("/usr/local/lib/python3.7/encodings/__init__.py", {st_mode=S_IFREG|0644, st_size=5668, ...}) = 015
futex(0x7ffcab9dd8b4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4999442}) = -1 ETIMEDOUT (连接超时)16
futex(0x7ffcab9dd8b4, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4998549}) = 017
futex(0x7f557934c2a4, FUTEX_WAKE_PRIVATE, 1) = 118
futex(0x7f557eb2b324, FUTEX_WAKE_PRIVATE, 1) = 119
futex(0x7f557eb2b2cc, FUTEX_WAKE_PRIVATE, 1) = 120
futex(0x7f557934c234, FUTEX_WAKE_PRIVATE, 1) = 121
futex(0x7f557eb2b2cc, FUTEX_WAKE_PRIVATE, 1) = 122
stat("/usr/local/lib/python3.7/codecs.py", {st_mode=S_IFREG|0644, st_size=36287, ...}) = 023
stat("/usr/local/lib/python3.7/codecs.py", {st_mode=S_IFREG|0644, st_size=36287, ...}) = 024
futex(0x7ffcab9dd564, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4999526}) = -1 EAGAIN (资源暂时不可用)25
futex(0x7ffcab9dd564, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4999624}) = 026
stat("/usr/local/lib/python3.7/codecs.py", {st_mode=S_IFREG|0644, st_size=36287, ..27
...28
...并没有看到进程26611对应的读写文件。怎么办呢？有没有其它思路？
8 通过BCC的filetop来跟踪
由于在操作系统层面并没有跟踪到进程26611实际读写的文件是哪个？我们通过BCC的filetop来跟踪内核里读写文件的信息。
安装BCC(BPF Compiler Collection)工具包，调用其filetop查看File reads and writes by filename and process。
安装之后，位于/usr/share/bcc/tools路径下：-C表示当前屏幕不清屏的方式持续输出，第1列，表示线程号，COMM线程执行的命令，READS+WRITES分别表示读写次数，R_Kb、W_Kb表示的是读写的大小，T表示方式，R是Read，FILE列，表示的读写的文件名。
1
52
1
[root@guoxin7 tools]# ./filetop -C2
Tracing... Output every 1 secs. Hit Ctrl-C to end3
•4
14:01:07 loadavg: 3.76 2.56 2.18 4/282 73365
•6
TID COMM READS WRITES R_Kb W_Kb T FILE7
7336 python 0 1 0 5175 R 84.txt8
7336 python 0 1 0 4785 R 113.txt9
7336 python 0 1 0 4589 R 134.txt10
7336 python 0 1 0 4492 R 150.txt11
7336 python 0 1 0 4443 R 123.txt12
7336 python 0 1 0 4394 R 85.txt13
7336 python 0 1 0 4345 R 56.txt14
7336 python 0 1 0 4296 R 106.txt15
7336 python 0 1 0 4248 R 73.txt16
7336 python 0 1 0 4052 R 59.txt17
7336 python 0 1 0 4052 R 107.txt18
7336 python 0 1 0 3662 R 147.txt19
7336 python 0 1 0 3466 R 118.txt20
7336 python 0 1 0 3369 R 89.txt21
7336 python 0 1 0 3369 R 69.txt22
7336 python 0 1 0 3369 R 128.txt23
7336 python 0 1 0 3320 R 67.txt24
7336 python 0 1 0 3320 R 119.txt25
7336 python 0 1 0 3271 R 114.txt26
7336 python 0 1 0 3222 R 61.txt27
•28
14:01:08 loadavg: 3.76 2.56 2.18 3/282 733629
•30
TID COMM READS WRITES R_Kb W_Kb T FILE31
7336 python 0 1 0 4394 R 397.txt32
7336 python 0 1 0 4296 R 388.txt33
7336 python 0 1 0 4199 R 365.txt34
7336 python 0 1 0 3955 R 363.txt35
7336 python 0 1 0 3857 R 386.txt36
7336 python 0 1 0 3857 R 398.txt37
7336 python 0 1 0 3808 R 360.txt38
7336 python 0 1 0 3710 R 367.txt39
7336 python 0 1 0 3710 R 392.txt40
7336 python 0 1 0 3417 R 362.txt41
7336 python 0 1 0 3173 R 402.txt42
7336 python 0 1 0 3027 R 359.txt43
7336 python 0 1 0 3027 R 385.txt44
7336 python 0 1 0 2978 R 368.txt45
7336 python 0 1 0 2929 R 371.txt46
7336 python 0 1 0 2929 R 378.txt47
7336 python 0 1 0 2880 R 361.txt48
7336 python 0 1 0 2880 R 381.txt49
7336 python 0 1 0 2832 R 387.txt50
7336 python 0 1 0 2783 R 380.txt51
Detaching...52
[root@guoxin7 tools]# 9 BCC的opensnoop查看内核open执行的系统调用
同样使用BCC工具包下提供的另一个工具，opensnoop。
1
15
1
[root@guoxin7 tools]# ./opensnoop -p 266112
PID COMM FD ERR PATH3
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/0.txt4
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/1.txt5
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/2.txt6
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/3.txt7
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/4.txt8
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/5.txt9
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/6.txt10
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/7.txt11
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/8.txt12
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/9.txt13
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/10.txt14
26611 python 6 0 /tmp/83425c82-a8dd-11ec-b3db-0242ac110002/11.txt15
...这次，可以看到26611进程读取的文件的路径，持续跟踪，发现文件的路径会发生变化。大概率猜测一下，可能是前面的Python进程，在创建临时文件，然后操作处理之后，删除了文件。
10 查看Docker 应用代码
进入container内部，查看app.py源代码：
1
50
1
[root@guoxin7 tools]# docker ps2
CONTAINER ID IMAGE COMMAND CREATED STATUS PORTS NAMES3
3ea1b081cf6d feisky/word-pop "python /app.py" About an hour ago Up About an hour 0.0.0.0:10000->80/tcp app4
[root@guoxin7 tools]# docker exec -it app /bin/sh5
/ # ls6
app.py bin dev etc home lib media mnt proc root run sbin srv sys tmp usr var7
/ # cat app.py 8
9
# -*- coding: UTF-8 -*-10
•11
import os12
import uuid13
import random14
import shutil15
from concurrent.futures import ThreadPoolExecutor16
from flask import Flask, jsonify17
...18
@app.route("/popularity/<word>")19
def word_popularity(word):20
dir_path = '/tmp/{}'.format(uuid.uuid1())21
count = 022
sample_size = 100023
•24
def save_to_file(file_name, content):25
with open(file_name, 'w') as f:26
f.write(content)27
•28
try:29
# initial directory firstly30
os.mkdir(dir_path)31
•32
# save article to files33
for i in range(sample_size):34
file_name = '{}/{}.txt'.format(dir_path, i)35
article = generate_article()36
save_to_file(file_name, article)37
•38
# count word popularity39
for root, dirs, files in os.walk(dir_path):40
for file_name in files:41
with open('{}/{}'.format(dir_path, file_name)) as f:42
if validate(word, f.read()):43
count += 144
finally:45
# clean files46
shutil.rmtree(dir_path, ignore_errors=True)47
•48
return jsonify({'popularity': count / sample_size * 100, 'word': word})49
...50
•的确，发现了创建临时目录和文件，然后处理之后，再删除的操作。
三 小结
1 分析思路
- 先top看到高CPU的进程；
- 然后，iostat -dx 1;查看系统IO
- 接下来，pidstat -d -p pid 1 ;查看指定进程的磁盘IO开销；
- 想要通过strace -p pid;找到进程读写的文件信息未果；
- 到此，转而使用BCC工具包的filetop查看内核中的文件读写信息，找到基本的文件名等读写相关信息；
- 最后，继续使用BCC工具包的opensnoop工具查看内核中open调用的栈信息；
2 另外一种思路
使用strace -f -p pid；可以跟踪进程及其线程的读写信息：
1
57
1
[root@guoxin7 tools]# strace -f -p 26611|grep Write2
strace: Process 26611 attached with 3 threads3
[pid 12362] close(6) = 04
[pid 26612] restart_syscall(<... resuming interrupted poll ...> <unfinished ...>5
[pid 26611] select(0, NULL, NULL, NULL, {tv_sec=0, tv_usec=989194} <unfinished ...>6
[pid 12362] mmap(NULL, 3002368, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5578b8e0007
[pid 12362] madvise(0x5644e1264000, 438272, MADV_DONTNEED) = 08
[pid 12362] munmap(0x7f5578e6b000, 1953792) = 09
[pid 12362] open("/tmp/7d5596d8-a8e0-11ec-b3db-0242ac110002/737.txt", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 610
[pid 12362] fcntl(6, F_SETFD, FD_CLOEXEC) = 011
[pid 12362] fstat(6, {st_mode=S_IFREG|0644, st_size=0, ...}) = 012
[pid 12362] ioctl(6, TIOCGWINSZ, 0x7f557934bff0) = -1 ENOTTY (对设备不适当的 ioctl 操作)13
[pid 12362] lseek(6, 0, SEEK_CUR) = 014
[pid 12362] ioctl(6, TIOCGWINSZ, 0x7f557934bf10) = -1 ENOTTY (对设备不适当的 ioctl 操作)15
[pid 12362] lseek(6, 0, SEEK_CUR) = 016
[pid 12362] mmap(NULL, 3002368, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5578f2f00017
[pid 12362] write(6, "The king explodes a cat with rab"..., 2999999) = 299999918
[pid 12362] munmap(0x7f5578f2f000, 3002368) = 019
[pid 12362] close(6) = 020
[pid 26612] <... restart_syscall resumed>) = 021
[pid 26612] futex(0x7f5579450874, FUTEX_WAIT_PRIVATE, 2, {tv_sec=0, tv_nsec=4999199} <unfinished ...>22
[pid 12362] mmap(NULL, 2752512, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5578f6c00023
[pid 12362] madvise(0x5644e1264000, 438272, MADV_DONTNEED) = 024
[pid 12362] munmap(0x7f5578b8e000, 3002368) = 025
[pid 12362] futex(0x7f5579450874, FUTEX_WAKE_PRIVATE, 1) = 126
[pid 12362] open("/tmp/7d5596d8-a8e0-11ec-b3db-0242ac110002/738.txt", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666 <unfinished ...>27
[pid 26612] <... futex resumed>) = 028
[pid 26612] poll([{fd=4, events=POLLIN}], 1, 500 <unfinished ...>29
[pid 12362] <... open resumed>) = 630
[pid 12362] fcntl(6, F_SETFD, FD_CLOEXEC) = 031
[pid 12362] fstat(6, {st_mode=S_IFREG|0644, st_size=0, ...}) = 032
[pid 12362] ioctl(6, TIOCGWINSZ, 0x7f557934bff0) = -1 ENOTTY (对设备不适当的 ioctl 操作)33
[pid 12362] lseek(6, 0, SEEK_CUR) = 034
[pid 12362] ioctl(6, TIOCGWINSZ, 0x7f557934bf10) = -1 ENOTTY (对设备不适当的 ioctl 操作)35
[pid 12362] lseek(6, 0, SEEK_CUR) = 036
[pid 12362] mmap(NULL, 2752512, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5578ccc00037
[pid 12362] write(6, "Some guy kicks some guy to know "..., 2749999) = 274999938
[pid 12362] munmap(0x7f5578ccc000, 2752512) = 039
[pid 12362] close(6) = 040
[pid 12362] mmap(NULL, 2002944, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f5578d8300041
[pid 12362] madvise(0x5644e1264000, 438272, MADV_DONTNEED) = 042
[pid 12362] munmap(0x7f5578f6c000, 2752512) = 043
[pid 12362] open("/tmp/7d5596d8-a8e0-11ec-b3db-0242ac110002/739.txt", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 644
[pid 12362] fcntl(6, F_SETFD, FD_CLOEXEC) = 045
[pid 12362] fstat(6, {st_mode=S_IFREG|0644, st_size=0, ...}) = 046
[pid 12362] ioctl(6, TIOCGWINSZ, 0x7f557934bff0) = -1 ENOTTY (对设备不适当的 ioctl 操作)47
[pid 12362] lseek(6, 0, SEEK_CUR) = 048
[pid 12362] ioctl(6, TIOCGWINSZ, 0x7f557934bf10) = -1 ENOTTY (对设备不适当的 ioctl 操作)49
[pid 12362] lseek(6, 0, SEEK_CUR) = 050
[pid 12362] mmap(NULL, 2002944, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f557902300051
[pid 12362] write(6, "The king treats some guy to make"..., 1999999) = 199999952
[pid 12362] munmap(0x7f5579023000, 2002944) = 053
[pid 12362] close(6) = 054
[pid 12362] mmap(NULL, 4100096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f557899a00055
[pid 12362] madvise(0x5644e1264000, 438272, MADV_DONTNEED) = 056
[pid 12362] munmap(0x7f5578d83000, 2002944) = 057
[pid 12362] open("/tmp/7d5596d8-a8e0-11ec-b3db-0242ac110002/740.txt", O_WRONLY|O_CREAT|O_TRUNC|O_CLOEXEC, 0666) = 63 个人收获
学习到strace -f -p pid；可以跟踪进程以及其线程的文件读写信息；
学会安装使用BCC工具包中的filetop跟踪内核中文件读写信息；opensnoop；跟踪内核中使用open系统调用的栈信息。
4 关于filetop和opensnoop的使用帮助
可以分别加上-h命令行查看，或者到GitHub站点查看相关示例。
四 参考和链接
1 倪朋飞老师的Linux性能优化实战，27 | 案例篇：为什么我的磁盘I/O延迟很高？；
一条评论
Pingback: