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

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

3章、ドリルダウンやUSEメソッドなど実際にどのようにパフォーマンスを改善するかを考えていく
また、非BPFのツールとBPFのツールの説明など

目次

uptime

システムの稼働時間を表示(現在の状態を簡単に確認する)

現在時刻, 起動時間, ログオンしてるユーザ数, ロードアベレージ(1, 5, 15)

❯ uptime
 12:28:32 up 53 min,  1 user,  load average: 0.23, 0.35, 0.31

dmesg

カーネルリングバッファーにあるメッセージを表示する

❯ dmesg | tail
[  193.692502] docker0: port 1(veth9bcda5b) entered disabled state
[  193.876898] eth0: renamed from vethce87622
[  193.893387] IPv6: ADDRCONF(NETDEV_CHANGE): veth9bcda5b: link becomes ready
[  193.893535] docker0: port 1(veth9bcda5b) entered blocking state
[  193.893536] docker0: port 1(veth9bcda5b) entered forwarding state
[  387.024658] docker0: port 1(veth9bcda5b) entered disabled state
[  387.024897] vethce87622: renamed from eth0
[  387.060913] docker0: port 1(veth9bcda5b) entered disabled state
[  387.062989] device veth9bcda5b left promiscuous mode
[  387.062994] docker0: port 1(veth9bcda5b) entered disabled state

vmstat

プロセス、メモリ、ページング、ブロックIO、トラップ、ディスク、CPUの状態に関する情報をレポートする

rは実行可能なプロセスの数(実行中もしくは実行待ち)
bは割り込み不可能なスリープ状態のプロセスの数(プロセスがカーネル空間(システムコール内)にあり、IOを実行しているなど)
swpdは使用している仮想メモリ量
freeは空いているメモリ量
buffはバッファとして使用しているメモリ量
cacheはキャッシュとして使用しているメモリ量
siはディスクからスワップインされたメモリ量(/s)
soはディスクにスワップされたメモリ量(/s)
biはブロックデバイスから受信したブロック数(/s)
boはブロックデバイスに送信されたブロック数(/s)
inはクロックタイマー割り込みを含む1秒あたりの割り込み数
csは1秒あたりのコンテキストスイッチ数
usは非カーネルコードの実行に費やした時間(niceタイムを含むユーザ時間)
syはカーネルコードの実行に費やした時間(システム時間)
idはアイドル時間(Linux 2.5.41より前では、I/O待ちの時間も含まれる)
waはI/O待ちに費やされた時間
stは仮想マシンに盗られた時間(Linux 2.6.11より前は不明)

❯ vmstat 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 1  0      0 5439152 126132 1267504    0    0    83    13  123  242  5  1 94  0  0
 4  0      0 5439208 126140 1267572    0    0     0    48  307  662  3  0 97  0  0

mpstat

CPUコア(プロセッサ)関連の統計をレポートする

CPUはプロセッサ(コア)の番号(allはすべてのプロセッサ間の平均)
%usrはユーザレベル(アプリケーション)で実行中に発生したCPU使用率の割合
%niceはnice値が設定されたユーザレベル(アプリケーション)で実行中に発生したCPU使用率の割合
%sysはシステムレベル(カーネル)で実行中に発生したCPU使用率の割合(ハードウェア/ソフトウェア割り込みの処理に費やされた時間は含まれない)
%iowaitは未処理のディスクのI/O要求がある間にCPUがアイドル状態だった時間の割合
%irqはCPUがハードウェア割り込みの処理に費やした時間の割合
%softはCPUがソフトウェア割り込みの処理に費やした時間の割合
%stealはハイパーバイザが別の仮想プロセッサにサービスを提供している間に仮想のCPUが不本意に待機した時間の割合
%guestはCPUが仮想プロセッサの実行に費やした時間の割合
%gniceはnice値が設定されたguestOSの実行に費やした時間の割合
%idleはCPUがアイドル状態(未処理のディスクI/O要求もなし)だった時間の割合

