BPF Performance Toolsを読みながら学ぶ4

4章、BCCとその機能に関しての紹介が主な感じだった

目次

funccount

パターンにマッチしたファンクション、トレースポイント、USDTプローブの呼び出しをカウントする
頻度の高いイベントを参照させるとオーバーヘッドが大きくなる(例えば、malloc(), free())

tcp_connectが呼び出されたかを確認する

❯ sudo /usr/share/bcc/tools/funccount tcp_connect
Tracing 1 functions for "tcp_connect"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
tcp_connect                                 2
Detaching...

最も頻繁に呼び出されているVFSの機能はなにかを確認する

❯ sudo /usr/share/bcc/tools/funccount 'vfs_*'
Tracing 56 functions for "vfs_*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
vfs_symlink                                 1
vfs_statfs                                  1
vfs_setxattr                                1
vfs_rmdir                                   7
vfs_unlink                                  8
vfs_lock_file                              14
vfs_readlink                               93
vfs_statx                                 162
vfs_writev                                217
vfs_write                                 428
vfs_read                                  822
vfs_statx_fd                             1687
vfs_getattr_nosec                        2106
vfs_getattr                              2108
vfs_open                                 2114
Detaching...

1秒間隔でlibcのpthread_mutex_lockが呼び出された回数をトレースする

❯ sudo /usr/share/bcc/tools/funccount -i 1 c:pthread_mutex_lock
Tracing 1 functions for "c:pthread_mutex_lock"... Hit Ctrl-C to end.

FUNC                                    COUNT
pthread_mutex_lock                          2

FUNC                                    COUNT
pthread_mutex_lock                          2

FUNC                                    COUNT
pthread_mutex_lock                          2

FUNC                                    COUNT
pthread_mutex_lock                        924

FUNC                                    COUNT
pthread_mutex_lock                        132
^C
FUNC                                    COUNT
pthread_mutex_lock                         28
Detaching...

システム全体のlibcからの最も頻繁なstr関数呼び出しはなにか

❯ sudo /usr/share/bcc/tools/funccount c:str*
Tracing 62 functions for "c:str*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
strstr                                      2
strerror_thread_freeres                     3
strcat_ifunc                                5
strcspn_ifunc                               5
strpbrk_ifunc                               5
strspn_ifunc                                5
strncasecmp_l                               5
strchrnul                                   5
strcasecmp_l                                5
strcpy_ifunc                                6
strncpy_ifunc                               6
strncasecmp                                 6
strcasecmp                                  6
strtok_r                                    8
strrchr_ifunc                              10
strchr_ifunc                               11
strnlen                                    11
strcmp_ifunc                               12
strlen_ifunc                               12
strncmp_ifunc                              12
strtoll                                    80
strerror                                  127
strerror_r                                129
strdup                                    233
strtouq                                   303
strtoull_l                              19208
Detaching...

最も頻繁なsyscallはなにか

