BPF本を読みながら学ぶ6

6章、 CPUについて及びCPUに関連するBCC

目次

• CPU
• CPUのパフォーマンス分析
• Perf-Stat
• 用語
• runqslower
• cpudist
• offcputime
• syscount
• softirqs
• hardirqs
• llcstat

CPU

CPUについては、詳解システムパフォーマンスで学んだことの復習になる

スレッドの状態

• On-Proc
  • CPU上で実行している
• Runnable
  • 実行可能だが、順番待ち
  • run queueでは優先度の値によってソートされる
• Sleep
  • 割り込み不可能な待機を含む別のイベントでブロックされている

スレッドの状態遷移(CPUの実行状態から遷移するトリガー)

• 自発的
  • I/O、ロック、またはスリープでブロックする場合
• 非自発的
  • CPU時間の超過
  • 優先度の高いスレッドによる横取り

異なるCPUへのバランシング

• 別のCPUがアイドル状態で、他のCPUのrun queueにスレッドが存在し待機時間のしきい値を超えた際に移動する(これはスケジューラにより実行される)
• 待機時間が短い場合は、移行をせずにハードウェアキャッシュが存在するはずのCPUで再度実行される

CPUキャッシュ(L1, L2, L3の場合)

• L1とL2はCPUごとのコア
• L3はソケット全体で共有

CPUのパフォーマンス分析

1. CPUワークロードの取得(mpstat), 全てのCPUが使用されているかどうかの確認
2. ワークロードがCPUバウンドであることの確認
3. CPU使用率の高いCPUの調査
4. 実行キューの遅延の確認(runqlat) システムがアイドル状態にも関わらず、コンテナのCPU制限(soft/hard)によりCPUバインドになっている可能性も探れる
5. プロセス、CPUのモード、CPU IDで分類する(mpstat, top) 単一のプロセス、モード、IDで高い使用率を探す
   1. システム時間が長い場合はプロセスまたは呼び出しのタイプごとにシステムコールをカウントし、非効率な呼び出しを探す(perf, bpfrace, sysstat)
6. プロファイラによるスタックトレースのサンプリング(フレームグラフを出力して視覚化する)
7. プロファイラによって原因と思われる呼び出しを見つけたらさらに引数やオブジェクトが見れるツールを使用する
8. タイマーベースのプロファイラを利用する(hardirqs)
9. BPF toolを使用する
10. PMCを使用してCPUのサイクルあたりの命令を測定してCPUがストールした量を見る

Perf-Stat

パフォーマンス解析ツール

オプション

-e	PMUイベントの指定
-d	詳細な統計の出力(詳細なイベント及びL1とLLCデータキャッシュ)
perf list	シンボリックイベントタイプのリストが見れる

❯ sudo perf stat -d top

top - 02:02:06 up  1:24,  1 user,  load average: 0.19, 0.05, 0.02
Tasks: 325 total,   1 running, 246 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.1 us,  0.2 sy,  0.0 ni, 99.7 id,  0.0 wa,  0.0 hi,  0.0 si,  0.0 st
KiB Mem :  8140984 total,  4596012 free,  1603428 used,  1941544 buff/cache
KiB Swap:  5661692 total,  5661692 free,        0 used.  6132404 avail Mem 

   PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND    
  1216 root      20   0 1101220  36564  21444 S   0.3  0.4   0:07.13 containerd 
  1251 root      20   0  680156 105032  52864 S   0.3  1.3   0:37.01 Xorg       
  3346 atrophy   20   0 3737192 258756 120200 S   0.3  3.2   2:37.25 gnome-she+ 
  3618 atrophy   20   0  517800  34712  28340 S   0.3  0.4   0:03.16 vmtoolsd   
  4034 atrophy   20   0  961456 243628 138980 S   0.3  3.0   1:01.53 chrome     
  6299 atrophy   20   0  795896  38688  28872 S   0.3  0.5   0:00.46 gnome-ter+ 
  7106 atrophy   20   0   42932   3796   3084 S   0.3  0.0   0:00.04 top        
  7114 root      20   0   42928   3852   3140 R   0.3  0.0   0:00.02 top        
     1 root      20   0  225364   9196   6736 S   0.0  0.1   0:02.07 systemd    
     2 root      20   0       0      0      0 S   0.0  0.0   0:00.01 kthreadd   
     3 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 rcu_gp     
     4 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 rcu_par_gp 
     6 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 kworker/0+ 
     8 root       0 -20       0      0      0 I   0.0  0.0   0:00.00 mm_percpu+ 
     9 root      20   0       0      0      0 S   0.0  0.0   0:00.08 ksoftirqd+ 
    10 root      20   0       0      0      0 I   0.0  0.0   0:01.18 rcu_sched  
    11 root      rt   0       0      0      0 S   0.0  0.0   0:00.01 migration+ 

 Performance counter stats for 'top':

             30.51 msec task-clock                #    0.005 CPUs utilized          
                 4      context-switches          #    0.131 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
               314      page-faults               #    0.010 M/sec                  
   <not supported>      cycles                                                      
   <not supported>      instructions                                                
   <not supported>      branches                                                    
   <not supported>      branch-misses                                               
                 0      L1-dcache-loads           #    0.000 K/sec                  
                 0      L1-dcache-load-misses     #    0.00% of all L1-dcache hits  
   <not supported>      LLC-loads                                                   
   <not supported>      LLC-load-misses                                             

       6.329104182 seconds time elapsed

       0.007734000 seconds user
       0.023203000 seconds sys

