不必太纠结于当下,也不必太忧虑未来,当你经历过一些事情的时候,眼前的风景已经和从前不一样了。——村上春树
写在前面
博文内容为 《BPF Performance Tools》
读书笔记整理
内容涉及 11 种 BCC 单一功能工具使用
理解不足小伙伴帮忙指正
不必太纠结于当下,也不必太忧虑未来,当你经历过一些事情的时候,眼前的风景已经和从前不一样了。——村上春树
关于 BCC
是什么这里不多介绍,小伙伴可以看我之前的文章
BCC工具检查清单 下面的内容 位于BCC仓库的docs/tutorial.md
文件中。它提供了个通用的使用 BCC 工具的检查清单:
https://github.com/iovisor/bcc/blob/master/docs/tutorial.md
execsnoop execsnoop(8)
通过跟踪每次 execve(2)
系统调用,为每个新创建的进程打印一行信息
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 ┌──[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)(文件打开)
系统调用(及其变体)时打印一行输出,包括详细信息。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 ┌──[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文件系统中常见的操作(读、写、打开和同步)
,并且可以把耗时超过某个阈值的操作
打印出来。
1 2 3 4 5 6 7 8 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延迟(也就是从向设备发出请求到请求完成的时间)
,并且以直方图
显示。
1 2 3 4 5 6 7 8 9 10 11 12 13 ┌──[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进行更细致的检查,并搜寻时序模式(比如,写动作之后的读排队)。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 ┌──[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)每秒(用户可以指定其他时长)打印一行摘要信息,展示文件系统缓存
的统计信息。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 ┌──[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()
调用)时,打印一行信息,包含源地址、目的地址
。在输出中应该寻找不寻常的连接请求,它们可能会暴露出软件配置的低效,也可能暴露入侵行为
。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 ┌──[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()),就会打印一行信息,同样包含源地址和目的地址。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 ┌──[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饱和的一个征兆,也可能是内核丢包引发的。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 ┌──[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饱和、配置错误或者是调度问题引起的。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 ┌──[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次。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 ┌──[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)