❯ mpstat -P ALL 1
Linux 5.0.0-31-generic (ubuntu)     10/08/2019  _x86_64_    (4 CPU)

12:36:25 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
12:36:26 PM  all    2.77    0.00    0.76    0.00    0.00    0.00    0.00    0.00    0.00   96.47
12:36:26 PM    0    3.03    0.00    2.02    0.00    0.00    0.00    0.00    0.00    0.00   94.95
12:36:26 PM    1    4.04    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00   95.96
12:36:26 PM    2    3.06    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00   96.94
12:36:26 PM    3    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00  100.00

12:36:26 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
12:36:27 PM  all    4.02    0.00    0.50    0.00    0.00    0.00    0.00    0.00    0.00   95.48
12:36:27 PM    0    3.06    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00   96.94
12:36:27 PM    1    4.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00   96.00
12:36:27 PM    2    5.00    0.00    1.00    0.00    0.00    0.00    0.00    0.00    0.00   94.00
12:36:27 PM    3    4.00    0.00    1.00    0.00    0.00    0.00    0.00    0.00    0.00   95.00
^C

Average:     CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
Average:     all    3.40    0.00    0.63    0.00    0.00    0.00    0.00    0.00    0.00   95.97
Average:       0    3.05    0.00    1.02    0.00    0.00    0.00    0.00    0.00    0.00   95.94
Average:       1    4.02    0.00    0.00    0.00    0.00    0.00    0.00    0.00    0.00   95.98
Average:       2    4.04    0.00    0.51    0.00    0.00    0.00    0.00    0.00    0.00   95.45
Average:       3    2.01    0.00    0.50    0.00    0.00    0.00    0.00    0.00    0.00   97.49

pidstat

Linuxカーネルによって現在管理されている個々のタスクをレポートする

UIDは監視しているタスクの実行ユーザ番号(id UIDでuser/group確認可能)
PIDは監視しているタスクのプロセスID
%usrはユーザレベル(アプリケーション)で実行中にタスクが使用するCPUの割合(nice値の設定に関わらず, 仮想プロセッサの実行に費やされた時間は含まれない)
%systemはシステムレベル(カーネル)で実行中にタスクが使用するCPUの割合
%guestは仮想マシンのタスク(仮想プロセッサの実行)が消費したCPUの割合
%waitは実行待機中にタスクが消費したCPUの割合
%CPUはタスクが使用したCPU時間の合計の割合
CPUはタスクが実行されているプロセッサの番号
Commandはタスクのコマンド名

❯ pidstat 1
Linux 5.0.0-31-generic (ubuntu)     10/08/2019  _x86_64_    (4 CPU)

12:40:45 PM   UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
12:40:46 PM   129      1265    0.00    0.99    0.00    0.00    0.99     3  mongod
12:40:46 PM     0      1304    0.99    0.00    0.00    0.00    0.99     0  Xorg
12:40:46 PM  1000      3817   11.88    0.00    0.00    0.00   11.88     1  gnome-shell
12:40:46 PM  1000     22874    0.00    0.99    0.00    0.00    0.99     3  pidstat
^C

Average:      UID       PID    %usr %system  %guest   %wait    %CPU   CPU  Command
Average:      129      1265    0.00    0.99    0.00    0.00    0.99     -  mongod
Average:        0      1304    0.99    0.00    0.00    0.00    0.99     -  Xorg
Average:     1000      3817   11.88    0.00    0.00    0.00   11.88     -  gnome-shell
Average:     1000     22874    0.00    0.99    0.00    0.00    0.99     -  pidstat

iostat

CPU統計とデバイスとパーティションのI/O統計をレポートする