用語

• voluntary context switches
  • 自発的なコンテキストスイッチ
• involuntary context switches
  • 時間切れや、優先度の高いプロセスの実行を行うために強制的に行われた非自発的なコンテキストスイッチ
• Memory Management Unit(MMU)
  • 仮想アドレスと物理アドレスの変換を行う
• Translation Lookaside Buffer(TLB)
  • 仮想アドレスから対応するフレーム番号を取得し、物理アドレスへのアクセスを高速化させるキャッシュみたいなもの
    • ヒットしなかった場合はPageTable or PageMapTableを参照し、フレーム番号を取得して物理アドレスを取得する(さらにTLBを更新する)

runqslower

run-queue上でタスクがon-CPUになるまでの経過時間が閾値を超えた場合に出力する
デフォルトは10000マイクロ秒(10ミリ秒)

以下は別terminalでyesコマンドを実行した

❯ sudo /usr/share/bcc/tools/runqslower
Tracing run queue latency higher than 10000 us
TIME     COMM             PID           LAT(us)
17:10:24 llvmpipe-2       3382            10011
17:10:32 llvmpipe-0       3383            10065
17:10:32 llvmpipe-0       3770            13693
17:10:32 yes              3384            10648

cpudist

タスクがCPU上で処理された時間のヒストグラム
4～15ミリ秒のcountがあまりにも多いと非自発なコンテキストスイッチに遭遇している可能性が高いっぽい？

オプション

-m	ミリ秒単位で出力

❯ sudo /usr/share/bcc/tools/cpudist -m
Tracing on-CPU time... Hit Ctrl-C to end.
     msecs               : count     distribution
         0 -> 1          : 555      |****************************************|
         2 -> 3          : 34       |**                                      |
         4 -> 7          : 84       |******                                  |
         8 -> 15         : 89       |******                                  |
        16 -> 31         : 94       |******                                  |
        32 -> 63         : 49       |***                                     |

offcputime

カーネルスタックトレースによるoff-CPU時間の要約
ブロックされたoff-CPUのスタックトレースとタスク名、およびそれらが実行されなかった合計時間(off-CPU time)を出力する

❯ sudo /usr/share/bcc/tools/offcputime 
Tracing off-CPU time (us) of all threads by user + kernel stack... Hit Ctrl-C to end.
    finish_task_switch
    schedule
    schedule_timeout
    wait_for_completion
    __flush_work
    flush_work
    tty_buffer_flush_work
    n_tty_read
    tty_read
    __vfs_read
    vfs_read
    ksys_read
    __x64_sys_read
    do_syscall_64
    entry_SYSCALL_64_after_hwframe
    __libc_read
    [unknown]
    -                gnome-terminal- (3770)
        2 // マイクロ秒表示

syscount

システム全体のsyscallのカウントの要約
プロセス単位でも取得できる
また、それぞれのレイテンシーも計れる

❯ sudo /usr/share/bcc/tools/syscount -i 1 -PL
Tracing syscalls, printing top 10... Ctrl+C to quit.
[18:27:57]
PID    COMM               COUNT        TIME (us)
1219   containerd           192      3847155.368
3375   gnome-shell          315      1988176.025
9798   syscount              19      1002143.822
3677   vmtoolsd              49       907569.626
706    vmtoolsd              39       907278.006
3770   gnome-terminal-       71       428708.563
1243   Xorg                 145       405583.505
1313   dockerd                4          958.638
7821   chrome                 2           84.800
5855   chrome                18           72.275

[18:27:57]
PID    COMM               COUNT        TIME (us)
3375   gnome-shell          280      3152947.632
1243   Xorg                 182       835259.443
3557   gsd-color              4       811892.451
1219   containerd            34       701318.176
3770   gnome-terminal-      112       276658.322
3244   ibus-daemon           98       208865.191
3328   ibus-engine-sim       40       207299.887
706    vmtoolsd               8       202147.340
9798   syscount              22       173864.929
5855   chrome                16       143513.600

❯ sudo /usr/share/bcc/tools/syscount -i 1 -L
Tracing syscalls, printing top 10... Ctrl+C to quit.
[18:28:25]
SYSCALL                   COUNT        TIME (us)
futex                       253      5027964.210
poll                        191      3793821.835
epoll_wait                   51      1215550.905
select                        6       959713.907
pselect6                     27        13272.355
writev                      114         2022.668
recvmsg                     544          984.996
write                        83          620.120
ioctl                         6          321.547
read                         81          141.556

softirqs

ソフトIRQ(ソフト割り込み)イベント時間を測定する

