BPF Performance Toolsを読みながら学ぶ3
3章、ドリルダウンや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.31dmesg
カーネルリングバッファーにあるメッセージを表示する
❯ 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 statevmstat
プロセス、メモリ、ページング、ブロック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 0mpstat
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.49pidstat
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 - pidstatiostat
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.40free
空きおよび使用済みの物理メモリとスワップメモリの合計量、およびカーネルが使用しているバッファとキャッシュを表示する
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 5528sar
システムアクティビティの情報を収集、レポート、または保存する
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.00sar -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.00top
実行中のシステムの動的なリアルタイムのビュー
上部は基本的に今まで調べてきた内容とかぶるので割愛
PIDはプロセスIDUSERはタスクの所有者の実効ユーザ名(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 systemdext4slower
イベント毎の詳細とともに、遅い(しきい値を超えた)ext4ファイル操作(読み取り、書き取り、オープン、同期(sync))をトレースする
TIMEはI/Oの完了時刻COMMはプロセス名PIDはプロセスIDTはオペレーションのタイプ(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 swapfilebiosnoop
ブロックデバイス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.15cachestat
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 2031tcpconnect
TCPのアクティブ接続(connect())をトレースする
PIDはプロセスIDCOMMはプロセス名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はプロセスIDCOMMはプロセス名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_SENTrunqlat
実行キューのレイテンシのヒストグラム
具体的には二種類の実行キューのレイテンシを測定する
- タスクが実行キューにエンキューされてから、コンテキストが切り替えられて実行されるまでの時間
- タスクが非自発的な(実行秒数で強制的に切り替えられた？)コンテキストに切り替えられ、まだ実行可能な状態であったときから、次に実行されるまでの時間(
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