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

本の内容をまとめるというよりは、実際に手を動かして調べた内容を残すメモ書きのような方針です(本の内容についてはSafariで読むもしくは物理本を買ってください)
物理本はまだ発売されていないので読み進めるのはO’reillyのSafariで読める方です
詳細は公式を見てください
また、調べた内容について間違っている恐れもあるので、話半分ぐらいに読んでください

環境はUbuntu18.04です

目次

execsnoop

execve()システムコール(exec()システムコール)をトレースする
fork -> exec()のシーケンスからexec()をトレースする
worker processの実行は出力されない

starshipをterminalで使っているので色々と実行がされているがコマンド的に実行したのはlsのみ
普段のterminal上でコマンドを実行しただけでもこれだけプロセスが発生していることがわかる

TIME(s)はexec()が戻ってくるまでの時間っぽい(Time of exec() return, in seconds.)が収集開始時からのTIMESTAMP的な意味合いが強そう
PCOMMは親プロセスもしくはコマンド名
PIDはプロセスID
PPIDは親プロセスID(読み取れなければ0)
RETはexec()の戻り値(0は成功, 失敗は-xオプションをつけないと見えない)
ARGSはコマンドライン引数(読み取れなければ?)

コマンドを実行したterminal

❯ ls
//省略

❯ echo $$
25353 //execsnoopした際に出力されているlsのPPIDと一致している
❯ sudo /usr/share/bcc/tools/execsnoop -t
TIME(s) PCOMM            PID    PPID   RET ARGS
1.531   date             31610  31609    0 /bin/date +%s
1.532   ls               31611  25353    0 /bin/ls --color=auto
1.535   date             31613  31612    0 /bin/date +%s
1.538   wc               31617  31615    0 /usr/bin/wc -l
1.539   starship         31618  31614    0 /usr/local/bin/starship prompt --status=0 --jobs=0 --cmd-duration=0
1.549   id               31623  31618    0 /usr/bin/id -u

// -xをつけてerrorの場合
2.133 bash             40723  25353   -2 /hoge/hoge

biolatency

ブロックデバイスのI/Oレイテンシをヒストグラムとして要約する

深堀りする場合は別のBPFツールを使って調べる

msecsはミリ秒の範囲
countはmsecsの範囲に入ったI/Oの数
distributionはcountの可視化

コマンドを実行したterminal

❯ dd if=/dev/zero of=./swapfile bs=1M count=2048
2048+0 records in
2048+0 records out
2147483648 bytes (2.1 GB, 2.0 GiB) copied, 8.62627 s, 249 MB/s
~ took 9s 
❯ sudo /usr/share/bcc/tools/biolatency -m
Tracing block device I/O... Hit Ctrl-C to end.
^C
     msecs               : count     distribution
         0 -> 1          : 798      |****************************************|
         2 -> 3          : 111      |*****                                   |
         4 -> 7          : 172      |********                                |
         8 -> 15         : 659      |*********************************       |
        16 -> 31         : 432      |*********************                   |
        32 -> 63         : 13       |                                        |

syscalls:sys_enter_open , syscalls:sys_enter_openat

glibc >= 2.26だとopenのラッパーは常にopenatを呼び出すので、そちらでトレースしないと取得できないっぽい

commはプロセス名
str(args->filename)はargsが全てのトレースポイント引数を含む構造体へのポインタ、filenameはメンバー

~ took 2s 
❯ sudo bpftrace -e 'tracepoint:syscalls:sys_enter_openat { printf("%s %s\n", comm, str(args->filename)); }'

irqbalance /proc/interrupts
irqbalance /proc/stat
date /etc/ld.so.cache
date /lib/x86_64-linux-gnu/libc.so.6
date /usr/lib/locale/locale-archive
date /etc/localtime
cat /etc/ld.so.cache
cat /lib/x86_64-linux-gnu/libc.so.6
cat /usr/lib/locale/locale-archive
cat /proc/cpuinfo
date /etc/ld.so.cache
date /lib/x86_64-linux-gnu/libc.so.6
date /usr/lib/locale/locale-archive
date /etc/localtime
ibus-engine-moz /home/atrophy/.mozc/.renderer.:0.ipc
ibus-engine-moz /home/atrophy/.mozc/.renderer.:0.ipc
wc /etc/ld.so.cache
wc /lib/x86_64-linux-gnu/libc.so.6
wc /usr/lib/locale/locale-archive
wc /usr/share/locale/locale.alias
wc /usr/share/locale/en_US/LC_MESSAGES/coreutils.mo
wc /usr/share/locale/en/LC_MESSAGES/coreutils.mo
wc /usr/share/locale-langpack/en_US/LC_MESSAGES/coreutils.mo
wc /usr/share/locale-langpack/en/LC_MESSAGES/coreutils.mo
starship /etc/ld.so.cache
starship /lib/x86_64-linux-gnu/libz.so.1
starship /lib/x86_64-linux-gnu/libdl.so.2
starship /lib/x86_64-linux-gnu/librt.so.1
starship /lib/x86_64-linux-gnu/libpthread.so.0
starship /lib/x86_64-linux-gnu/libgcc_s.so.1
starship /lib/x86_64-linux-gnu/libc.so.6
starship /lib/x86_64-linux-gnu/libm.so.6
starship /proc/self/maps
starship /home/atrophy/.config/starship.toml
starship /home/atrophy
starship /dev/urandom
starship /usr/lib/ssl/certs/ca-certificates.crt
starship /sys/class/power_supply
starship /sys/class/power_supply/ACAD/type
starship Cargo.toml
starship package.json
starship pyproject.toml
starship /dev/null