ソフト割り込みの処理に費やされた時間を要約し、合計時間もしくはヒストグラムとして出力する

❯ sudo /usr/share/bcc/tools/softirqs 
Tracing soft irq event time... Hit Ctrl-C to end.
SOFTIRQ          TOTAL_usecs
net_tx                     1
tasklet                    6
block                      7
net_rx                    47
rcu                      254
timer                    723
sched                   1148

❯ sudo /usr/share/bcc/tools/softirqs -d
Tracing soft irq event time... Hit Ctrl-C to end.
softirq = sched
     usecs               : count     distribution
         0 -> 1          : 3        |****                                    |
         2 -> 3          : 3        |****                                    |
         4 -> 7          : 6        |********                                |
         8 -> 15         : 8        |***********                             |
        16 -> 31         : 27       |****************************************|
        32 -> 63         : 9        |*************                           |

hardirqs

ハードIRQ(ハード割り込み)イベント時間を測定する

ハード割り込みの処理に費やされた時間を要約し、合計時間もしくはヒストグラムとして出力する

❯ sudo /usr/share/bcc/tools/hardirqs 10 1
Tracing hard irq event time... Hit Ctrl-C to end.
^C
HARDIRQ                    TOTAL_usecs
ens33                                9

❯ sudo /usr/share/bcc/tools/hardirqs 10 1 -d
Tracing hard irq event time... Hit Ctrl-C to end.

hardirq = 'ens33'
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|

llcstat

CPUキャッシュの参照(最終レベルキャッシュ LLC)とプロセスごとのミスとヒット率を要約する

VMだと動作しないっぽい？

Failed to attach to a hardware event. Is this a virtual machine?

動けばこんな感じで出力される
PID      NAME             CPU     REFERENCE         MISS   HIT%
0        swapper/15       15        3515000       640000  81.79%
238      migration/38     38           5000            0 100.00%
4512     ntpd             11           5000            0 100.00%

BPF本を読みながら学ぶ5

5章、他観測ツールとの比較, インストール方法, それぞれのProbeに対しての解説, 内部動作についてみたいな感じ
何かやりたいときに参照することが多そう、手を動かした部分はあまりなかったので短め

目次

• USDT Probe

USDT Probe

読んでて試したくなったので、MySQLで試すかと思ったが8.0からProbeが消失していた、残念
なので、PostgreSQLの11で試すことにした

By default the probes are not compiled into PostgreSQL; the user needs to explicitly tell the configure script to make the probes available.

とのことだったがaptのリポジトリとして追加した先から落としてくるものは既にコンパイルオプションに入っていたので、そのままで問題なかった

❯ sudo /usr/share/bcc/tools/tplist -l /usr/lib/postgresql/11/bin/postgres 
/usr/lib/postgresql/11/bin/postgres postgresql:clog__checkpoint__start
/usr/lib/postgresql/11/bin/postgres postgresql:clog__checkpoint__done
/usr/lib/postgresql/11/bin/postgres postgresql:multixact__checkpoint__start
/usr/lib/postgresql/11/bin/postgres postgresql:multixact__checkpoint__done
/usr/lib/postgresql/11/bin/postgres postgresql:subtrans__checkpoint__start
/usr/lib/postgresql/11/bin/postgres postgresql:subtrans__checkpoint__done
/usr/lib/postgresql/11/bin/postgres postgresql:twophase__checkpoint__start
/usr/lib/postgresql/11/bin/postgres postgresql:twophase__checkpoint__done
/usr/lib/postgresql/11/bin/postgres postgresql:transaction__start
/usr/lib/postgresql/11/bin/postgres postgresql:transaction__commit
/usr/lib/postgresql/11/bin/postgres postgresql:transaction__abort
/usr/lib/postgresql/11/bin/postgres postgresql:wal__buffer__write__dirty__start
/usr/lib/postgresql/11/bin/postgres postgresql:wal__buffer__write__dirty__done
/usr/lib/postgresql/11/bin/postgres postgresql:wal__switch
/usr/lib/postgresql/11/bin/postgres postgresql:checkpoint__start
/usr/lib/postgresql/11/bin/postgres postgresql:checkpoint__done
/usr/lib/postgresql/11/bin/postgres postgresql:wal__insert
/usr/lib/postgresql/11/bin/postgres postgresql:statement__status
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__flush__start
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__flush__done
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__read__start
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__read__done
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__write__dirty__start
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__write__dirty__done
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__sync__start
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__sync__done
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__sync__written
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__checkpoint__start
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__checkpoint__sync__start
/usr/lib/postgresql/11/bin/postgres postgresql:buffer__checkpoint__done
/usr/lib/postgresql/11/bin/postgres postgresql:lock__wait__start
/usr/lib/postgresql/11/bin/postgres postgresql:lock__wait__done
/usr/lib/postgresql/11/bin/postgres postgresql:deadlock__found
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__wait__start
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__wait__done
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__acquire
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__condacquire
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__condacquire__fail
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__acquire__or__wait
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__acquire__or__wait__fail
/usr/lib/postgresql/11/bin/postgres postgresql:lwlock__release
/usr/lib/postgresql/11/bin/postgres postgresql:smgr__md__read__start
/usr/lib/postgresql/11/bin/postgres postgresql:smgr__md__read__done
/usr/lib/postgresql/11/bin/postgres postgresql:smgr__md__write__start
/usr/lib/postgresql/11/bin/postgres postgresql:smgr__md__write__done
/usr/lib/postgresql/11/bin/postgres postgresql:query__parse__start
/usr/lib/postgresql/11/bin/postgres postgresql:query__parse__done
/usr/lib/postgresql/11/bin/postgres postgresql:query__rewrite__start
/usr/lib/postgresql/11/bin/postgres postgresql:query__rewrite__done
/usr/lib/postgresql/11/bin/postgres postgresql:query__plan__start
/usr/lib/postgresql/11/bin/postgres postgresql:query__plan__done
/usr/lib/postgresql/11/bin/postgres postgresql:query__start
/usr/lib/postgresql/11/bin/postgres postgresql:query__done
/usr/lib/postgresql/11/bin/postgres postgresql:query__execute__start
/usr/lib/postgresql/11/bin/postgres postgresql:query__execute__done
/usr/lib/postgresql/11/bin/postgres postgresql:sort__start
/usr/lib/postgresql/11/bin/postgres postgresql:sort__done