cpu周りは他と一緒なので割愛(マルチプロセッサであれば平均値)
Device/devディレクトリにリストされているデバイス(またはパーティション)名
r/sはデバイスの1秒あたりに完了した読み取り要求の数
w/sはデバイスの1秒あたりに完了した書き込み要求の数
rkB/sは1秒あたりにデバイスから読み取られたセクター(キロバイト)の数
rkB/sは1秒あたりにデバイスへ書き込まれたセクター(キロバイト)の数
rrqm/sはデバイスにキューイングされた1秒あたりの読み取り要求の数
wrqm/sはデバイスにキューイングされた1秒あたりの書き込み要求の数
r_awaitはデバイスに発行された読み出し要求の平均完了時間
w_awaitはデバイスに発行された書き込み要求の平均完了時間
aqu-szはデバイスに発行されたリクエストの平均のキューの長さ
rareq-szはデバイスに発行された読み取り要求の平均サイズ(キロバイト)
wareq-szはデバイスに発行された書き込み要求の平均サイズ(キロバイト)
svctmはデバイスに発行されたI/O要求の平均サービス時間(ミリ秒)(将来的にこのフィールドは削除される)
%utilはI/O要求がデバイスに発行された経過時間の割合(デバイスの帯域幅の使用率, デバイスが飽和状態だと100%に近くなる, RAIDアレイやSSDなどのリクエストを並行して処理するデバイスの場合、この数値はパフォーマンスの制限を反映していない)

❯ iostat -xz 1
Linux 5.0.0-31-generic (ubuntu)     10/08/2019  _x86_64_    (4 CPU)

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           5.16    0.02    0.82    0.02    0.00   93.98

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
loop0            0.01    0.00      0.08      0.00     0.00     0.00   0.00   0.00    0.15    0.00   0.00     9.94     0.00   0.48   0.00
loop1            0.01    0.00      0.26      0.00     0.00     0.00   0.00   0.00    0.33    0.00   0.00    20.31     0.00   0.46   0.00
loop2            0.01    0.00      0.08      0.00     0.00     0.00   0.00   0.00    0.18    0.00   0.00     9.94     0.00   0.73   0.00
loop3            0.01    0.00      0.26      0.00     0.00     0.00   0.00   0.00    0.34    0.00   0.00    22.64     0.00   0.51   0.00
loop4            2.08    0.00      2.31      0.00     0.00     0.00   0.00   0.00    0.23    0.00   0.00     1.11     0.00   0.11   0.02
loop5            0.00    0.00      0.00      0.00     0.00     0.00   0.00   0.00    0.00    0.00   0.00     1.00     0.00   4.00   0.00
sda             11.28    6.82    303.10     69.24     0.93     3.92   7.60  36.48    0.20    0.38   0.00    26.88    10.15   0.30   0.54

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           4.52    0.00    0.50    0.00    0.00   94.97

Device            r/s     w/s     rkB/s     wkB/s   rrqm/s   wrqm/s  %rrqm  %wrqm r_await w_await aqu-sz rareq-sz wareq-sz  svctm  %util
sda              0.00    2.00      0.00     84.00     0.00    19.00   0.00  90.48    0.00    0.00   0.00     0.00    42.00   2.00   0.40

free

空きおよび使用済みの物理メモリとスワップメモリの合計量、およびカーネルが使用しているバッファとキャッシュを表示する

totalは取り付けられている(メモリ/スワップ)の合計値(/proc/meminfoMemTotalSwapTotal)
usedは使用済みの(メモリ/スワップ)値(total - free - buffers - cacheで計算されている)
freeは未使用の(メモリ/スワップ)値(/proc/meminfoMemFreeSwapFree)
sharedはtmpfsで主に使用するメモリ(/proc/meminfoShmem)
buff/cacheはbuffers(カーネルバッファーが使用するメモリ(/proc/meminfoBuffers))とcache(ページキャッシュとスラブで使用されるメモリ(/proc/meminfoCachedSReclaimable))の合計値
availableはスワップなしで新しいアプリケーションを開始するために使用可能なメモリ量の推定

❯ free -m
              total        used        free      shared  buff/cache   available
Mem:           7950        1317        5159          35        1472        6304
Swap:          5528           0        5528

sar

