HackToTech

Hack To Technology

BPF本を読みながら学ぶ2

probeとかカーネルに関しての知識が浅すぎてとても難しい2章だった

目次

bitesize

ブロックデバイスのI/Oサイズをヒストグラムとして要約する
要求されたブロックサイズのI/O分布をプロセス名毎に表示する
block I/Oトレースポイントをトレースしてヒストグラムを更新する(カーネル空間側)
ユーザ空間側に非同期的にヒストグラムをコピーするのでオーバーヘッドがこくわずかで済む

前回と同様にddで書き込みながら試す

フィールド

Kbytes キロバイトの範囲
count Kbytesの範囲に入った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, 3.24655 s, 661 MB/s
❯ sudo /usr/share/bcc/tools/bitesize 
Tracing block I/O... Hit Ctrl-C to end.
^C
Process Name = kworker/3:1H
     Kbytes              : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 3        |****************************************|

Process Name = ThreadPoolForeg
     Kbytes              : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 1        |****************************************|

Process Name = nautilus-deskto
     Kbytes              : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 1        |****************************************|

Process Name = kworker/u256:1
     Kbytes              : count     distribution
         0 -> 1          : 9        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 39       |*                                       |
         8 -> 15         : 9        |                                        |
        16 -> 31         : 5        |                                        |
        32 -> 63         : 5        |                                        |
        64 -> 127        : 2        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 1        |                                        |
       512 -> 1023       : 778      |*************************************** |
      1024 -> 2047       : 781      |****************************************|

Process Name = jbd2/sda1-8
     Kbytes              : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 4        |****************************************|
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 2        |********************                    |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 2        |********************                    |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 1        |**********                              |

bpftool perf list

システム内の全てのraw_tracepoint, tracepoint, kprobeを表示する

terminal 2

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

❯ sudo bpftool perf list -p
[{
        "pid": 20499,
        "fd": 9,
        "prog_id": 19,
        "fd_type": "tracepoint",
        "tracepoint": "sys_enter_openat"
    }
]


❯ sudo bpftool prog show -p

[{
        "id": 19,
        "type": "tracepoint",
        "name": "sys_enter_opena",
        "tag": "1a6248388c2bcac4",
        "gpl_compatible": true,
        "loaded_at": 1570254902,
        "uid": 0,
        "bytes_xlated": 560,
        "jited": true,
        "bytes_jited": 371,
        "bytes_memlock": 4096,
        "map_ids": [18]
    }
]

vfsstat

一般的なVFS呼び出しをトレースし、一秒ごとの要約を出力する
ワークロードの特性評価、および時間経過に伴うオペレーションのパターンを見るのに役立つ
ユーザ空間側に非同期的にコピーするのでオーバーヘッドは小さい

フィールド

READ/s vfs_read()呼び出しの一秒あたりの平均数
WRITE/s vfs_write()呼び出しの一秒あたりの平均数
CREATE/s vfs_create()呼び出しの一秒あたりの平均数
OPEN/s vfs_open()呼び出しの一秒あたりの平均数
FSYNC/s vfs_fsync()呼び出しの一秒あたりの平均数
❯ sudo /usr/share/bcc/tools/vfsstat 
TIME         READ/s  WRITE/s CREATE/s   OPEN/s  FSYNC/s
10:32:21:        81       29        0        7        0
10:32:22:        70       30        0        5        0
10:32:23:       548      303        0     2045        0
10:32:24:        80      100        0        5        0
10:32:25:        30       29        0        6        0
10:32:26:        49       29        0       20        0
10:32:27:        29       28        0        5        0
10:32:28:      1000      339        0      526        0
10:32:29:        47       28        0       20        0
10:32:30:        29       28        0        5        0

gethostlatency

getaddrinfo(),gethostbyname(),gethostbyname2()が呼び出されたときにトレースおよび出力する

フィールド

PID 呼び出しを実行しているプロセスのID
COMM 呼び出しを実行しているプロセス(コマンド)名
LATms latency
HOST ルックアップのターゲットであるホスト名
❯ sudo /usr/share/bcc/tools/gethostlatency 
TIME      PID    COMM                  LATms HOST
10:41:40  36378  DNS Resolver #1       19.90 detectportal.firefox.com
10:41:40  36387  DNS Resolver #2        0.84 detectportal.firefox.com
10:41:40  36378  DNS Resolver #1       16.87 mozilla.org
10:41:40  36388  DNS Resolver #3       19.86 mozilla.org
10:41:41  36387  DNS Resolver #2       34.27 push.services.mozilla.com
10:41:41  36378  DNS Resolver #1        0.57 push.services.mozilla.com
10:41:41  36388  DNS Resolver #3        0.69 push.services.mozilla.com
10:41:41  36387  DNS Resolver #2       33.96 tiles.services.mozilla.com
10:41:41  36388  DNS Resolver #3       19.09 content-signature-2.cdn.mozilla.net
10:41:41  36378  DNS Resolver #1       36.61 ocsp.digicert.com

tcplife

TCPセッションをトレースして寿命(lifespan)を要約する
ワークロードの特性評価とフローアカウンティングに役立つ

フィールド

PID プロセスID
COMM 呼び出しを実行しているプロセス(コマンド)名
LADDR ローカルIP
LPORT ローカルポート
RADDR リモートIP
RPORT リモートポート
TX_KB トータルの送信(キロバイト)
RX_KB トータルの受信(キロバイト)
MS セッションの寿命
❯ sudo /usr/share/bcc/tools/tcplife 
PID   COMM       LADDR           LPORT RADDR           RPORT TX_KB RX_KB MS
41633 curl       192.168.221.129 36010 172.217.161.36  443       0    16 146.34
42828 curl       192.168.221.129 46722 182.22.59.229   443       0     5 67.13

USDT probe

node.jsのライブラリがあるので試してみる

terminal 1

~/workspace/usdt-example via ⬢ v10.15.3 took 11s 
❯ node index.js 
Firing probe...
Firing probe...
Firing probe...
Firing probe...
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Probe fired!
Firing probe...
Disable provider
Firing probe...
Disable provider
Firing probe...
Disable provider
terminal 2

❯ sudo /usr/share/bcc/tools/trace -p $(pgrep node) 'u::firstProbe "%d - %s", arg1, arg2'
PID     TID     COMM            FUNC             -
58156   58156   node            firstProbe       9 - My little string
58156   58156   node            firstProbe       8 - My little string
58156   58156   node            firstProbe       7 - My little string
58156   58156   node            firstProbe       6 - My little string
58156   58156   node            firstProbe       5 - My little string
58156   58156   node            firstProbe       4 - My little string
58156   58156   node            firstProbe       3 - My little string
58156   58156   node            firstProbe       2 - My little string
58156   58156   node            firstProbe       1 - My little string
58156   58156   node            firstProbe       0 - My little string

BPF本を読みながら学ぶ1

極力本の内容をまとめるというよりは、実際に手を動かして調べた内容を残す

環境は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 or 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