❯ sudo /usr/share/bcc/tools/funccount t:syscalls:sys_enter_*
Tracing 320 functions for "t:syscalls:sys_enter_*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
syscalls:sys_enter_accept4                  1
syscalls:sys_enter_getpeername              1
syscalls:sys_enter_add_key                  1
syscalls:sys_enter_inotify_rm_watch         1
syscalls:sys_enter_fstatfs                  1
syscalls:sys_enter_setxattr                 1
syscalls:sys_enter_dup2                     1
syscalls:sys_enter_symlink                  1
syscalls:sys_enter_execve                   1
syscalls:sys_enter_ftruncate                1
syscalls:sys_enter_chdir                    1
syscalls:sys_enter_sched_getaffinity        1
syscalls:sys_enter_getppid                  1
syscalls:sys_enter_getegid                  1
syscalls:sys_enter_setsid                   1
syscalls:sys_enter_newuname                 1
syscalls:sys_enter_set_tid_address          1
syscalls:sys_enter_arch_prctl               1
syscalls:sys_enter_shutdown                 2
syscalls:sys_enter_keyctl                   2
syscalls:sys_enter_dup3                     2
syscalls:sys_enter_getdents64               2
syscalls:sys_enter_rename                   2
syscalls:sys_enter_pipe2                    2
syscalls:sys_enter_geteuid                  2
syscalls:sys_enter_getrusage                2
syscalls:sys_enter_rt_sigreturn             2
syscalls:sys_enter_getsockopt               3
syscalls:sys_enter_lseek                    3
syscalls:sys_enter_brk                      3
syscalls:sys_enter_umask                    3
syscalls:sys_enter_capget                   3
syscalls:sys_enter_waitid                   3
syscalls:sys_enter_sendto                   4
syscalls:sys_enter_getgid                   4
syscalls:sys_enter_connect                  5
syscalls:sys_enter_getuid                   5
syscalls:sys_enter_utimensat                6
syscalls:sys_enter_rmdir                    8
syscalls:sys_enter_mkdir                    9
syscalls:sys_enter_gettid                   9
syscalls:sys_enter_inotify_add_watch       11
syscalls:sys_enter_select                  15
syscalls:sys_enter_timerfd_settime         17
syscalls:sys_enter_epoll_pwait             17
syscalls:sys_enter_sigaltstack             18
syscalls:sys_enter_bind                    22
syscalls:sys_enter_signalfd4               22
syscalls:sys_enter_kill                    22
syscalls:sys_enter_getsockname             23
syscalls:sys_enter_epoll_create1           23
syscalls:sys_enter_exit_group              23
syscalls:sys_enter_setsockopt              25
syscalls:sys_enter_prctl                   26
syscalls:sys_enter_socket                  28
syscalls:sys_enter_clone                   31
syscalls:sys_enter_mprotect                32
syscalls:sys_enter_set_robust_list         32
syscalls:sys_enter_newstat                 37
syscalls:sys_enter_wait4                   39
syscalls:sys_enter_getdents                40
syscalls:sys_enter_rt_sigprocmask          42
syscalls:sys_enter_io_getevents            49
syscalls:sys_enter_prlimit64               50
syscalls:sys_enter_unlink                  52
syscalls:sys_enter_getpid                  52
syscalls:sys_enter_fcntl                   54
syscalls:sys_enter_mmap                    56
syscalls:sys_enter_epoll_ctl               65
syscalls:sys_enter_setitimer               90
syscalls:sys_enter_recvfrom               100
syscalls:sys_enter_sendmsg                108
syscalls:sys_enter_kcmp                   115
syscalls:sys_enter_perf_event_open        117
syscalls:sys_enter_writev                 125
syscalls:sys_enter_rt_sigaction           129
syscalls:sys_enter_newfstatat             140
syscalls:sys_enter_munmap                 142
syscalls:sys_enter_times                  157
syscalls:sys_enter_pselect6               188
syscalls:sys_enter_nanosleep              195
syscalls:sys_enter_clock_gettime          200
syscalls:sys_enter_sched_yield            270
syscalls:sys_enter_getrandom              297
syscalls:sys_enter_epoll_wait             301
syscalls:sys_enter_bpf                    320
syscalls:sys_enter_write                  351
syscalls:sys_enter_access                 361
syscalls:sys_enter_ioctl                  436
syscalls:sys_enter_newlstat               449
syscalls:sys_enter_readlinkat             513
syscalls:sys_enter_read                   710
syscalls:sys_enter_newfstat              1657
syscalls:sys_enter_recvmsg               1768
syscalls:sys_enter_poll                  1813
syscalls:sys_enter_futex                 2176
syscalls:sys_enter_openat                2281
syscalls:sys_enter_close                 2546
Detaching...

stackcount

イベントにつながったスタックトレースをカウントする

ktime_get()につながったコードパスの特定(試しにコード追ってみた感じ参照は下から上っぽい)
-Pオプションでプロセス名+プロセスID

❯ sudo /usr/share/bcc/tools/stackcount ktime_get
Tracing 1 functions for "ktime_get"... Hit Ctrl-C to end.
^C
  ktime_get
  __schedule
  schedule
  io_schedule
  __lock_page_or_retry
  filemap_fault
  ext4_filemap_fault
  __do_fault
  __handle_mm_fault
  handle_mm_fault
  __do_page_fault
  do_page_fault
  page_fault
  [unknown]
    1

  ktime_get
  scsi_queue_rq
  blk_mq_dispatch_rq_list
  blk_mq_do_dispatch_sched
  blk_mq_sched_dispatch_requests
  __blk_mq_run_hw_queue
  __blk_mq_delay_run_hw_queue
  blk_mq_run_hw_queue
  blk_mq_sched_insert_requests
  blk_mq_flush_plug_list
  blk_flush_plug_list
  blk_finish_plug
  ext4_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_flush
  ext4_alloc_da_blocks
  ext4_rename
  ext4_rename2
  vfs_rename
  do_renameat2
  __x64_sys_rename
  do_syscall_64
  entry_SYSCALL_64_after_hwframe
  [unknown]
  [unknown]
  [unknown]
    1