システムアクティビティの情報を収集、レポート、または保存する

sar -n DEV

DEVキーワードを使用して、ネットワークデバイスからの統計情報をレポートする

IFACEはネットワークインタフェースの名前
rxpck/sは1秒あたりに受信したパケットの数
txpck/sは1秒あたりに送信したパケットの数
rxkB/sは1秒あたりに受信したキロバイトの合計値
txkB/sは1秒あたりに送信したキロバイトの合計値
rxcmp/sは1秒あたりに受信した圧縮されたパケットの数
txcmp/sは1秒あたりに送信した圧縮されたパケットの数
rxmcst/sは1秒あたりに受信したマルチキャストパケットの数
%ifutilはネットワークインタフェースの使用率(half-duplexインタフェースの場合、使用率はrxkB/sとtxkB/sの合計をインタフェース速度の割合として使用して計算, full-duplexの場合は、rxkB/sとtxkB/sのうちの大きい方を使用)

❯ sar -n DEV 1
Linux 5.0.0-31-generic (ubuntu)     10/08/2019  _x86_64_    (4 CPU)

12:49:54 PM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:49:55 PM br-d794bdf9fb1e      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:55 PM virbr0-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:55 PM    virbr1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:55 PM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:55 PM     ens33      2.00      3.00      0.12      0.26      0.00      0.00      0.00      0.00
12:49:55 PM virbr1-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:55 PM        lo      4.00      4.00      0.26      0.26      0.00      0.00      0.00      0.00
12:49:55 PM    virbr0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

12:49:55 PM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:49:56 PM br-d794bdf9fb1e      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:56 PM virbr0-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:56 PM    virbr1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:56 PM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:56 PM     ens33     32.00     21.00     29.69      1.48      0.00      0.00      0.00      0.02
12:49:56 PM virbr1-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:56 PM        lo     12.00     12.00      0.82      0.82      0.00      0.00      0.00      0.00
12:49:56 PM    virbr0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

12:49:56 PM     IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
12:49:57 PM br-d794bdf9fb1e      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:57 PM virbr0-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:57 PM    virbr1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:57 PM   docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:57 PM     ens33     32.00     27.00     16.97      1.85      0.00      0.00      0.00      0.01
12:49:57 PM virbr1-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
12:49:57 PM        lo     12.00     12.00      0.86      0.86      0.00      0.00      0.00      0.00
12:49:57 PM    virbr0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
^C

Average:        IFACE   rxpck/s   txpck/s    rxkB/s    txkB/s   rxcmp/s   txcmp/s  rxmcst/s   %ifutil
Average:    br-d794bdf9fb1e      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:    virbr0-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:       virbr1      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:      docker0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:        ens33     22.00     17.00     15.59      1.19      0.00      0.00      0.00      0.01
Average:    virbr1-nic      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00
Average:           lo      9.33      9.33      0.65      0.65      0.00      0.00      0.00      0.00
Average:       virbr0      0.00      0.00      0.00      0.00      0.00      0.00      0.00      0.00

sar -n TCP,ETCP

TCPキーワードを使用して、TCPv4のネットワークトラフィックに関する統計をレポートする

active/sはTCP接続が1秒間にCLOSED状態からSYN-SENT状態に遷移した回数(tcpActiveOpens)
passive/sはTCP接続が1秒間にLISTEN状態からSYN-RCVD状態に遷移した回数(tcpPassiveOpens)
iseg/sはエラーで受信したセグメントを含む、1秒あたりの受信したセグメントの総数(この数には、現在確立されている接続(established connections)で受信したセグメントが含まれる)(tcpInSegs)
oseg/sは現在の接続を含む(再送信されたオクテットのみを除く)、1秒間に送信されたセグメントの総数(tcpOutSegs)

ETCPキーワードを使用して、TCPv4のネットワークとエラーに関する統計をレポートする