まだ良く書き方がわからないので、参考になりそうなサイト探していたらとてもわかりやすいサイトがあった
bccとUSDTを使ってMySQL/PostgreSQLのクエリログを取得する

クエリについて確認することは既にやっていたので、クエリのかかった時間を計測することにしてソースを一部いじってやってみた

from __future__ import print_function
from bcc import BPF, USDT
import sys

pid = sys.argv[1]

bpf_text = """
#include <uapi/linux/ptrace.h>
int do_trace1(struct pt_regs *ctx) {
    char *query;
    bpf_usdt_readarg(1, ctx, &query);
    bpf_trace_printk("%s\\n", query);
    return 0;
};

int do_trace2(struct pt_regs *ctx) {
    char *query;
    bpf_usdt_readarg(1, ctx, &query);
    bpf_trace_printk("%s\\n", query);
    return 0;
};
"""

contexts = []

u1 = USDT(pid=int(pid))
u1.enable_probe(probe="query__start", fn_name="do_trace1")
contexts.append(u1)

u2 = USDT(pid=int(pid))
u2.enable_probe(probe="query__done", fn_name="do_trace2")
contexts.append(u2)

b = BPF(text=bpf_text, usdt_contexts=contexts)
print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "QUERY"))

while True:
    try:
        (start_task, start_pid, start_cpu, start_flags, start_ts, start_msg) = b.trace_fields()
        (end_task, end_pid, end_cpu, end_flags, end_ts, end_msg) = b.trace_fields()
    except ValueError:
        print("value error")
        continue
    except KeyboardInterrupt:
        exit()
    print("%-18.9f %-16s %-6d %s" % (end_ts - start_ts, start_task.decode('utf-8'), start_pid, start_msg.decode('utf-8')))

後は普通に別ターミナルでクエリを投げて実行してみる

❯ sudo python3 psql_query_logger.py 16052
TIME(s)            COMM             PID    QUERY
0.000189000        postgres         16052  SELECT * FROM user;
0.064199000        postgres         16052  SELECT * FROM pg_roles;

BPF本を読みながら学ぶ4

4章、BCCとその機能に関しての紹介が主な感じだった

目次

• funccount
• stackcount
• trace
• argdist

funccount

パターンにマッチしたファンクション、トレースポイント、USDTプローブの呼び出しをカウントする
頻度の高いイベントを参照させるとオーバーヘッドが大きくなる(例えば、malloc(), free())

tcp_connectが呼び出されたかを確認する

❯ sudo /usr/share/bcc/tools/funccount tcp_connect
Tracing 1 functions for "tcp_connect"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
tcp_connect                                 2
Detaching...

最も頻繁に呼び出されているVFSの機能はなにかを確認する

❯ sudo /usr/share/bcc/tools/funccount 'vfs_*'
Tracing 56 functions for "vfs_*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
vfs_symlink                                 1
vfs_statfs                                  1
vfs_setxattr                                1
vfs_rmdir                                   7
vfs_unlink                                  8
vfs_lock_file                              14
vfs_readlink                               93
vfs_statx                                 162
vfs_writev                                217
vfs_write                                 428
vfs_read                                  822
vfs_statx_fd                             1687
vfs_getattr_nosec                        2106
vfs_getattr                              2108
vfs_open                                 2114
Detaching...

1秒間隔でlibcのpthread_mutex_lockが呼び出された回数をトレースする

❯ sudo /usr/share/bcc/tools/funccount -i 1 c:pthread_mutex_lock
Tracing 1 functions for "c:pthread_mutex_lock"... Hit Ctrl-C to end.

