HackToTech

Hack To Technology

BPF本を読みながら学ぶ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