Linux BPF性能分析之基于BCC工具清单检查

举报
山河已无恙 发表于 2024/09/07 20:03:39 2024/09/07
【摘要】 写在前面博文内容为 《BPF Performance Tools》 读书笔记整理内容涉及 11 种 BCC 单一功能工具使用理解不足小伙伴帮忙指正 不必太纠结于当下，也不必太忧虑未来，当你经历过一些事情的时候，眼前的风景已经和从前不一样了。——村上春树关于 BCC 是什么这里不多介绍，小伙伴可以看我之前的文章 BCC工具检查清单下面的内容 位于BCC仓库的docs/tutorial.md ...

写在前面

  • 博文内容为 《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) 系统调用,为每个新创建的进程打印一行信息

┌──[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)

【版权声明】本文为华为云社区用户原创内容，转载时必须标注文章的来源（华为云社区）、文章链接、文章作者等基本信息， 否则作者和本社区有权追究责任。如果您发现本社区中有涉嫌抄袭的内容，欢迎发送邮件进行举报，并提供相关证据，一经查实，本社区将立刻删除涉嫌侵权内容，举报邮箱： cloudbbs@huaweicloud.com
  • 点赞
  • 收藏
  • 关注作者

评论（0）

0/1000
抱歉，系统识别当前为高风险访问，暂不支持该操作

全部回复

上滑加载中

设置昵称

在此一键设置昵称，即可参与社区互动！

*长度不超过10个汉字或20个英文字符，设置后3个月内不可修改。

*长度不超过10个汉字或20个英文字符，设置后3个月内不可修改。

确认 取消

加入云驻计划，成为创作者

  • 华为云周边好礼
  • 免费体验产品
  • 特殊身份标识
  • 线下官方门票
  • 内部专家零距离
  • 与10000+优质创作者共同成长
立即加入