FUNC                                    COUNT
pthread_mutex_lock                          2

FUNC                                    COUNT
pthread_mutex_lock                          2

FUNC                                    COUNT
pthread_mutex_lock                          2

FUNC                                    COUNT
pthread_mutex_lock                        924

FUNC                                    COUNT
pthread_mutex_lock                        132
^C
FUNC                                    COUNT
pthread_mutex_lock                         28
Detaching...

システム全体のlibcからの最も頻繁なstr関数呼び出しはなにか

❯ sudo /usr/share/bcc/tools/funccount c:str*
Tracing 62 functions for "c:str*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
strstr                                      2
strerror_thread_freeres                     3
strcat_ifunc                                5
strcspn_ifunc                               5
strpbrk_ifunc                               5
strspn_ifunc                                5
strncasecmp_l                               5
strchrnul                                   5
strcasecmp_l                                5
strcpy_ifunc                                6
strncpy_ifunc                               6
strncasecmp                                 6
strcasecmp                                  6
strtok_r                                    8
strrchr_ifunc                              10
strchr_ifunc                               11
strnlen                                    11
strcmp_ifunc                               12
strlen_ifunc                               12
strncmp_ifunc                              12
strtoll                                    80
strerror                                  127
strerror_r                                129
strdup                                    233
strtouq                                   303
strtoull_l                              19208
Detaching...

最も頻繁なsyscallはなにか

❯ sudo /usr/share/bcc/tools/funccount t:syscalls:sys_enter_*
Tracing 320 functions for "t:syscalls:sys_enter_*"... Hit Ctrl-C to end.
^C
FUNC                                    COUNT
syscalls:sys_enter_accept4                  1
syscalls:sys_enter_getpeername              1
syscalls:sys_enter_add_key                  1
syscalls:sys_enter_inotify_rm_watch         1
syscalls:sys_enter_fstatfs                  1
syscalls:sys_enter_setxattr                 1
syscalls:sys_enter_dup2                     1
syscalls:sys_enter_symlink                  1
syscalls:sys_enter_execve                   1
syscalls:sys_enter_ftruncate                1
syscalls:sys_enter_chdir                    1
syscalls:sys_enter_sched_getaffinity        1
syscalls:sys_enter_getppid                  1
syscalls:sys_enter_getegid                  1
syscalls:sys_enter_setsid                   1
syscalls:sys_enter_newuname                 1
syscalls:sys_enter_set_tid_address          1
syscalls:sys_enter_arch_prctl               1
syscalls:sys_enter_shutdown                 2
syscalls:sys_enter_keyctl                   2
syscalls:sys_enter_dup3                     2
syscalls:sys_enter_getdents64               2
syscalls:sys_enter_rename                   2
syscalls:sys_enter_pipe2                    2
syscalls:sys_enter_geteuid                  2
syscalls:sys_enter_getrusage                2
syscalls:sys_enter_rt_sigreturn             2
syscalls:sys_enter_getsockopt               3
syscalls:sys_enter_lseek                    3
syscalls:sys_enter_brk                      3
syscalls:sys_enter_umask                    3
syscalls:sys_enter_capget                   3
syscalls:sys_enter_waitid                   3
syscalls:sys_enter_sendto                   4
syscalls:sys_enter_getgid                   4
syscalls:sys_enter_connect                  5
syscalls:sys_enter_getuid                   5
syscalls:sys_enter_utimensat                6
syscalls:sys_enter_rmdir                    8
syscalls:sys_enter_mkdir                    9
syscalls:sys_enter_gettid                   9
syscalls:sys_enter_inotify_add_watch       11
syscalls:sys_enter_select                  15
syscalls:sys_enter_timerfd_settime         17
syscalls:sys_enter_epoll_pwait             17
syscalls:sys_enter_sigaltstack             18
syscalls:sys_enter_bind                    22
syscalls:sys_enter_signalfd4               22
syscalls:sys_enter_kill                    22
syscalls:sys_enter_getsockname             23
syscalls:sys_enter_epoll_create1           23
syscalls:sys_enter_exit_group              23
syscalls:sys_enter_setsockopt              25
syscalls:sys_enter_prctl                   26
syscalls:sys_enter_socket                  28
syscalls:sys_enter_clone                   31
syscalls:sys_enter_mprotect                32
syscalls:sys_enter_set_robust_list         32
syscalls:sys_enter_newstat                 37
syscalls:sys_enter_wait4                   39
syscalls:sys_enter_getdents                40
syscalls:sys_enter_rt_sigprocmask          42
syscalls:sys_enter_io_getevents            49
syscalls:sys_enter_prlimit64               50
syscalls:sys_enter_unlink                  52
syscalls:sys_enter_getpid                  52
syscalls:sys_enter_fcntl                   54
syscalls:sys_enter_mmap                    56
syscalls:sys_enter_epoll_ctl               65
syscalls:sys_enter_setitimer               90
syscalls:sys_enter_recvfrom               100
syscalls:sys_enter_sendmsg                108
syscalls:sys_enter_kcmp                   115
syscalls:sys_enter_perf_event_open        117
syscalls:sys_enter_writev                 125
syscalls:sys_enter_rt_sigaction           129
syscalls:sys_enter_newfstatat             140
syscalls:sys_enter_munmap                 142
syscalls:sys_enter_times                  157
syscalls:sys_enter_pselect6               188
syscalls:sys_enter_nanosleep              195
syscalls:sys_enter_clock_gettime          200
syscalls:sys_enter_sched_yield            270
syscalls:sys_enter_getrandom              297
syscalls:sys_enter_epoll_wait             301
syscalls:sys_enter_bpf                    320
syscalls:sys_enter_write                  351
syscalls:sys_enter_access                 361
syscalls:sys_enter_ioctl                  436
syscalls:sys_enter_newlstat               449
syscalls:sys_enter_readlinkat             513
syscalls:sys_enter_read                   710
syscalls:sys_enter_newfstat              1657
syscalls:sys_enter_recvmsg               1768
syscalls:sys_enter_poll                  1813
syscalls:sys_enter_futex                 2176
syscalls:sys_enter_openat                2281
syscalls:sys_enter_close                 2546
Detaching...

