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の結果からframegraphを生成する
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]'
