Linux BPF性能分析之基于BCC工具清单检查
写在前面
- 博文内容为
《BPF Performance Tools》读书笔记整理 - 内容涉及 11 种 BCC 单一功能工具使用
- 理解不足小伙伴帮忙指正
不必太纠结于当下，也不必太忧虑未来，当你经历过一些事情的时候，眼前的风景已经和从前不一样了。——村上春树
关于 BCC 是什么这里不多介绍，小伙伴可以看我之前的文章：Linux 可观测性 BPF&eBPF 以及 BCC&bpftrace 认知
BCC工具检查清单
下面的内容 位于BCC仓库的docs/tutorial.md 文件中。它提供了个通用的使用 BCC 工具的检查清单:
https://github.com/iovisor/bcc/blob/master/docs/tutorial.md
execsnoop
execsnoop(8) 通过跟踪每次 execve(2) 系统调用,为每个新创建的进程打印一行信息
┌──[root@vms100.liruilongs.github.io]-[~]
└─$execsnoop -T
TIME PCOMM PID PPID RET ARGS
12:24:09 runc 86262 1879 0 /usr/bin/runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/4e8d90ea3eff37105a86bc6e53c964e98bac2a1e2e67b8e2a3f0fa37cbe673df/log.json --log-format json exec --process /tmp/runc-process3278214083 --detach --pid-file /run/containerd/io.containerd.runtime.v2.task/moby/4e8d90ea3eff37105a86bc6e53c964e98bac2a1e2e67b8e2a3f0fa37cbe673df/cb051c901399 4e8d90ea3eff37105a86bc6e53c964e98bac2a1e2e67b8e2a3f0fa37cbe673df
12:24:09 exe 86268 86262 0 /proc/self/exe init
12:24:10 runc 86278 2814 0 /usr/bin/runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/178526f4fb3ea51f979becad80f2d889f1e43fc29eeb328641230a51299d0ecc/log.json --log-format json exec --process /tmp/runc-process2833259500 --detach --pid-file /run/containerd/io.containerd.runtime.v2.task/moby/178526f4fb3ea51f979becad80f2d889f1e43fc29eeb328641230a51299d0ecc/aa2935770297 178526f4fb3ea51f979becad80f2d889f1e43fc29eeb328641230a51299d0ecc
12:24:10 runc 86279 1830 0 /usr/bin/runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/2a97142e025cd33197e7830875e1387ff3600095c5a19cdc15fa541c24c586e0/log.json --log-format json exec --process /tmp/runc-process1454194643 --detach --pid-file /run/containerd/io.containerd.runtime.v2.task/moby/2a97142e025cd33197e7830875e1387ff3600095c5a19cdc15fa541c24c586e0/dbdd764bbaa0 2a97142e025cd33197e7830875e1387ff3600095c5a19cdc15fa541c24c586e0
..........................................
12:24:10 healthcheck_por 86328 2245 0 /usr/local/bin/healthcheck_port neutron-metadata-agent 5672
12:24:10 pgrep 86334 86328 0 /usr/bin/pgrep -d | -f neutron-metadata-agent
12:24:10 grep 86336 86328 0 /usr/bin/grep -qE :(5672).*,pid=(7|49|50|51|52|788),
12:24:10 ss 86335 86328 0 /usr/sbin/ss -ntp
........................................
12:24:27 erlexec 86752 86698 0 /usr/lib64/erlang/erts-13.2.2.3/bin/erlexec +B -boot start_clean -noinput -noshell -hidden -smp enable -kernel inet_dist_listen_min 35672 -kernel inet_dist_listen_max 35682 -run escript start -escript main
12:24:27 beam.smp 86752 86698 0 /usr/lib64/erlang/erts-13.2.2.3/bin/beam.smp -B -- -root /usr/lib64/erlang -bindir /usr/lib64/erlang/erts-13.2.2.3/bin -progname erl -- -home /var/lib/rabbitmq -epmd_port 4369 -- -boot start_clean -noshell -noinput -noshell
12:24:27 erl_child_setup 86767 86752 0 /usr/lib64/erlang/erts-13.2.2.3/bin/erl_child_setup 1048576
12:24:27 clustercheck 86788 3193 0 /usr/bin/clustercheck
12:24:27 mysql 86790 86789 0 /usr/bin/mysql -nNE --connect-timeout=10 --user=haproxy --password= --host=192.168.26.100 --port=3306 -e SHOW STATUS LIKE 'wsrep_local_state';
12:24:27 tail 86791 86789 0 /usr/bin/tail -1
12:24:27 sleep 86792 86788 0 /usr/bin/sleep 0.1
12:24:27 check_alive.sh 86793 3098 0 /check_alive.sh
12:24:27 socat 86795 86793 0 /usr/bin/socat unix-connect:/var/lib/kolla/haproxy/haproxy.sock stdio
^C┌──[root@vms100.liruilongs.github.io]-[~]
└─$
存活周期短的进程会消耗CPU资源，但通过传统的周期执行的监控工具较难发现，可使用execsnoop(8)来检查
opensnoop
opensnoop(8) 在每次open(2)(文件打开)系统调用(及其变体)时打印一行输出，包括详细信息。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$opensnoop
PID COMM FD ERR PATH
3262 ovs-vswitchd 47 0 /sys/devices/system/cpu
3028 2_dirty_io_sche 43 0 /proc/26/statm
90165 xinetd 0 0 /etc/passwd
90165 xinetd 0 0 /proc/sys/kernel/ngroups_max
90165 xinetd 0 0 /etc/group
90165 clustercheck 3 0 /etc/ld.so.cache
90165 clustercheck 3 0
90165 clustercheck 3 0 /lib64/libdl.so.2
949 tuned 14 0 /proc/90165/cmdline
90165 clustercheck 3 0 /lib64/libc.so.6
949 tuned 14 0 /proc/90165/stat
90165 clustercheck -1 6 /dev/tty
90165 clustercheck 3 0 /usr/lib/locale/locale-archive
90165 clustercheck 3 0 /usr/lib64/gconv/gconv-modules.cache
90165 clustercheck 3 0 /etc/nsswitch.conf
90165 clustercheck 3 0 /etc/ld.so.cache
90165 clustercheck -1 2 /lib64/glibc-hwcaps/x86-64-v3/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/glibc-hwcaps/x86-64-v2/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/tls/haswell/x86_64/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/tls/haswell/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/tls/x86_64/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/tls/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/haswell/x86_64/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/haswell/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/x86_64/libnss_sss.so.2
90165 clustercheck -1 2 /lib64/libnss_sss.so.2
包括打开文件的路径、打开操作是否成功(“ERR”列)。打开的文件可以透露应用程序工作的很多信息:识别应用程序的数据文件、配置文件和日志文件。有时应用程序在反复尝试打开一个不存在的文件时，会导致异常表现或者性能受损。
ext4slower（或 btrfs、xfs、zfs*）
ext4slower(8)跟踪ext4文件系统中常见的操作(读、写、打开和同步)，并且可以把耗时超过某个阈值的操作打印出来。
# ./ext4slower
Tracing ext4 operations slower than 10 ms
TIME COMM PID T BYTES OFF_KB LAT(ms) FILENAME
06:35:01 cron 16464 R 1249 0 16.05 common-auth
06:35:01 cron 16463 R 1249 0 16.04 common-auth
06:35:01 cron 16465 R 1249 0 16.03 common-auth
06:35:01 cron 16465 R 4096 0 10.62 login.defs
06:35:01 cron 16464 R 4096 0 10.61 login.defs
这可以定位或者排除一类性能问题:应用程序正在通过文件系统等待某个较慢的磁盘IO。ext4 之外的其他文件系统，也有类似的工具:btrfsslower(8)、xfsslower(8)，以及zfsslower(8)。
biolatency
biolatency(8)跟踪磁盘I/O延迟(也就是从向设备发出请求到请求完成的时间)，并且以直方图显示。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$biolatency -m
Tracing block device I/O... Hit Ctrl-C to end.
^C
msecs : count distribution
0 -> 1 : 240 |****************************************|
2 -> 3 : 98 |**************** |
4 -> 7 : 6 |* |
8 -> 15 : 3 | |
16 -> 31 : 2 | |
32 -> 63 : 3 | |
┌──[root@vms100.liruilongs.github.io]-[~]
└─$
这种形式可以比用iostat(1)工具的平均值输出更好地解释磁盘IO性能可以显示 IO请求的多峰分布，峰指的是在一个分布中出现频次比其他值高的值。
biosnoop
biosnoop(8)将每一次磁盘I/O请求打印出来，包含延迟之类的细节信息。这允许你磁盘 I/O进行更细致的检查，并搜寻时序模式(比如，写动作之后的读排队)。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$biosnoop
TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms)
0.000000 mariadbd 6621 nvme0n1 W 85444008 4096 0.23
0.198842 kworker/2:1 98256 <unknown> R 18446744073709551615 8 0.12
1.614408 mariadbd 6621 nvme0n1 W 85444008 4096 0.31
1.669567 mariadbd 6621 nvme0n1 W 85444008 4096 0.21
2.001210 mariadbd 6621 nvme0n1 W 85444008 4096 0.18
2.232486 mariadbd 6621 nvme0n1 W 85444008 4096 0.20
2.246185 kworker/2:1 98256 <unknown> R 18446744073709551615 8 0.07
2.291031 mariadbd 6621 nvme0n1 W 85444008 4096 0.24
2.576154 mariadbd 6621 nvme0n1 W 85444008 4096 0.48
...................
^C┌──[root@vms100.liruilongs.github.io]-[~]
└─$
cachestat
cachestat(8)每秒(用户可以指定其他时长)打印一行摘要信息，展示文件系统缓存的统计信息。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$cachestat
HITS MISSES DIRTIES HITRATIO BUFFERS_MB CACHED_MB
28764 0 0 100.00% 4 1282
18030 0 0 100.00% 4 1282
15229 0 0 100.00% 4 1282
44129 0 0 100.00% 4 1282
15222 0 0 100.00% 4 1282
34555 0 0 100.00% 4 1282
6400 0 0 100.00% 4 1282
27587 0 0 100.00% 4 1282
36645 0 0 100.00% 4 1282
33455 0 0 100.00% 4 1282
7864 0 0 100.00% 4 1282
12014 0 0 100.00% 4 1282
9349 0 0 100.00% 4 1282
2625 0 0 100.00% 4 1282
38570 0 0 100.00% 4 1283
^C 368 0 0 100.00% 4 1284
Detaching...
┌──[root@vms100.liruilongs.github.io]-[~]
└─$
可以使用这个工具发现缓存命中率较低的问题，或者说较高的缓存命空率问题。这可以给你指出性能调优的方向。
tcpconnect
tcpconnect(8)会在每次主动的TCP连接建立(例如，通过connect()调用)时，打印一行信息，包含源地址、目的地址。在输出中应该寻找不寻常的连接请求，它们可能会暴露出软件配置的低效，也可能暴露入侵行为。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$tcpconnect
Tracing connect ... Hit Ctrl-C to end
PID COMM IP SADDR DADDR DPORT
103502 curl 4 192.168.26.100 192.168.26.100 8000
103509 curl 4 192.168.26.100 192.168.26.100 8780
103512 mysql 4 192.168.26.100 192.168.26.100 3306
3053 haproxy 4 192.168.26.100 192.168.26.100 3306
3053 haproxy 4 192.168.26.100 192.168.26.102 4569
3053 haproxy 4 192.168.26.100 192.168.26.100 3306
103550 curl 4 192.168.26.100 192.168.26.100 5000
3053 haproxy 4 192.168.26.100 192.168.26.100 3306
3053 haproxy 4 192.168.26.100 192.168.26.100 4569
103572 mysql 4 192.168.26.100 192.168.26.100 3306
3053 haproxy 4 192.168.26.100 192.168.26.102 5000
3053 haproxy 4 192.168.26.100 192.168.26.102 8775
3053 haproxy 4 192.168.26.100 192.168.26.102 8000
................................
3053 haproxy 4 192.168.26.100 192.168.26.100 3306
3053 haproxy 4 192.168.26.100 192.168.26.102 35357
3053 haproxy 4 192.168.26.100 192.168.26.101 80
tcpaccept
tepaccept(8)是tcpconnect(8)工具的搭档。每当有被动的TCP连接建立时(通tcpaccept())，就会打印一行信息，同样包含源地址和目的地址。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$tcpaccept
PID COMM IP RADDR RPORT LADDR LPORT
3193 xinetd 6 ::ffff:192.168.26.100 55384 ::ffff:192.168.26.100 4569
6621 mariadbd 4 192.168.26.100 42682 192.168.26.100 3306
3193 xinetd 6 ::ffff:192.168.26.102 56114 ::ffff:192.168.26.100 4569
6621 mariadbd 4 192.168.26.100 42696 192.168.26.100 3306
3636 httpd 4 192.168.26.100 38142 192.168.26.100 80
3193 xinetd 6 ::ffff:192.168.26.101 47122 ::ffff:192.168.26.100 4569
6621 mariadbd 4 192.168.26.100 42700 192.168.26.100 3306
3994 httpd 4 192.168.26.100 57924 192.168.26.100 8004
3053 haproxy 4 192.168.26.101 51722 192.168.26.99 3306
6621 mariadbd 4 192.168.26.100 42702 192.168.26.100 3306
.......................................
6621 mariadbd 4 192.168.26.100 52492 192.168.26.100 3306
^C┌──[root@vms100.liruilongs.github.io]-[~]
└─$
tcpretrans
每次TCP重传数据包时，tcpretrans(8)会打印一行记录，包含源地址和目的地址，以及当时该TCP连接所处的内核状态。TCP重传会导致延迟和吞吐量方面的问题。
如果重传发生在 TCPESTABLISHED状态下，会进一步寻找外部网络可能存在的问题。如果重传发在SYNSENT状态下，这可能是CPU饱和的一个征兆，也可能是内核丢包引发的。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$tcpretrans
Tracing retransmits ... Hit Ctrl-C to end
TIME PID IP LADDR:LPORT T> RADDR:RPORT STATE
12:35:36 107232 4 192.168.26.100:39122 R> 192.168.26.100:3306 FIN_WAIT1
12:35:36 0 4 192.168.26.99:3306 R> 192.168.26.101:57360 ESTABLISHED
12:35:55 0 4 192.168.26.99:48370 R> 192.168.26.99:3306 FIN_WAIT1
12:36:07 11139 4 192.168.26.100:43004 R> 192.168.26.100:3306 FIN_WAIT1
12:36:07 11139 4 192.168.26.99:45960 R> 192.168.26.99:3306 FIN_WAIT1
12:36:07 11139 4 192.168.26.99:45950 R> 192.168.26.99:3306 FIN_WAIT1
12:36:07 3053 4 192.168.26.99:46030 R> 192.168.26.99:3306 FIN_WAIT1
12:36:07 27 4 192.168.26.99:46014 R> 192.168.26.99:3306 FIN_WAIT1
^C┌──[root@vms100.liruilongs.github.io]-[~]
└─$
runqlat
runqlat(8)对线程等待CPU运行的时间进行统计，并打印为一个直方图。本工具可以定位超出预期的CPU等待时间，就原因来说它可能是CPU饱和、配置错误或者是调度问题引起的。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$runqlat
Tracing run queue latency... Hit Ctrl-C to end.
^C
usecs : count distribution
0 -> 1 : 2065 |* |
2 -> 3 : 65759 |****************************************|
4 -> 7 : 10278 |****** |
8 -> 15 : 7693 |**** |
16 -> 31 : 3109 |* |
32 -> 63 : 2555 |* |
64 -> 127 : 2188 |* |
128 -> 255 : 2212 |* |
256 -> 511 : 2063 |* |
512 -> 1023 : 2527 |* |
1024 -> 2047 : 2394 |* |
2048 -> 4095 : 2544 |* |
4096 -> 8191 : 3062 |* |
8192 -> 16383 : 4041 |** |
16384 -> 32767 : 2552 |* |
32768 -> 65535 : 2212 |* |
65536 -> 131071 : 1534 | |
131072 -> 262143 : 757 | |
262144 -> 524287 : 286 | |
524288 -> 1048575 : 40 | |
1048576 -> 2097151 : 1 | |
┌──[root@vms100.liruilongs.github.io]-[~]
└─$
profile
profle(8)是一个CPU剖析器，这个工具可以用来理解哪些代码路径消耗了CPU资源。它周期性地对调用栈进行采样，然后将消重后的调用栈连同出现的次数一起打印出来。上面的输出经过了截断，只显示了一个调用栈，它出现的次数是58次。
┌──[root@vms100.liruilongs.github.io]-[~]
└─$profile
Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
^C
[unknown]
[unknown]
- privsep-helper (8392)
1
_PyEval_EvalFrameDefault
[unknown]
- httpd (3645)
1
smp_call_function_many_cond
smp_call_function_many_cond
on_each_cpu
cpa_flush
change_page_attr_set_clr
set_memory_ro
module_enable_ro.part.59
load_module
__do_sys_init_module
do_syscall_64
entry_SYSCALL_64_after_hwframe
[unknown]
[unknown]
- modprobe (8647)
1
PyDict_GetItem
[unknown]
- neutron-server: (7695)
1
[unknown]
[unknown]
[unknown]
[unknown]
- 4_scheduler (8373)
1
[unknown]
- neutron-server: (7666)
1
[unknown]
- check_alive.sh (8708)
1
[unknown]
[unknown]
- nova-scheduler (8562)
1
[unknown]
- httpd (4997)
博文部分内容参考
© 文中涉及参考链接内容版权归原作者所有，如有侵权请告知 :)
《BPF Performance Tools》
© 2018-2024 liruilonger@gmail.com, All rights reserved. 保持署名-非商用-相同方式共享(CC BY-NC-SA 4.0)
本文参与 腾讯云自媒体分享计划，分享自微信公众号。
原始发表：2024-04-01，如有侵权请联系 cloudcommunity@tencent.com 删除
评论
登录后参与评论
推荐阅读