stackcount

イベントにつながったスタックトレースをカウントする

ktime_get()につながったコードパスの特定(試しにコード追ってみた感じ参照は下から上っぽい)

オプション

-P	プロセス名+プロセスID

❯ sudo /usr/share/bcc/tools/stackcount ktime_get
Tracing 1 functions for "ktime_get"... Hit Ctrl-C to end.
^C
  ktime_get
  __schedule
  schedule
  io_schedule
  __lock_page_or_retry
  filemap_fault
  ext4_filemap_fault
  __do_fault
  __handle_mm_fault
  handle_mm_fault
  __do_page_fault
  do_page_fault
  page_fault
  [unknown]
    1

  ktime_get
  scsi_queue_rq
  blk_mq_dispatch_rq_list
  blk_mq_do_dispatch_sched
  blk_mq_sched_dispatch_requests
  __blk_mq_run_hw_queue
  __blk_mq_delay_run_hw_queue
  blk_mq_run_hw_queue
  blk_mq_sched_insert_requests
  blk_mq_flush_plug_list
  blk_flush_plug_list
  blk_finish_plug
  ext4_writepages
  do_writepages
  __filemap_fdatawrite_range
  filemap_flush
  ext4_alloc_da_blocks
  ext4_rename
  ext4_rename2
  vfs_rename
  do_renameat2
  __x64_sys_rename
  do_syscall_64
  entry_SYSCALL_64_after_hwframe
  [unknown]
  [unknown]
  [unknown]
    1
--------------------------------------------------------------------------------
use -P option

  ktime_get
  do_idle
  cpu_startup_entry
  start_secondary
  secondary_startup_64
    swapper/1 [0]
    130

stackcountの結果からframegraphを生成する

trace

イベントごとのカスタムな詳細を表示する
計測をするにあたってオーバーヘッドが大きいので、あまりに頻繁なイベントに対しては別のtoolを使ったほうが良い

❯ sudo /usr/share/bcc/tools/trace 'do_sys_open "%s", arg2'
PID     TID     COMM            FUNC             -
1968    3559    ftdc            do_sys_open      /proc/1968/stat
1968    3559    ftdc            do_sys_open      /proc/1968/stat
1968    3559    ftdc            do_sys_open      /proc/stat
1968    3559    ftdc            do_sys_open      /proc/meminfo
1968    3559    ftdc            do_sys_open      /proc/diskstats
1971    1971    snmpd           do_sys_open      /proc/net/dev
1971    1971    snmpd           do_sys_open      /proc/net/if_inet6
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr1/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/docker0/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/docker0/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/br-d794bdf9fb1e/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/br-d794bdf9fb1e/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr1-nic/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr0-nic/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/br-5b0ab1ed302c/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/br-5b0ab1ed302c/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/virbr0/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/virbr0/retrans_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/lo/device/vendor
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/lo/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/lo/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/conf/lo/forwarding
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/lo/base_reachable_time_ms
1971    1971    snmpd           do_sys_open      /sys/class/net/ens33/device/vendor
1971    1971    snmpd           do_sys_open      /sys/class/net/ens33/device/device
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv4/neigh/ens33/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/ens33/retrans_time_ms
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/conf/ens33/forwarding
1971    1971    snmpd           do_sys_open      /proc/sys/net/ipv6/neigh/ens33/base_reachable_time_ms

条件つけてfilteringとかできるみたいなので、そこは結構ありがたそうな印象
色々と触ってみて構造体周りの出力ができると嬉しい...と思ったらあった！！！
これもっと良い書き方あるんだろうなって思って書いたので見逃してください

❯ sudo /usr/share/bcc/tools/trace 'tcp_connect(struct sock *sk) "%x", sk->sk_daddr' -I 'net/sock.h'
PID     TID     COMM            FUNC             -
1716    1716    curl            tcp_connect      4e1bd9ac

-----------------------------------------------------------------------