--------------------------------------------------------------------------------
use -P option

  ktime_get
  do_idle
  cpu_startup_entry
  start_secondary
  secondary_startup_64
    swapper/1 [0]
    130

stackcountの結果からflamegraphを生成する

trace

イベントごとのカスタムな詳細を表示する
計測をするにあたってオーバーヘッドが大きいので、あまりに頻繁なイベントに対しては別のtoolを使ったほうが良い

❯ sudo /usr/share/bcc/tools/trace 'do_sys_open "%s", arg2'
PID     TID     COMM            FUNC             -
1968    3559    ftdc            do_sys_open      /proc/1968/stat
1968    3559    ftdc            do_sys_open      /proc/1968/stat
1968    3559    ftdc            do_sys_open      /proc/stat
1968    3559    ftdc            do_sys_open      /proc/meminfo
1968    3559    ftdc            do_sys_open      /proc/diskstats
1971    1971    snmpd           do_sys_open      /proc/net/dev
1971    1971    snmpd           do_sys_open      /proc/net/if_inet6
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr1/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/docker0/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/docker0/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/br-d794bdf9fb1e/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/br-d794bdf9fb1e/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr1-nic/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr0-nic/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/br-5b0ab1ed302c/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/br-5b0ab1ed302c/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr0/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/virbr0/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/lo/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/lo/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/lo/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/conf/lo/forwarding
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/lo/base_reachable_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/ens33/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/ens33/device/device
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/ens33/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/ens33/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/conf/ens33/forwarding
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/ens33/base_reachable_time_ms

条件つけてfilteringとかできるみたいなので、そこは結構ありがたそうな印象
色々と触ってみて構造体周りの出力ができると嬉しい…と思ったらあった!!!
これもっと良い書き方あるんだろうなって思って書いたので見逃してください

❯ sudo /usr/share/bcc/tools/trace 'tcp_connect(struct sock *sk) "%x", sk->sk_daddr' -I 'net/sock.h'
PID     TID     COMM            FUNC             -
1716    1716    curl            tcp_connect      4e1bd9ac

-----------------------------------------------------------------------

❯ python3
>>> from socket import inet_ntop, AF_INET
>>> from struct import pack
>>> inet_ntop(AF_INET, pack("I",  int('4e1bd9ac', base=16)))
'172.217.27.78'

-----------------------------------------------------------------------

❯ dig google.com

;; ANSWER SECTION:
google.com.        5   IN  A   172.217.27.78

argdist

関数をトレースし、パラメータのヒストグラムもしくはカウントを出力する
-Cでカウント
-Hでヒストグラム

vfs_read()によって返された結果のサイズのヒストグラムの出力

❯ sudo /usr/share/bcc/tools/argdist -H 'r::vfs_read()'
[13:23:14]
     retval              : count     distribution
         0 -> 1          : 5        |****************                        |
         2 -> 3          : 2        |******                                  |
         4 -> 7          : 12       |****************************************|
         8 -> 15         : 3        |**********                              |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 1        |***                                     |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 3        |**********                              |
       512 -> 1023       : 1        |***                                     |
      1024 -> 2047       : 2        |******                                  |
      2048 -> 4095       : 1        |***                                     |

試しにnginxへリクエストを投げた際のfdへの書き込みを確認する
(ログへの書き込み、straceは取れてargdistだと取れないのはなぜなのか…後で調べよう…)

