BCC
BCC
目录
用例教程 - 基本
安装完再看这里
这些工具可能安装在您的系统上的 /usr/share/bcc/tools 下,或者您也可以从 /tools 下的 bcc github 存储库运行它们,其中它们具有 .py 扩展名。浏览 50 多种可用工具以获得更多分析选项。
常规性能
目录
- execsnoop, 为每个新进程打印一行输出
- opensnoop, 打开监听
- ext4slower, 跟踪 ext4 文件系统
- biolatency, 跟踪磁盘 I/O 延迟
- biosnoop, 为每个磁盘 I/O 打印一行输出,其中包含延迟(从设备发出到完成的时间)等详细信息
- cachestat每秒(或每个自定义时间间隔)打印一行摘要,显示文件系统缓存的统计信息
- tcpconnect, 为每个活动的 TCP 连接(例如,通过 connect())打印一行输出,其中包括源地址和目标地址等详细信息
- tcpaccept, 为每个被动 TCP 连接(例如,通过accept())打印一行输出,其中包括源地址和目标地址等详细信息
- tcpretrans, 为每个 TCP 重传数据包打印一行输出,其中包括源地址和目标地址以及 TCP 连接的内核状态等详细信息
- runqlat, 计算线程在 CPU 运行队列上等待的时间,并将其打印为直方图
- profile, 一个 CPU 分析器,它以一定的时间间隔采集堆栈跟踪样本,并打印唯一堆栈跟踪的摘要及其出现次数
execsnoop
# ./execsnoop
PCOMM PID RET ARGS
supervise 9660 0 ./run
supervise 9661 0 ./run
mkdir 9662 0 /bin/mkdir -p ./main
run 9663 0 ./run
[...]
execsnoop 为每个新进程打印一行输出。检查短期进程。这些可能会消耗 CPU 资源,但不会出现在大多数定期拍摄正在运行的进程的快照的监控工具中。
它通过跟踪 exec() 而不是 fork() 来工作,因此它将捕获多种类型的新进程,但不是全部(例如,它不会看到应用程序启动工作进程,也不会执行 exec() 任何其他进程)。
More examples
opensnoop
# ./opensnoop
PID COMM FD ERR PATH
1565 redis-server 5 0 /proc/1565/stat
1565 redis-server 5 0 /proc/1565/stat
1565 redis-server 5 0 /proc/1565/stat
1603 snmpd 9 0 /proc/net/dev
1603 snmpd 11 0 /proc/net/if_inet6
1603 snmpd -1 2 /sys/class/net/eth0/device/vendor
1603 snmpd 11 0 /proc/sys/net/ipv4/neigh/eth0/retrans_time_ms
1603 snmpd 11 0 /proc/sys/net/ipv6/neigh/eth0/retrans_time_ms
1603 snmpd 11 0 /proc/sys/net/ipv6/conf/eth0/forwarding
[...]
为每个 open() 系统调用打印一行输出,包括详细信息。
打开的文件可以告诉您很多有关应用程序如何工作的信息:识别它们的数据文件、配置文件和日志文件。有时,当应用程序不断尝试读取不存在的文件时,它们可能会行为不当且性能不佳。 opensnoop 让您快速浏览一下。
More examples.
ext4slower (or btrfs*
, xfs*
, zfs*
)
# ./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
ext4slower 跟踪 ext4 文件系统并对常见操作进行计时,然后仅打印超出阈值的操作。
这对于识别或消除一种类型的性能问题非常有用:通过文件系统显示单独的缓慢磁盘 I/O。磁盘异步处理 I/O,可能很难将该层的延迟与延迟应用程序体验相关联。在内核堆栈中向上跟踪,在 VFS -> 文件系统接口处,将更接近地匹配应用程序所遭受的情况。使用此工具可以确定文件系统延迟是否超过给定阈值。
其他文件系统的 bcc 中也存在类似的工具:btrfsslower、xfsslower 和 zfsslower。还有 fileslower,它在 VFS 层工作并跟踪所有内容(尽管开销较高)
More examples.
biolatency
# ./biolatency
Tracing block device I/O... Hit Ctrl-C to end.
^C
usecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 1 | |
128 -> 255 : 12 |******** |
256 -> 511 : 15 |********** |
512 -> 1023 : 43 |******************************* |
1024 -> 2047 : 52 |**************************************|
2048 -> 4095 : 47 |********************************** |
4096 -> 8191 : 52 |**************************************|
8192 -> 16383 : 36 |************************** |
16384 -> 32767 : 15 |********** |
32768 -> 65535 : 2 |* |
65536 -> 131071 : 2 |* |
biolatency 跟踪磁盘 I/O 延迟(从设备发出到完成的时间),当工具结束时(Ctrl-C 或给定间隔),它会打印延迟的直方图摘要。
这对于了解超出 iostat 等工具给出的平均时间的磁盘 I/O 延迟非常有用。 I/O 延迟异常值在分发以及多模式分发结束时将可见。
More examples
biosnoop
# ./biosnoop
TIME(s) COMM PID DISK T SECTOR BYTES LAT(ms)
0.000004001 supervise 1950 xvda1 W 13092560 4096 0.74
0.000178002 supervise 1950 xvda1 W 13092432 4096 0.61
0.001469001 supervise 1956 xvda1 W 13092440 4096 1.24
0.001588002 supervise 1956 xvda1 W 13115128 4096 1.09
1.022346001 supervise 1950 xvda1 W 13115272 4096 0.98
1.022568002 supervise 1950 xvda1 W 13188496 4096 0.93
[...]
biosnoop 为每个磁盘 I/O 打印一行输出,其中包含延迟(从设备发出到完成的时间)等详细信息。
这使您可以更详细地检查磁盘 I/O,并查找按时间排序的模式(例如,在写入后面排队的读取)。请注意,如果您的系统以高速率执行磁盘 I/O,则输出将会很详细。
More examples
cachestat
# ./cachestat
HITS MISSES DIRTIES READ_HIT% WRITE_HIT% BUFFERS_MB CACHED_MB
1074 44 13 94.9% 2.9% 1 223
2195 170 8 92.5% 6.8% 1 143
182 53 56 53.6% 1.3% 1 143
62480 40960 20480 40.6% 19.8% 1 223
7 2 5 22.2% 22.2% 1 223
348 0 0 100.0% 0.0% 1 223
[...]
cachestat 每秒(或每个自定义时间间隔)打印一行摘要,显示文件系统缓存的统计信息。
使用它来识别低缓存命中率和高未命中率:这为性能调整提供了线索。
More examples
tcpconnect
# ./tcpconnect
PID COMM IP SADDR DADDR DPORT
1479 telnet 4 127.0.0.1 127.0.0.1 23
1469 curl 4 10.201.219.236 54.245.105.25 80
1469 curl 4 10.201.219.236 54.67.101.145 80
1991 telnet 6 ::1 ::1 23
2015 ssh 6 fe80::2000:bff:fe82:3ac fe80::2000:bff:fe82:3ac 22
[...]
tcpconnect 为每个活动的 TCP 连接(例如,通过 connect())打印一行输出,其中包括源地址和目标地址等详细信息。
查找可能导致应用程序配置效率低下或入侵者的意外连接。
More examples.
tcpaccept
# ./tcpaccept
PID COMM IP RADDR LADDR LPORT
907 sshd 4 192.168.56.1 192.168.56.102 22
907 sshd 4 127.0.0.1 127.0.0.1 22
5389 perl 6 1234:ab12:2040:5020:2299:0:5:0 1234:ab12:2040:5020:2299:0:5:0 7001
[...]
tcpaccept 为每个被动 TCP 连接(例如,通过accept())打印一行输出,其中包括源地址和目标地址等详细信息。
查找可能导致应用程序配置效率低下或入侵者的意外连接。
More examples.
tcpretrans
# ./tcpretrans
TIME PID IP LADDR:LPORT T> RADDR:RPORT STATE
01:55:05 0 4 10.153.223.157:22 R> 69.53.245.40:34619 ESTABLISHED
01:55:05 0 4 10.153.223.157:22 R> 69.53.245.40:34619 ESTABLISHED
01:55:17 0 4 10.153.223.157:22 R> 69.53.245.40:22957 ESTABLISHED
[...]
tcprerans 为每个 TCP 重传数据包打印一行输出,其中包括源地址和目标地址以及 TCP 连接的内核状态等详细信息。
TCP 重传会导致延迟和吞吐量问题。对于 ESTABLISHED 重传,寻找网络模式。对于 SYN_SENT,这可能表明目标内核 CPU 饱和和内核数据包丢失。
More examples.
runqlat
# ./runqlat
Tracing run queue latency... Hit Ctrl-C to end.
^C
usecs : count distribution
0 -> 1 : 233 |*********** |
2 -> 3 : 742 |************************************ |
4 -> 7 : 203 |********** |
8 -> 15 : 173 |******** |
16 -> 31 : 24 |* |
32 -> 63 : 0 | |
64 -> 127 : 30 |* |
128 -> 255 : 6 | |
256 -> 511 : 3 | |
512 -> 1023 : 5 | |
1024 -> 2047 : 27 |* |
2048 -> 4095 : 30 |* |
4096 -> 8191 : 20 | |
8192 -> 16383 : 29 |* |
16384 -> 32767 : 809 |****************************************|
32768 -> 65535 : 64 |*** |
runqlat 计算线程在 CPU 运行队列上等待的时间,并将其打印为直方图。
这可以帮助量化在 CPU 饱和期间等待打开 CPU 所损失的时间。
More examples.
profile
# ./profile
Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
^C
00007f31d76c3251 [unknown]
47a2c1e752bf47f7 [unknown]
- sign-file (8877)
1
ffffffff813d0af8 __clear_user
ffffffff813d5277 iov_iter_zero
ffffffff814ec5f2 read_iter_zero
ffffffff8120be9d __vfs_read
ffffffff8120c385 vfs_read
ffffffff8120d786 sys_read
ffffffff817cc076 entry_SYSCALL_64_fastpath
00007fc5652ad9b0 read
- dd (25036)
4
0000000000400542 func_a
0000000000400598 main
00007f12a133e830 __libc_start_main
083e258d4c544155 [unknown]
- func_ab (13549)
5
[...]
ffffffff8105eb66 native_safe_halt
ffffffff8103659e default_idle
ffffffff81036d1f arch_cpu_idle
ffffffff810bba5a default_idle_call
ffffffff810bbd07 cpu_startup_entry
ffffffff8104df55 start_secondary
- swapper/1 (0)
75
profile 是一个 CPU 分析器,它以一定的时间间隔采集堆栈跟踪样本,并打印唯一堆栈跟踪的摘要及其出现次数。
使用此工具可以了解消耗 CPU 资源的代码路径。
More examples.
使用通用工具的可观察性
除了上述用于性能调整的工具之外,下面是 bcc 通用工具的清单,首先作为列表,然后详细说明:
- trace
- argdist
- funccount
这些通用工具可能有助于提供可视性来解决您的特定问题。
trace
example1
假设您要跟踪文件所有权更改。用户可以使用三个系统调用 chown
、 fchown
和 lchown
来更改文件所有权。对应的系统调用条目是 SyS_[f|l]chown
。以下命令可用于打印系统调用参数和调用进程用户 ID。您可以使用 id
命令查找特定用户的uid。
$ trace.py \
'p::SyS_chown "file = %s, to_uid = %d, to_gid = %d, from_uid = %d", arg1, arg2, arg3, $uid' \
'p::SyS_fchown "fd = %d, to_uid = %d, to_gid = %d, from_uid = %d", arg1, arg2, arg3, $uid' \
'p::SyS_lchown "file = %s, to_uid = %d, to_gid = %d, from_uid = %d", arg1, arg2, arg3, $uid'
PID TID COMM FUNC -
1269255 1269255 python3.6 SyS_lchown file = /tmp/dotsync-usisgezu/tmp, to_uid = 128203, to_gid = 100, from_uid = 128203
1269441 1269441 zstd SyS_chown file = /tmp/dotsync-vic7ygj0/dotsync-package.zst, to_uid = 128203, to_gid = 100, from_uid = 128203
1269255 1269255 python3.6 SyS_lchown file = /tmp/dotsync-a40zd7ev/tmp, to_uid = 128203, to_gid = 100, from_uid = 128203
1269442 1269442 zstd SyS_chown file = /tmp/dotsync-gzp413o_/dotsync-package.zst, to_uid = 128203, to_gid = 100, from_uid = 128203
1269255 1269255 python3.6 SyS_lchown file = /tmp/dotsync-whx4fivm/tmp/.bash_profile, to_uid = 128203, to_gid = 100, from_uid = 128203
example2
假设您想要在基于 bpf 的性能监控工具中对非自愿上下文切换 ( nvcsw
) 进行计数,并且您不知道什么是正确的方法。 /proc/<pid>/status
已经告诉您 pid 的编号 ( nonvoluntary_ctxt_switches
),您可以使用 trace.py
进行快速实验来验证您的方法。对于内核源代码, nvcsw
在文件 linux/kernel/sched/core.c
函数 __schedule
处进行计数,并在条件下
!(!preempt && prev->state) // i.e., preempt || !prev->state
__schedule
函数被标记为 notrace
,评估上述条件的最佳位置似乎是在函数 __schedule
内部调用并在 linux/include/trace/events/sched.h
中定义的 sched/sched_switch
跟踪点。 trace.py
已经将 args
作为指向跟踪点 TP_STRUCT__entry
的指针。上述条件在函数 __schedule
中可以表示为
args->prev_state == TASK_STATE_MAX || args->prev_state == 0
下面的命令可用于计算非自愿上下文切换(每个进程或每个 pid),并与 /proc/<pid>/status
或 /proc/<pid>/task/<task_id>/status
进行比较以确保正确性,因为在典型情况下,非自愿上下文切换并不常见。
$ trace.py -p 1134138 't:sched:sched_switch (args->prev_state == TASK_STATE_MAX || args->prev_state == 0)'
PID TID COMM FUNC
1134138 1134140 contention_test sched_switch
1134138 1134142 contention_test sched_switch
...
$ trace.py -L 1134140 't:sched:sched_switch (args->prev_state == TASK_STATE_MAX || args->prev_state == 0)'
PID TID COMM FUNC
1134138 1134140 contention_test sched_switch
1134138 1134140 contention_test sched_switch
...
example3
此示例与issue 1231 和 1516 相关,其中 uprobe 在某些情况下根本不起作用。首先,您可以执行以下操作 strace
$ strace trace.py 'r:bash:readline "%s", retval'
...
perf_event_open(0x7ffd968212f0, -1, 0, -1, 0x8 /* PERF_FLAG_??? */) = -1 EIO (Input/output error)
...
perf_event_open
系统调用返回 -EIO
。深入 /kernel/trace
和 /kernel/events
目录下的内核uprobe相关代码进行搜索 EIO
,函数 uprobe_register
是最可疑的。让我们看看这个函数是否被调用,如果被调用,返回值是多少。在一个终端使用以下命令打印出uprobe_register的返回值,
$ trace.py 'r::uprobe_register "ret = %d", retval'
在另一个终端中运行相同的 bash uretprobe 跟踪示例,您应该得到
$ trace.py 'r::uprobe_register "ret = %d", retval'
PID TID COMM FUNC -
1041401 1041401 python2.7 uprobe_register ret = -5
-5
错误代码是 EIO。这证实了函数 uprobe_register
中的以下代码是最可疑的罪魁祸首。
if (!inode->i_mapping->a_ops->readpage && !shmem_mapping(inode->i_mapping))
return -EIO;
shmem_mapping
函数定义为
bool shmem_mapping(struct address_space *mapping)
{
return mapping->a_ops == &shmem_aops;
}
为了证实这一理论,请使用以下命令查找 inode->i_mapping->a_ops
是什么
$ trace.py -I 'linux/fs.h' 'p::uprobe_register(struct inode *inode) "a_ops = %llx", inode->i_mapping->a_ops'
PID TID COMM FUNC -
814288 814288 python2.7 uprobe_register a_ops = ffffffff81a2adc0
^C$ grep ffffffff81a2adc0 /proc/kallsyms
ffffffff81a2adc0 R empty_aops
More examples.
argdist
More examples.
funccount
More examples.