opensnoop

PIDはプロセスID
COMMはプロセス名
FDはファイルディスクリプタ
ERRはエラーコード
PATHはファイルパス

~ took 5s 
❯ sudo /usr/share/bcc/tools/opensnoop 
PID    COMM               FD ERR PATH
1730   snmpd              15   0 /proc/net/dev
1730   snmpd              17   0 /proc/net/if_inet6
1730   snmpd              -1   2 /sys/class/net/virbr1-nic/device/vendor
1730   snmpd              -1   2 /sys/class/net/virbr0/device/vendor
1730   snmpd              17   0 /proc/sys/net/ipv4/neigh/virbr0/retrans_time_ms
1730   snmpd              -1   2 /sys/class/net/vboxnet1/device/vendor
1730   snmpd              -1   2 /sys/class/net/lo/device/vendor
1730   snmpd              17   0 /proc/sys/net/ipv4/neigh/lo/retrans_time_ms
1730   snmpd              17   0 /proc/sys/net/ipv6/neigh/lo/retrans_time_ms
1730   snmpd              17   0 /proc/sys/net/ipv6/conf/lo/forwarding
1730   snmpd              17   0 /proc/sys/net/ipv6/neigh/lo/base_reachable_time_ms
1730   snmpd              -1   2 /sys/class/net/vboxnet0/device/vendor
1730   snmpd              -1   2 /sys/class/net/docker0/device/vendor
1730   snmpd              17   0 /proc/sys/net/ipv4/neigh/docker0/retrans_time_ms
1730   snmpd              17   0 /sys/class/net/ens33/device/vendor
1730   snmpd              17   0 /sys/class/net/ens33/device/device
1730   snmpd              17   0 /proc/sys/net/ipv4/neigh/ens33/retrans_time_ms
1730   snmpd              17   0 /proc/sys/net/ipv6/neigh/ens33/retrans_time_ms
1730   snmpd              17   0 /proc/sys/net/ipv6/conf/ens33/forwarding
1730   snmpd              17   0 /proc/sys/net/ipv6/neigh/ens33/base_reachable_time_ms
1730   snmpd              -1   2 /sys/class/net/virbr1/device/vendor
1730   snmpd              -1   2 /sys/class/net/virbr0-nic/device/vendor
1730   snmpd              -1   2 /sys/class/net/br-d794bdf9fb1e/device/vendor
1730   snmpd              17   0 /proc/sys/net/ipv4/neigh/br-d794bdf9fb1e/retrans_time_ms
43615  opensnoop          -1   2 /usr/lib/python2.7/encodings/ascii.x86_64-linux-gnu.so
43615  opensnoop          -1   2 /usr/lib/python2.7/encodings/ascii.so
43615  opensnoop          -1   2 /usr/lib/python2.7/encodings/asciimodule.so
43615  opensnoop          14   0 /usr/lib/python2.7/encodings/ascii.py
43615  opensnoop          15   0 /usr/lib/python2.7/encodings/ascii.pyc
1730   snmpd              15   0 /proc/diskstats
1730   snmpd              15   0 /proc/stat
1730   snmpd              15   0 /proc/vmstat
^C

-xでエラーのみを取得できる

❯ sudo /usr/share/bcc/tools/opensnoop -x
PID    COMM               FD ERR PATH
1730   snmpd              -1   2 /sys/class/net/virbr1-nic/device/vendor
1730   snmpd              -1   2 /sys/class/net/virbr0/device/vendor
1730   snmpd              -1   2 /sys/class/net/vboxnet1/device/vendor
1730   snmpd              -1   2 /sys/class/net/lo/device/vendor
1730   snmpd              -1   2 /sys/class/net/vboxnet0/device/vendor
1730   snmpd              -1   2 /sys/class/net/docker0/device/vendor
1730   snmpd              -1   2 /sys/class/net/virbr1/device/vendor
1730   snmpd              -1   2 /sys/class/net/virbr0-nic/device/vendor
1730   snmpd              -1   2 /sys/class/net/br-d794bdf9fb1e/device/vendor
43640  opensnoop          -1   2 /usr/lib/python2.7/encodings/ascii.x86_64-linux-gnu.so
43640  opensnoop          -1   2 /usr/lib/python2.7/encodings/ascii.so
43640  opensnoop          -1   2 /usr/lib/python2.7/encodings/asciimodule.so
^C