atmptf/sはTCP接続が1秒間にSYN-SENT状態もしくは、SYN-RCVD状態からCLOSED状態に遷移した回数と、SYN-RCVD状態からLISTEN状態に遷移した回数を足し合わせた数(tcpAttemptFails)
estres/sはTCP接続が1秒間にESTABLISHED状態もしくは、CLOSE-WAIT状態からCLOSED状態に遷移した回数(tcpEstabResets)
retrans/sは1秒間に再送信されたセグメントの総数(要するに、1つ以上前に送信したオクテットを含んで送信されたTCPセグメントの数)(tcpRetransSegs)
isegerr/sは1秒間にエラーとして受信したセグメントの総数(例えば、不正なTCPのチェックサム)(tcpInErrs)
orsts/sは1秒間に送信されたRSTフラグを含むTCPセグメントの数(tcpOutRsts)

❯ sar -n TCP,ETCP 1
Linux 5.0.0-31-generic (ubuntu)     10/08/2019  _x86_64_    (4 CPU)

12:50:45 PM  active/s passive/s    iseg/s    oseg/s
12:50:46 PM      2.00      0.00      5.00      7.00

12:50:45 PM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:50:46 PM      0.00      0.00      0.00      0.00      0.00

12:50:46 PM  active/s passive/s    iseg/s    oseg/s
12:50:47 PM      6.00      0.00     45.00     51.00

12:50:46 PM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:50:47 PM      0.00      0.00      0.00      0.00      0.00

12:50:47 PM  active/s passive/s    iseg/s    oseg/s
12:50:48 PM      4.00      0.00     26.00     30.00

12:50:47 PM  atmptf/s  estres/s retrans/s isegerr/s   orsts/s
12:50:48 PM      0.00      0.00      0.00      0.00      0.00
^C

Average:     active/s passive/s    iseg/s    oseg/s
Average:         4.00      0.00     25.33     29.33

Average:     atmptf/s  estres/s retrans/s isegerr/s   orsts/s
Average:         0.00      0.00      0.00      0.00      0.00

top

実行中のシステムの動的なリアルタイムのビュー
上部は基本的に今まで調べてきた内容とかぶるので割愛

PIDはプロセスID
USERはタスクの所有者の実効ユーザ名(effective user name)
PRはタスクのスケジューリング優先度(RTと表示されている場合、タスクがリアルタイムスケジューリングで実行されていることを意味する)
NIはnice値
VIRTは仮想メモリサイズ(Virtual Memory Size (KiB))
RESは物理メモリサイズ(Resident Memory Size (KiB))
SHRは共有メモリサイズ(Shared Memory Size (KiB))
Sはプロセスの状態(Dは割り込み不可, Rは実行可能, Sは割り込み可能, Tはシグナルによる停止, tはデバッガによる停止, Zはゾンビ)

top - 12:51:22 up  1:16,  1 user,  load average: 0.19, 0.27, 0.26
Tasks: 313 total,   1 running, 232 sleeping,   0 stopped,   0 zombie
%Cpu(s):  5.1 us,  0.8 sy,  0.0 ni, 94.0 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8140972 total,  5288900 free,  1342064 used,  1510008 buff/cache
KiB Swap:  5661692 total,  5661692 free,        0 used.  6462432 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
  1304 root      20   0  764172 114456  61036 S   6.2  1.4   0:37.64 Xorg
 26032 atrophy   20   0   42952   3824   3060 R   6.2  0.0   0:00.01 top
     1 root      20   0  225780   9588   6704 S   0.0  0.1   0:03.66 systemd

ext4slower

イベント毎の詳細とともに、遅い(しきい値を超えた)ext4ファイル操作(読み取り、書き取り、オープン、同期(sync))をトレースする