❯ python3
>>> from socket import inet_ntop, AF_INET
>>> from struct import pack
>>> inet_ntop(AF_INET, pack("I",  int('4e1bd9ac', base=16)))
'172.217.27.78'

-----------------------------------------------------------------------

❯ dig google.com

;; ANSWER SECTION:
google.com.        5  IN  A   172.217.27.78

argdist

関数をトレースし、パラメータのヒストグラムもしくはカウントを出力する

オプション

-C	カウント
-H	ヒストグラム

vfs_read()によって返された結果のサイズのヒストグラムの出力

❯ sudo /usr/share/bcc/tools/argdist -H 'r::vfs_read()'
[13:23:14]
     retval              : count     distribution
         0 -> 1          : 5        |****************                        |
         2 -> 3          : 2        |******                                  |
         4 -> 7          : 12       |****************************************|
         8 -> 15         : 3        |**********                              |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 1        |***                                     |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 3        |**********                              |
       512 -> 1023       : 1        |***                                     |
      1024 -> 2047       : 2        |******                                  |
      2048 -> 4095       : 1        |***                                     |

試しにnginxへリクエストを投げた際のfdへの書き込みを確認する(ログへの書き込み、straceは取れてargdistだと取れないのはなぜなのか理解できていないので課題として積んでおく)