// straceでとりあえず何が呼ばれているかを確認する
❯ sudo strace -p 15526
strace: Process 15526 attached
epoll_wait(11, [{EPOLLIN, {u32=4277780496, u64=139775398494224}}], 512, -1) = 1
accept4(7, {sa_family=AF_INET, sin_port=htons(41066), sin_addr=inet_addr("127.0.0.1")}, [112->16], SOCK_NONBLOCK) = 3
epoll_ctl(11, EPOLL_CTL_ADD, 3, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=4277781457, u64=139775398495185}}) = 0
epoll_wait(11, [{EPOLLIN, {u32=4277781457, u64=139775398495185}}], 512, 60000) = 1
recvfrom(3, "GET / HTTP/1.1\r\nHost: localhost:"..., 1024, 0, NULL, NULL) = 78
stat("/var/www/html/index.nginx-debian.html", {st_mode=S_IFREG|0644, st_size=612, ...}) = 0
openat(AT_FDCWD, "/var/www/html/index.nginx-debian.html", O_RDONLY|O_NONBLOCK) = 13
fstat(13, {st_mode=S_IFREG|0644, st_size=612, ...}) = 0
setsockopt(3, SOL_TCP, TCP_CORK, [1], 4) = 0
writev(3, [{iov_base="HTTP/1.1 200 OK\r\nServer: nginx/1"..., iov_len=247}], 1) = 247
sendfile(3, 13, [0] => [612], 612)      = 612
write(6, "127.0.0.1 - - [26/Oct/2019:22:48"..., 86) = 86
close(13)                               = 0
setsockopt(3, SOL_TCP, TCP_CORK, [0], 4) = 0
epoll_wait(11, [{EPOLLIN|EPOLLRDHUP, {u32=4277781457, u64=139775398495185}}], 512, 65000) = 1
recvfrom(3, "", 1024, 0, NULL, NULL)    = 0
close(3)                                = 0
epoll_wait(11, ^Cstrace: Process 15526 detached
 <detached ...>

-----------------------------------------------------------------------------------------------------------------------------

// writeだと何も出ない(ログへの書き込みは出ない)
❯ sudo /usr/share/bcc/tools/argdist -p 15526 -C 'p:c:write(int fd):int:fd'
[23:03:14]
p:c:write(int fd):int:fd
	COUNT      EVENT
[23:03:15]
p:c:write(int fd):int:fd
	COUNT      EVENT
[23:03:16]
p:c:write(int fd):int:fd
	COUNT      EVENT

-----------------------------------------------------------------------------------------------------------------------------

// writevだと出る(ソケットへの書き込みは出る)
❯ sudo /usr/share/bcc/tools/argdist -p 15526 -C 'p:c:writev(int fd):int:fd'
[23:03:50]
p:c:writev(int fd):int:fd
	COUNT      EVENT
[23:03:51]
p:c:writev(int fd):int:fd
	COUNT      EVENT
[23:03:52]
p:c:writev(int fd):int:fd
	COUNT      EVENT
	1          fd = 3
[23:03:53]
p:c:writev(int fd):int:fd
	COUNT      EVENT
[23:03:54]
p:c:writev(int fd):int:fd
	COUNT      EVENT
	1          fd = 3

-----------------------------------------------------------------------------------------------------------------------------

/proc/15526
❯ sudo ls -lh fd/
total 0
dr-x------ 2 www-data www-data  0 Oct 26 22:47 .
dr-xr-xr-x 9 www-data www-data  0 Oct 26 18:53 ..
lrwx------ 1 www-data www-data 64 Oct 26 23:09 0 -> /dev/null
lrwx------ 1 www-data www-data 64 Oct 26 23:09 1 -> /dev/null
lrwx------ 1 www-data www-data 64 Oct 26 23:09 10 -> 'socket:[95871]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 11 -> 'anon_inode:[eventpoll]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 12 -> 'anon_inode:[eventfd]'
l-wx------ 1 www-data www-data 64 Oct 26 23:09 2 -> /var/log/nginx/error.log
l-wx------ 1 www-data www-data 64 Oct 26 23:09 4 -> /var/log/nginx/access.log
l-wx------ 1 www-data www-data 64 Oct 26 23:09 5 -> /var/log/nginx/error.log
l-wx------ 1 www-data www-data 64 Oct 26 23:09 6 -> /var/log/nginx/main.log
lrwx------ 1 www-data www-data 64 Oct 26 23:09 7 -> 'socket:[95866]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 8 -> 'socket:[95867]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 9 -> 'socket:[95868]'