TIMEはI/Oの完了時刻
COMMはプロセス名
PIDはプロセスID
Tはオペレーションのタイプ(R(read), W(write), O(open), S(fsync))
BYTESはI/Oのサイズ
OFF_KBはI/Oのファイルオフセット(キロバイト)
LAT(ms)はI/Oのレイテンシ(VFSがファイルシステムにリクエストを発行した時点から完了した時点までを測定する)
この時間には、ブロックデバイスI/O、ファイルシステムのCPUサイクル、ファイルシステムのロック、実行キューの待ち時間などが含まれる
FILENAMEはキャッシュされたカーネルファイル名(dentry->d_inameから取得)

❯ sudo /usr/share/bcc/tools/ext4slower 
Tracing ext4 operations slower than 10 ms
TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
14:28:21 gnome-terminal 26413  R 2072    0          11.18 tab-new-symbolic.svg
14:28:45 cut            98119  R 6       0          11.38 version
14:28:49 bash           98299  R 128     0          81.16 dd
14:28:52 dd             98299  W 1048576 509952     23.04 swapfile
14:28:52 dd             98299  W 1048576 564224     26.67 swapfile
14:28:52 dd             98299  W 1048576 616448     17.11 swapfile
14:28:53 dd             98299  W 1048576 831488     11.47 swapfile
14:28:54 dd             98299  W 1048576 859136     15.72 swapfile
14:28:56 dd             98299  W 1048576 1387520    57.64 swapfile
14:28:57 dd             98299  W 1048576 1441792    14.33 swapfile
14:28:57 dd             98299  W 1048576 1445888    60.14 swapfile

biosnoop

ブロックデバイスI/Oをトレースし、各I/Oの詳細を含んで出力する。

TIME(s)はI/Oの完了時間(最初のI/Oが観測されてからの経過時間)
COMMはキャッシュされたプロセス名(取得できない場合もある)(通常は、I/Oの原因となるプロセス)
PIDはキャッシュされたプロセスID(取得できない場合もある)(通常は、I/Oの原因となるプロセス)
DISKはディスクデバイスの名前
TはI/Oのタイプ(R(Read), W(Write))
SECTORはI/Oのデバイスセクタ
BYTESはI/Oのサイズ
LAT(ms)はデバイスに発行してから完了までのI/O時間

❯ sudo /usr/share/bcc/tools/biosnoop 
TIME(s)     COMM           PID    DISK    T SECTOR     BYTES  LAT(ms)
0.000000    ?              0              R 0          8         0.20
2.015911    ?              0              R 0          8         0.20
3.705983    jbd2/sda1-8    420    sda     W 17090736   200704    0.48
3.706352    jbd2/sda1-8    420    sda     W 17091128   4096      0.25
4.031347    ?              0              R 0          8         0.21
6.047361    ?              0              R 0          8         0.23
6.932799    kworker/u256:2 97165  sda     W 5507392    8192      0.23
6.932877    kworker/u256:2 97165  sda     W 25144640   16384     0.19
6.932890    kworker/u256:2 97165  sda     W 25144720   4096      0.16
6.933065    kworker/u256:2 97165  sda     W 25144792   4096      0.17
6.933075    kworker/u256:2 97165  sda     W 25144904   4096      0.13
6.933185    kworker/u256:2 97165  sda     W 25144952   4096      0.19
6.933196    kworker/u256:2 97165  sda     W 25145096   4096      0.17
6.933517    kworker/u256:2 97165  sda     W 25143504   4096      0.28
6.933550    kworker/u256:2 97165  sda     W 37619816   4096      0.23
6.933558    kworker/u256:2 97165  sda     W 37620176   4096      0.18
6.933564    kworker/u256:2 97165  sda     W 37620376   4096      0.12
6.933749    kworker/u256:2 97165  sda     W 37620464   4096      0.18
6.933759    kworker/u256:2 97165  sda     W 37620624   4096      0.13
6.933764    kworker/u256:2 97165  sda     W 37620728   4096      0.08
6.933950    kworker/u256:2 97165  sda     W 37620848   4096      0.13
6.933989    kworker/u256:2 97165  sda     W 37621112   4096      0.13
6.933999    kworker/u256:2 97165  sda     W 37621144   4096      0.10
6.934222    kworker/u256:2 97165  sda     W 37621160   4096      0.29
6.934247    kworker/u256:2 97165  sda     W 37621176   4096      0.17
6.934255    kworker/u256:2 97165  sda     W 37621440   4096      0.15
6.934292    kworker/u256:2 97165  sda     W 37621808   4096      0.15
6.934447    kworker/u256:2 97165  sda     W 37622088   4096      0.15