// straceでとりあえず何が呼ばれているかを確認する
❯ sudo strace -p 15526
strace: Process 15526 attached
epoll_wait(11, [{EPOLLIN, {u32=4277780496, u64=139775398494224}}], 512, -1) = 1
accept4(7, {sa_family=AF_INET, sin_port=htons(41066), sin_addr=inet_addr("127.0.0.1")}, [112->16], SOCK_NONBLOCK) = 3
epoll_ctl(11, EPOLL_CTL_ADD, 3, {EPOLLIN|EPOLLRDHUP|EPOLLET, {u32=4277781457, u64=139775398495185}}) = 0
epoll_wait(11, [{EPOLLIN, {u32=4277781457, u64=139775398495185}}], 512, 60000) = 1
recvfrom(3, "GET / HTTP/1.1\r\nHost: localhost:"..., 1024, 0, NULL, NULL) = 78
stat("/var/www/html/index.nginx-debian.html", {st_mode=S_IFREG|0644, st_size=612, ...}) = 0
openat(AT_FDCWD, "/var/www/html/index.nginx-debian.html", O_RDONLY|O_NONBLOCK) = 13
fstat(13, {st_mode=S_IFREG|0644, st_size=612, ...}) = 0
setsockopt(3, SOL_TCP, TCP_CORK, [1], 4) = 0
writev(3, [{iov_base="HTTP/1.1 200 OK\r\nServer: nginx/1"..., iov_len=247}], 1) = 247
sendfile(3, 13, [0] => [612], 612)      = 612
write(6, "127.0.0.1 - - [26/Oct/2019:22:48"..., 86) = 86
close(13)                               = 0
setsockopt(3, SOL_TCP, TCP_CORK, [0], 4) = 0
epoll_wait(11, [{EPOLLIN|EPOLLRDHUP, {u32=4277781457, u64=139775398495185}}], 512, 65000) = 1
recvfrom(3, "", 1024, 0, NULL, NULL)    = 0
close(3)                                = 0
epoll_wait(11, ^Cstrace: Process 15526 detached
 <detached ...>

-----------------------------------------------------------------------------------------------------------------------------

// writeだと何も出ない(ログへの書き込みは出ない)
❯ sudo /usr/share/bcc/tools/argdist -p 15526 -C 'p:c:write(int fd):int:fd'
[23:03:14]
p:c:write(int fd):int:fd
   COUNT      EVENT
[23:03:15]
p:c:write(int fd):int:fd
   COUNT      EVENT
[23:03:16]
p:c:write(int fd):int:fd
   COUNT      EVENT

-----------------------------------------------------------------------------------------------------------------------------

// writevだと出る(ソケットへの書き込みは出る)
❯ sudo /usr/share/bcc/tools/argdist -p 15526 -C 'p:c:writev(int fd):int:fd'
[23:03:50]
p:c:writev(int fd):int:fd
   COUNT      EVENT
[23:03:51]
p:c:writev(int fd):int:fd
   COUNT      EVENT
[23:03:52]
p:c:writev(int fd):int:fd
   COUNT      EVENT
   1          fd = 3
[23:03:53]
p:c:writev(int fd):int:fd
   COUNT      EVENT
[23:03:54]
p:c:writev(int fd):int:fd
   COUNT      EVENT
   1          fd = 3

-----------------------------------------------------------------------------------------------------------------------------

/proc/15526
❯ sudo ls -lh fd/
total 0
dr-x------ 2 www-data www-data  0 Oct 26 22:47 .
dr-xr-xr-x 9 www-data www-data  0 Oct 26 18:53 ..
lrwx------ 1 www-data www-data 64 Oct 26 23:09 0 -> /dev/null
lrwx------ 1 www-data www-data 64 Oct 26 23:09 1 -> /dev/null
lrwx------ 1 www-data www-data 64 Oct 26 23:09 10 -> 'socket:[95871]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 11 -> 'anon_inode:[eventpoll]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 12 -> 'anon_inode:[eventfd]'
l-wx------ 1 www-data www-data 64 Oct 26 23:09 2 -> /var/log/nginx/error.log
l-wx------ 1 www-data www-data 64 Oct 26 23:09 4 -> /var/log/nginx/access.log
l-wx------ 1 www-data www-data 64 Oct 26 23:09 5 -> /var/log/nginx/error.log
l-wx------ 1 www-data www-data 64 Oct 26 23:09 6 -> /var/log/nginx/main.log
lrwx------ 1 www-data www-data 64 Oct 26 23:09 7 -> 'socket:[95866]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 8 -> 'socket:[95867]'
lrwx------ 1 www-data www-data 64 Oct 26 23:09 9 -> 'socket:[95868]'

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

BPF本を読みながら学ぶ2

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

目次

• bitesize
• bpftool perf list
• vfsstat
• gethostlatency
• tcplife
• USDT probe

bitesize

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

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

フィールド

Kbytes	キロバイトの範囲
count	Kbytesの範囲に入ったI/Oの数
distribution	countの可視化

コマンドを実行したterminal

❯ dd if=/dev/zero of=./swapfile bs=1M count=2048
2048+0 records in
2048+0 records out
2147483648 bytes (2.1 GB, 2.0 GiB) copied, 3.24655 s, 661 MB/s

❯ sudo /usr/share/bcc/tools/bitesize 
Tracing block I/O... Hit Ctrl-C to end.
^C
Process Name = kworker/3:1H
     Kbytes              : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 0        |                                        |
        64 -> 127        : 0        |                                        |
       128 -> 255        : 0        |                                        |
       256 -> 511        : 0        |                                        |
       512 -> 1023       : 3        |****************************************|

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

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

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

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

bpftool perf list

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

terminal 2

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

terminal 1

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


❯ sudo bpftool prog show -p

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

vfsstat

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

フィールド

READ/s	vfs_read()呼び出しの一秒あたりの平均数
WRITE/s	vfs_write()呼び出しの一秒あたりの平均数
CREATE/s	vfs_create()呼び出しの一秒あたりの平均数
OPEN/s	vfs_open()呼び出しの一秒あたりの平均数
FSYNC/s	vfs_fsync()呼び出しの一秒あたりの平均数

❯ sudo /usr/share/bcc/tools/vfsstat 
TIME         READ/s  WRITE/s CREATE/s   OPEN/s  FSYNC/s
10:32:21:        81       29        0        7        0
10:32:22:        70       30        0        5        0
10:32:23:       548      303        0     2045        0
10:32:24:        80      100        0        5        0
10:32:25:        30       29        0        6        0
10:32:26:        49       29        0       20        0
10:32:27:        29       28        0        5        0
10:32:28:      1000      339        0      526        0
10:32:29:        47       28        0       20        0
10:32:30:        29       28        0        5        0

gethostlatency

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

フィールド

PID	呼び出しを実行しているプロセスのID
COMM	呼び出しを実行しているプロセス(コマンド)名
LATms	latency
HOST	ルックアップのターゲットであるホスト名

❯ sudo /usr/share/bcc/tools/gethostlatency 
TIME      PID    COMM                  LATms HOST
10:41:40  36378  DNS Resolver #1       19.90 detectportal.firefox.com
10:41:40  36387  DNS Resolver #2        0.84 detectportal.firefox.com
10:41:40  36378  DNS Resolver #1       16.87 mozilla.org
10:41:40  36388  DNS Resolver #3       19.86 mozilla.org
10:41:41  36387  DNS Resolver #2       34.27 push.services.mozilla.com
10:41:41  36378  DNS Resolver #1        0.57 push.services.mozilla.com
10:41:41  36388  DNS Resolver #3        0.69 push.services.mozilla.com
10:41:41  36387  DNS Resolver #2       33.96 tiles.services.mozilla.com
10:41:41  36388  DNS Resolver #3       19.09 content-signature-2.cdn.mozilla.net
10:41:41  36378  DNS Resolver #1       36.61 ocsp.digicert.com

tcplife

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

フィールド

PID	プロセスID
COMM	呼び出しを実行しているプロセス(コマンド)名
LADDR	ローカルIP
LPORT	ローカルポート
RADDR	リモートIP
RPORT	リモートポート
TX_KB	トータルの送信(キロバイト)
RX_KB	トータルの受信(キロバイト)
MS	セッションの寿命

❯ sudo /usr/share/bcc/tools/tcplife 
PID   COMM       LADDR           LPORT RADDR           RPORT TX_KB RX_KB MS
41633 curl       192.168.221.129 36010 172.217.161.36  443       0    16 146.34
42828 curl       192.168.221.129 46722 182.22.59.229   443       0     5 67.13

USDT probe

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

terminal 1

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

terminal 2

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