ドリルダウンやUSEメソッドなど実際にどのようにパフォーマンスを改善するかを考えていく
また、非BPFのツールとBPFのツールの説明など
目次
- uptime
- dmesg
- vmstat
- mpstat
- pidstat
- iostat
- free
- sar
- top
- ext4slower
- biosnoop
- cachestat
- tcpconnect
- tcpaccept
- tcpretrans
- runqlat
- profile
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/meminfoのMemTotalとSwapTotal) |
| used | 使用済みの(メモリ/スワップ)値(total - free - buffers - cacheで計算されている) |
| free | 未使用の(メモリ/スワップ)値(/proc/meminfoのMemFreeとSwapFree) |
| shared | tmpfsで主に使用するメモリ(/proc/meminfoのShmem) |
| buff/cache | buffers(カーネルバッファーが使用するメモリ(/proc/meminfoのBuffers))とcache(ページキャッシュとスラブで使用されるメモリ(/proc/meminfoのCachedとSReclaimable))の合計値 |
| 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