cachestat

Linuxページキャッシュのヒット/ミス率の統計

HITSはページキャッシュのヒット数
MISSESはページキャッシュのミス数
DIRTIESはページキャッシュに追加されたダーティページの数
HITRATIOはヒット率
BUFFERS_MBはバッファサイズ(/proc/meminfoから取得)
CACHED_MBは現在のページキャッシュのキャッシュされたデータ量(/proc/meminfoから取得)

❯ sudo /usr/share/bcc/tools/cachestat 
    HITS   MISSES  DIRTIES HITRATIO   BUFFERS_MB  CACHED_MB
       7        0        0  100.00%          766       2031
       4        0       39  100.00%          766       2031
   25446        0       52  100.00%          766       2031
      32        0       14  100.00%          766       2031
       0        0        0    0.00%          766       2031
       0        0        0    0.00%          766       2031
       2        0        0  100.00%          766       2031
       0        0        0    0.00%          766       2031

tcpconnect

TCPのアクティブ接続(connect())をトレースする

PIDはプロセスID
COMMはプロセス名
IPはIPアドレスファミリ(v4, v6)
SADDRは送信元IPアドレス
DADDRは宛先IPアドレス
DPORTは宛先ポート

❯ sudo /usr/share/bcc/tools/tcpconnect 
PID    COMM         IP SADDR            DADDR            DPORT
102602 curl         4  127.0.0.1        127.0.0.1        8080
30538  Chrome_Child 4  192.168.221.129  172.217.24.129   443 
1452   NetworkManag 4  192.168.221.129  35.222.85.5      80  
30538  Chrome_Child 4  192.168.221.129  216.58.197.206   443 
30538  Chrome_Child 4  192.168.221.129  192.41.192.145   443 
30538  Chrome_Child 4  192.168.221.129  117.18.237.29    80  
30538  Chrome_Child 4  192.168.221.129  117.18.237.29    80  
30538  Chrome_Child 4  192.168.221.129  59.106.216.193   80  
30538  Chrome_Child 4  192.168.221.129  192.41.192.145   443 
30538  Chrome_Child 4  192.168.221.129  192.41.192.145   443 
30538  Chrome_Child 4  192.168.221.129  192.41.192.145   443 
30538  Chrome_Child 4  192.168.221.129  192.41.192.145   443 
30538  Chrome_Child 4  192.168.221.129  192.41.192.145   443 
30538  Chrome_Child 4  192.168.221.129  104.19.199.151   443 
30538  Chrome_Child 4  192.168.221.129  23.111.9.35      443 
30538  Chrome_Child 4  192.168.221.129  172.217.26.46    443 
30538  Chrome_Child 4  192.168.221.129  23.111.9.35      443 

tcpaccept

TCPのパッシブ接続(accept())をトレースする

PIDはプロセスID
COMMはプロセス名
IPはIPアドレスファミリ(v4, v6)
RADDRはリモートアドレス
RPORTはリモートポート
LADDRはローカルアドレス
LPORTはローカルポート

❯ sudo /usr/share/bcc/tools/tcpaccept
PID     COMM         IP RADDR            RPORT LADDR            LPORT
104315  node         6  ::ffff:127.0.0.1 52458 ::ffff:127.0.0.1 3000 
105042  main         6  ::ffff:127.0.0.1 55964 ::ffff:127.0.0.1 8080 
107940  node         6  ::ffff:192.168.221.129 56054 ::ffff:192.168.221.129 3000 

tcpretrans

TCPの再送信とTLPをトレースもしくはカウントする
カウントする場合は-cオプション

TIMEは再送信した時間
PIDはCPU上にあったプロセスID(カーネルやタイマーベースの再送信は0になるので、そこまで有用ではない)
IPはIPアドレスファミリ(v4, v6)
LADDR:LPORTはローカルアドレス:ローカルポート
T>はイベントのタイプ(R(retransmit), L(tail loss probe))
RADDR:RPORTはリモートアドレス:リモートポート
STATEはTCPセッションのステート

❯ sudo /usr/share/bcc/tools/tcpretrans 
Tracing retransmits ... Hit Ctrl-C to end
TIME     PID    IP LADDR:LPORT          T> RADDR:RPORT          STATE
15:12:09 120420 4  127.0.0.1:53250      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53248      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53246      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53244      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53242      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53238      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53234      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120420 4  127.0.0.1:53232      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120722 4  127.0.0.1:53240      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120722 4  127.0.0.1:53236      R> 127.0.0.1:3000       SYN_SENT
15:12:09 119466 4  127.0.0.1:53254      R> 127.0.0.1:3000       SYN_SENT
15:12:09 119466 4  127.0.0.1:53252      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120717 4  127.0.0.1:53628      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120717 4  127.0.0.1:53626      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120717 4  127.0.0.1:53624      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120717 4  127.0.0.1:53622      R> 127.0.0.1:3000       SYN_SENT
15:12:09 120717 4  127.0.0.1:53620      R> 127.0.0.1:3000       SYN_SENT

runqlat

実行キューのレイテンシのヒストグラム
具体的には二種類の実行キューのレイテンシを測定する

  • タスクが実行キューにエンキューされてから、コンテキストが切り替えられて実行されるまでの時間
  • タスクが非自発的な(実行秒数で強制的に切り替えられた?)コンテキストに切り替えられ、まだ実行可能な状態であったときから、次に実行されるまでの時間(finish_task_switch()から計測される)

usecsはマイクロ秒のレンジ
countはタスクイベントがこの範囲に入った回数
distirbutionはcountの可視化

❯ sudo /usr/share/bcc/tools/runqlat 
Tracing run queue latency... Hit Ctrl-C to end.

^C
     usecs               : count     distribution
         0 -> 1          : 10939    |*******************************         |
         2 -> 3          : 9194     |**************************              |
         4 -> 7          : 13718    |****************************************|
         8 -> 15         : 6002     |*****************                       |
        16 -> 31         : 8129     |***********************                 |
        32 -> 63         : 4774     |*************                           |
        64 -> 127        : 2781     |********                                |
       128 -> 255        : 1459     |****                                    |
       256 -> 511        : 709      |**                                      |
       512 -> 1023       : 575      |*                                       |
      1024 -> 2047       : 294      |                                        |
      2048 -> 4095       : 308      |                                        |
      4096 -> 8191       : 145      |                                        |
      8192 -> 16383      : 105      |                                        |
     16384 -> 32767      : 5        |                                        |

profile

スタックトレースをサンプリングして、CPU使用率をプロファイルする
CPU使用率を理解し、定量化するのに役立つ
デフォルトでは、すべてのCPUで49Hz(1秒あたりのサンプル数)でサンプリングを行う
説明が浅すぎるけどまだうまく咀嚼できてないので暫定

❯ sudo /usr/share/bcc/tools/profile 
Sampling at 49 Hertz of all threads by user + kernel stack... Hit Ctrl-C to end.
^C
    [unknown]
    -                stress (9794)
        1

    _raw_spin_unlock_irqrestore
    _raw_spin_unlock_irqrestore
    __wake_up_common_lock
    __wake_up_sync_key
    sock_def_readable
    __netlink_sendskb
    netlink_broadcast_filtered
    netlink_sendmsg
    sock_sendmsg
    ___sys_sendmsg
    __sys_sendmsg
    __x64_sys_sendmsg
    do_syscall_64
    entry_SYSCALL_64_after_hwframe