BPF本を読みながら学ぶ8

8章、 ファイルシステムについて

目次

• 用語
• ファイルシステムのキャッシュ
• ディスクのパフォーマンス分析
• df
• mount
• fatrace
• statsnoop
• syncsnoop
• filelife
• vfscount
• fileslower
• filetop
• dcstat
• dcsnoop
• mountsnoop
• ext4dist

用語

• Read Ahead
  • シーケンシャルなアクセスを行う際に、次に読み込まれるページを先に読み込み、パフォーマンスを向上させる
  • readahead syscall
• Write Back
  • ディスクによるI/Oで、アプリケーションをブロックしないように、バッファをメモリに書き込んで、カーネルのワーカースレッドによってディスクへフラッシュする

ファイルシステムのキャッシュ

• ページキャッシュ
  • ファイルとI/Oバッファーの内容(バッファーキャッシュ)を含む仮想メモリページが含まれ、ファイルおよびディレクトリI/Oのパフォーマンスが向上する
• inodeキャッシュ
  • ファイルに対しての権限チェックやその他のメタデータを頻繁に読み込むために使用する
• ディレクトリキャッシュ
  • ディレクトリエントリ名からVFS inodeへのマッピングをキャッシュ、パス名によるルックアップのパフォーマンスを向上させる

ディスクのパフォーマンス分析

1. ファイルシステムの特定をする df / mount
2. ファイルシステムの容量を確認する ファイルシステム次第では使用量が100%に近づくにつれ、検索アルゴリズムによるパフォーマンスの問題が発生する
   1. ZFSは80%未満が良い
3. fioを使ってアイドル状態のシステムで既知のファイルシステムのワークロードを再現する
4. opensnoopを実行して開いているファイルを確認する
5. filelifeを実行して、寿命の短いファイルを確認する
6. 異常に遅いファイルシステムへのI/Oを特定する ext4slower / btrfsslower / zfsslower / fileslower
7. ファイルシステムのレイテンシの分布を調べる ext4dist / btrfsdist / zfsdist
8. ページキャッシュのヒット率を調べる cachestat
9. 論理I/Oと物理I/Oのレートを比較する(基本的には論理I/O > 物理I/Oが高いことが望ましい) vfsstat
10. bpftoolを実行する

df

ファイルシステムのディスクスペースの使用量を表示する

❯ df -h
Filesystem      Size  Used Avail Use% Mounted on
udev            3.9G     0  3.9G   0% /dev
tmpfs           796M  1.9M  794M   1% /run
/dev/sda1       290G  110G  167G  40% /
tmpfs           3.9G     0  3.9G   0% /dev/shm
tmpfs           5.0M  4.0K  5.0M   1% /run/lock
tmpfs           3.9G     0  3.9G   0% /sys/fs/cgroup
/dev/loop0       90M   90M     0 100% /snap/core/8213
/dev/loop1       11M   11M     0 100% /snap/kubectl/1357
/dev/loop2       90M   90M     0 100% /snap/core/8268
/dev/loop3       11M   11M     0 100% /snap/kubectl/1373
/dev/loop4      100M  100M     0 100% /snap/bpftrace/29
tmpfs           796M   20K  796M   1% /run/user/1000

mount

マウントされた全てのファイルシステムを表示する

❯ mount
sysfs on /sys type sysfs (rw,nosuid,nodev,noexec,relatime)
proc on /proc type proc (rw,nosuid,nodev,noexec,relatime)
udev on /dev type devtmpfs (rw,nosuid,relatime,size=4045620k,nr_inodes=1011405,mode=755)
devpts on /dev/pts type devpts (rw,nosuid,noexec,relatime,gid=5,mode=620,ptmxmode=000)
tmpfs on /run type tmpfs (rw,nosuid,noexec,relatime,size=814152k,mode=755)
/dev/sda1 on / type ext4 (rw,relatime,errors=remount-ro)

fatrace

システム全体のファイルアクセスイベントを表示する
プロセス名(プロセスID): イベントタイプ ファイルパス

オプション

-t	タイムスタンプの表示
-p PID	指定したプロセスを除外する

イベントタイプ

O	Open
R	Read
W	Write
C	Close

❯ sudo fatrace
chrome(4527): O /home/atrophy/.cache/google-chrome/Default/Cache/index-dir/temp-index
chrome(4527): CW /home/atrophy/.cache/google-chrome/Default/Cache/index-dir/temp-index
vmtoolsd(736): W /var/log/vmware-vmsvc-root.log
chrome(4471): CWO /home/atrophy/.config/google-chrome/Default/.com.google.Chrome.g1yHPA
chrome(4471): CWO /home/atrophy/.config/google-chrome/.com.google.Chrome.c6ba3F
chrome(4471): W /home/atrophy/.config/google-chrome/Default/.com.google.Chrome.g1yHPA
chrome(4471): CW /home/atrophy/.config/google-chrome/Local State
chrome(4471): CW /home/atrophy/.config/google-chrome/Default/Preferences
gnome-terminal-(3903): RCO /usr/share/icons/ubuntu-mono-dark/actions/16/window-close-symbolic.svg
gnome-terminal-(3903): R /usr/share/icons/ubuntu-mono-dark/actions/16/window-close-symbolic.svg
gnome-terminal-(3903): C /usr/share/icons/ubuntu-mono-dark/actions/16/window-close-symbolic.svg
gnome-terminal-(3903): O /usr/share/icons/Adwaita/scalable/actions/tab-new-symbolic.svg
gnome-terminal-(3903): RC /usr/share/icons/Adwaita/scalable/actions/tab-new-symbolic.svg
gnome-terminal-(3903): RO /usr/share/icons/Adwaita/scalable/actions/tab-new-symbolic.svg
gnome-terminal-(3903): C /usr/share/icons/Adwaita/scalable/actions/tab-new-symbolic.svg
gnome-terminal-(3903): RCO /usr/share/icons/Adwaita/scalable/actions/pan-down-symbolic.svg
gnome-terminal-(3903): C /usr/share/icons/Adwaita/scalable/actions/pan-down-symbolic.svg
pool(7940): RCO /etc/nsswitch.conf
pool(7940): CO /etc/ld.so.cache
pool(7940): RO /lib/x86_64-linux-gnu/libnss_compat-2.27.so
pool(7940): RO /lib/x86_64-linux-gnu/libnss_nis-2.27.so
pool(7940): RO /lib/x86_64-linux-gnu/libnsl-2.27.so
pool(7940): RO /lib/x86_64-linux-gnu/libnss_files-2.27.so
pool(7940): CO /etc/group
pool(7940): O /bin/bash
pool(7940): R /bin/bash
pool(7940): RO /lib/x86_64-linux-gnu/ld-2.27.so
bash(7940): C /lib/x86_64-linux-gnu/libnss_compat-2.27.so
bash(7940): C /lib/x86_64-linux-gnu/libnss_nis-2.27.so
bash(7940): C /lib/x86_64-linux-gnu/libnsl-2.27.so
bash(7940): C /lib/x86_64-linux-gnu/libnss_files-2.27.so

statsnoop

stat() syscallをトレースし、どのプロセスがどのファイルに関する情報を読み取ろうとしているかを表示する

オプション

-x	失敗した統計のみ表示
-t	タイムスタンプの表示
-p PID	指定したプロセスのみ表示

フィールド

TIME	呼び出し時間(秒単位)
PID	プロセスID
COMM	プロセス名
FD	ファイルディスクリプタ(失敗時は-1)
ERR	Error number(errno.h)
PATH	開いたパス

❯ sudo /usr/share/bcc/tools/statsnoop -t
TIME(s)       PID    COMM               FD ERR PATH
0.000000000   736    vmtoolsd            0   0 /etc/vmware-tools/tools.conf
0.000445262   13535  statsnoop          -1   2 /usr/lib/python2.7/encodings/ascii
1.975937867   3583   vmtoolsd            0   0 /etc/vmware-tools/tools.conf
5.000724336   736    vmtoolsd            0   0 /etc/vmware-tools/tools.conf
6.743327313   13310  ThreadPoolForeg     0   0 /etc/resolv.conf
6.743624226   729    systemd-resolve     0   0 /etc/hosts
6.743682672   729    systemd-resolve     0   0 /etc/resolv.conf
6.743698833   729    systemd-resolve     0   0 /etc/resolv.conf
6.977109934   3583   vmtoolsd            0   0 /etc/vmware-tools/tools.conf
10.002457003  736    vmtoolsd            0   0 /etc/vmware-tools/tools.conf

syncsnoop

ファイルシステムバッファをストレージデバイスにフラッシュするsync() syscallをトレースする

フィールド

TIME(s)	呼び出し時間(秒単位)
CALL	呼び出しのトレース

❯ sudo /usr/share/bcc/tools/syncsnoop
TIME(s)            CALL
23751.034417000    sync()
23751.770298000    sync()
23752.147148000    sync()
23752.378717000    sync()
23755.794625000    sync()
23759.138742000    sync()

filelife

ファイルの作成と削除をトレースし、ファイルを削除したユーザー、ファイルの経過時間、ファイル名に関する情報を表示する

オプション

-p PID	指定したプロセスのみ表示

フィールド

TIME	削除された時刻
PID	ファイルを削除したプロセスID
COMM	プロセス名
AGE(s)	作成されてから削除されるまでの時間(秒単位)
FILE	ファイル名

❯ sudo /usr/share/bcc/tools/filelife 
TIME     PID    COMM             AGE(s)  FILE
00:09:36 16063  bash             0.00    sh-thd.aglEmZ
00:09:36 18969  rm               4.36    hoge
00:09:45 18610  anacron          0.00    fileNpHdSz
00:09:45 495    systemd-udevd    0.00    queue
00:09:45 495    systemd-udevd    0.00    queue
00:09:45 495    systemd-udevd    0.00    queue
00:09:45 495    systemd-udevd    0.00    queue
00:09:45 19187  gpg              0.00    .#lk0x000055fe6b0679f0.ubuntu.19
00:09:45 19187  gpg              0.00    .#lk0x000055fe6b066f70.ubuntu.19
00:09:45 495    systemd-udevd    0.00    queue
00:09:45 19191  gpg              0.00    .#lk0x000055ebc43c8e70.ubuntu.19
00:09:45 19253  rm               0.05    trustdb.gpg
00:09:45 19253  rm               0.05    pubring.kbx
00:09:45 19253  rm               0.05    pubring.gpg

vfscount

VFS呼び出しをカウントする
VFSへの操作の一般的なワークロードの特性評価に役立つ

フィールド

ADDR	トレースされた命令ポインタ(instruction pointer)のアドレス
FUNC	カーネルのファンクション名
COUNT	トレース中に呼び出された回数

❯ sudo /usr/share/bcc/tools/vfscount 10
Tracing... Ctrl-C to end.

ADDR             FUNC                          COUNT
ffffffffa7af28f1 vfs_statfs                        1
ffffffffa7ac5b01 vfs_unlink                        3
ffffffffa7aefd91 vfs_fsync_range                   5
ffffffffa7ac4651 vfs_rmdir                         7
ffffffffa7b1df91 vfs_lock_file                    24
ffffffffa7acb121 vfs_readlink                     49
ffffffffa7ab7a11 vfs_write                       274
ffffffffa7abc3d1 vfs_statx                       299
ffffffffa7ab5de1 vfs_writev                      325
ffffffffa7ab7751 vfs_read                        365
ffffffffa7abc351 vfs_statx_fd                    868
ffffffffa7ab3541 vfs_open                       1100
ffffffffa7abc311 vfs_getattr                    1133
ffffffffa7abc281 vfs_getattr_nosec              1139

fileslower

VFSインターフェイスで同期読み取りおよび書き込みをカーネルの動的トレースを使用して、
ファイルシステムへの遅いファイル読み込みと書き込みを見分ける

フィールド

TIME(s)	最初のI/Oが開始してからI/Oが完了するまでにかかった時間(秒単位)
COMM	プロセス名
PID	プロセスID
D	I/Oの方向 R(Read) W(write)
BYTES	I/Oのサイズ
LAT(ms)	I/Oのlatency
FILENAME	キャッシュされたカーネルのファイル名(dentry->d_iname)

❯ sudo /usr/share/bcc/tools/fileslower 
Tracing sync read/writes slower than 10 ms
TIME(s)  COMM           TID    D BYTES   LAT(ms) FILENAME
26.288   dd             21861  W 1048576   10.30 swapfile
26.979   dd             21861  W 1048576   11.35 swapfile
28.525   dd             21861  W 1048576   38.75 swapfile
28.622   dd             21861  W 1048576   11.50 swapfile
28.644   dd             21861  W 1048576   12.38 swapfile
28.682   dd             21861  W 1048576   30.95 swapfile
28.698   dd             21861  W 1048576   15.74 swapfile
28.720   dd             21861  W 1048576   19.20 swapfile

filetop

プロセスとファイル名による読み込みと書き込み
Topコマンドのファイル版

オプション

-a	通常ファイル以外のファイルタイプも含める(sockets, FIFOs, etc)
-p PID	指定したプロセスのみ表示

フィールド

loadavg	/proc/loadavgの内容
TID	スレッドID
COMM	プロセス名
READS	インターバル中の読み込み回数
WRITES	インターバル中の書き込み回数
R_Kb	インターバル中の読み込み(Kbytes)の合計
W_Kb	インターバル中の書き込み(Kbytes)の合計
T	ファイルのタイプ R(Regular) S(Socket) O(Other(pipe, etc))

❯ sudo /usr/share/bcc/tools/filetop -a

01:10:17 loadavg: 0.05 0.11 0.07 1/725 22487

TID    COMM             READS  WRITES R_Kb    W_Kb    T FILE
3903   gnome-terminal-  8      1      62      0       O ptmx
1707   InputThread      8      0      56      0       O event1
22487  clear            2      0      8       0       R xterm-256color
3404   gmain            2      0      8       0       O inotify
22484  filetop          2      0      2       0       R loadavg
22487  clear            1      0      0       0       R libtinfo.so.5.9
22487  clear            1      0      0       0       R libc-2.27.so
22487  filetop          3      0      0       0       R clear
22487  filetop          2      0      0       0       R ld-2.27.so
3188   gdbus            12     28     0       0       O [eventfd]
3279   gdbus            6      10     0       0       O [eventfd]
3903   gnome-terminal-  7      8      0       0       O [eventfd]
3312   gnome-shell      6      8      0       0       O [eventfd]
3905   gdbus            6      8      0       0       O [eventfd]
3180   ibus-daemon      8      4      0       0       O [eventfd]
1127   acpid            6      0      0       0       O event1
22484  filetop          0      3      0       0       O 0
3404   gmain            2      6      0       0       O [eventfd]
3275   ibus-engine-sim  2      2      0       0       O [eventfd]
3903   gnome-terminal-  0      2      0       0       O [eventfd]

dcstat

ディレクトリエントリキャッシュ(dcache)の統計

フィールド

TIME	タイムスタンプ
REFS/s	dcacheのルックアップ数(秒間)
SLOW/s	lookup_fast()に失敗し、 代わりにlookup_slow()を実行したdcacheのルックアップ数(秒間)
MISS/s	ミス数(lookup_fast/lookup_slowの両方に失敗した場合)
HIT%	dcacheのヒット率

❯ sudo /usr/share/bcc/tools/dcstat
TIME         REFS/s   SLOW/s   MISS/s     HIT%
01:21:12:        36        0        0   100.00
01:21:13:         8        0        0   100.00
01:21:14:        66        0        0   100.00
01:21:15:       404        0        0   100.00
01:21:16:        13        0        0   100.00
01:21:17:        40        0        0   100.00
01:21:18:        63        1        0   100.00
01:21:19:        23        0        0   100.00
01:21:20:      7218       72       63    99.13
01:21:21:         8        0        0   100.00

dcsnoop

ディレクトリエントリキャッシュ(dcache)ルックアップをトレースする

オプション

-a	失敗したルックアップだけでなく、参照もトレースに含める

フィールド

TIME(s)	ルックアップした時間(秒単位)
PID	プロセスID
COMM	プロセス名
T	タイプ R(Reference) -aオプションの場合のみ表示 M(Miss)
FILE	ルックアップしていたファイル名コンポーネント

❯ sudo /usr/share/bcc/tools/dcsnoop -a
TIME(s)     PID    COMM             T FILE
0.097416    3481   gsd-color        R etc/localtime
0.097488    3481   gsd-color        R localtime
0.097515    3481   gsd-color        R usr/share/zoneinfo/Asia/Tokyo
# 省略
0.097779    23215  dcsnoop          R usr/lib/python2.7/encodings/ascii
0.097786    23215  dcsnoop          R lib/python2.7/encodings/ascii
0.097809    23215  dcsnoop          R python2.7/encodings/ascii
# 省略
0.753587    1175   gmain            R extrausers
0.753599    1211   gmain            R etc/NetworkManager/VPN
0.753622    1211   gmain            R NetworkManager/VPN
0.753634    1211   gmain            R VPN
# 省略
4.666200    23163  ThreadPoolForeg  M .com.google.Chrome.LWOyo3

mountsnoop

mount() および umount() syscallをトレースする

COMM	プロセス名
PID	プロセスID
TID	スレッドID
MNT_NS	マウントしているnamespaceのinode number
CALL	syscall、引数、戻り値

❯ sudo /usr/share/bcc/tools/mountsnoop 
COMM             PID     TID     MNT_NS      CALL
dockerd          1329    2575    4026531840  mount("overlay", "/var/lib/docker/overlay2/f606e18c5811d17fbe31ae16d76af01a3a1c77f6e72c031137d98499c79d3ebb-init/merged", "overlay", MS_NOSUID|MS_NOEXEC|MS_REMOUNT|MS_MANDLOCK|MS_MOVE|MS_REC|MS_SILENT|MS_POSIXACL|MS_UNBINDABLE|MS_PRIVATE|MS_LAZYTIME|MS_NOUSER|0x564510000200, "") = 0
dockerd          1329    1714    4026531840  mount("overlay", "/var/lib/docker/overlay2/b9dc1b32c519d1567f91049d638141703d05795dedd49d371628d8a6c3d4ed30-init/merged", "overlay", MS_NOSUID|MS_NOEXEC|MS_REMOUNT|MS_MANDLOCK|MS_MOVE|MS_REC|MS_SILENT|MS_POSIXACL|MS_UNBINDABLE|MS_PRIVATE|MS_LAZYTIME|MS_NOUSER|0x564510000200, "") = 0
dockerd          1329    1673    4026531840  mount("overlay", "/var/lib/docker/overlay2/accc5ace809c7b6f253c0ba6aabea824b16555b78b482687a3fc4bd95fd8c1f8-init/merged", "overlay", MS_NOSUID|MS_NOEXEC|MS_REMOUNT|MS_MANDLOCK|MS_MOVE|MS_REC|MS_SILENT|MS_POSIXACL|MS_UNBINDABLE|MS_PRIVATE|MS_LAZYTIME|MS_NOUSER|0x564510000200, "") = 0
dockerd          1329    1563    4026531840  mount("overlay", "/var/lib/docker/overlay2/5c2f7a8d49bfc977691083b40801307c929632baa9de64acbeb1acc26d0016b7-init/merged", "overlay", MS_NOSUID|MS_NOEXEC|MS_REMOUNT|MS_MANDLOCK|MS_MOVE|MS_REC|MS_SILENT|MS_POSIXACL|MS_UNBINDABLE|MS_PRIVATE|MS_LAZYTIME|MS_NOUSER|0x564510000200, "") = 0
dockerd          1329    1563    4026531840  umount("/var/lib/docker/overlay2/5c2f7a8d49bfc977691083b40801307c929632baa9de64acbeb1acc26d0016b7-init/merged", MNT_DETACH) = 0
dockerd          1329    2575    4026531840  umount("/var/lib/docker/overlay2/f606e18c5811d17fbe31ae16d76af01a3a1c77f6e72c031137d98499c79d3ebb-init/merged", MNT_DETACH) = 0
dockerd          1329    1673    4026531840  umount("/var/lib/docker/overlay2/accc5ace809c7b6f253c0ba6aabea824b16555b78b482687a3fc4bd95fd8c1f8-init/merged", MNT_DETACH) = 0
dockerd          1329    1714    4026531840  umount("/var/lib/docker/overlay2/b9dc1b32c519d1567f91049d638141703d05795dedd49d371628d8a6c3d4ed30-init/merged", MNT_DETACH) = 0
dockerd          1329    2575    4026531840  mount("overlay", "/var/lib/docker/overlay2/f606e18c5811d17fbe31ae16d76af01a3a1c77f6e72c031137d98499c79d3ebb/merged", "overlay", MS_NOSUID|MS_NOEXEC|MS_REMOUNT|MS_MANDLOCK|MS_MOVE|MS_REC|MS_SILENT|MS_POSIXACL|MS_UNBINDABLE|MS_PRIVATE|MS_LAZYTIME|MS_NOUSER|0x564510000200, "") = 0

ext4dist

ext4操作のレイテンシを要約する

フィールド

usecs	マイクロ秒の範囲
count	範囲内のオペレーションの回数
distribution	カウントの分布

❯ sudo /usr/share/bcc/tools/ext4dist
Tracing ext4 operation latency... Hit Ctrl-C to end.

operation = read
     usecs               : count     distribution
         0 -> 1          : 290      |****************************************|
         2 -> 3          : 11       |*                                       |
         4 -> 7          : 3        |                                        |
         8 -> 15         : 4        |                                        |
        16 -> 31         : 1        |                                        |

operation = write
     usecs               : count     distribution
         0 -> 1          : 1        |****************************************|
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |****************************************|

operation = open
     usecs               : count     distribution
         0 -> 1          : 175      |****************************************|
         2 -> 3          : 5        |*                                       |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 1        |                                        |

BPF本を読みながら学ぶ7

7章、 メモリについて
仮想･物理のそれぞれについて理解がまた一段と深まった
昔作ったメモリリークアプリが役に立ったのが地味に嬉しい

目次

• 用語
• メモリのパフォーマンス分析
• swapon
• ps
• pmap
• sar
• oomkill
• memleak
• shmsnoop
• drsnoop

用語

• backed by disk
  • ディスクから読み出されて変更のなかったページ
• brk syscall
  • 渡した値が現在の値を下回った場合、ヒープの領域の開放が行われる
  • 渡した値が現在の値を上回った場合、ヒープの領域の拡張が行われる(失敗するとENOMEM)

メモリのパフォーマンス分析

1. システムメッセージをチェックして、最近にOOMキラーがプロセスを強制終了したかどうかを確認する dmesg
2. システムにスワップデバイスがあるかどうか、及び使用中のスワップの量を確認する(それらのデバイスに対してのアクティブなI/Oがあるかも確認する) swapon -s / free / vmstat / iostat
3. システム上の空きメモリの量とキャッシュによるシステム全体の使用量を確認する
4. プロセスごとのメモリ使用量を確認する top / ps axo user,pid,pmem,vsz,rsz,comm
5. ページフォールトのレートを確認し、ページフォールトのスタックトレースを調べる これでRSSの増加については説明ができる(ページフォールトする箇所のコードでヒットしなかった場合に物理メモリの確保を行うからだと思われ)
6. ページフォールトしていたファイルを調べる
7. brkとmmapのsyscallをトレースして、メモリ使用量のビューを取得する
8. BPFツールを使用して実行する
9. PMCを使用してハードウェアキャッシュミスとメモリアクセスを確認し、メモリI/Oを引き起こす関数と命令を特定する perf

swapon

スワップデバイスの構成及び使用中のボリュームの量を表示する

❯ swapon -s
Filename        Type    Size  Used  Priority
/dev/sda5                               partition 5661692 0 -2

ps

プロセスごとのメモリ使用量を確認する

❯ ps axo user,pid,pmem,vsz,rsz,comm | head -n10
USER        PID %MEM    VSZ   RSZ COMMAND
root          1  0.1 225492  9328 systemd
root          2  0.0      0     0 kthreadd
root          3  0.0      0     0 rcu_gp
root          4  0.0      0     0 rcu_par_gp
root          6  0.0      0     0 kworker/0:0H-kb
root          8  0.0      0     0 mm_percpu_wq
root          9  0.0      0     0 ksoftirqd/0
root         10  0.0      0     0 rcu_sched
root         11  0.0      0     0 migration/0

pmap

アドレス空間ごとのプロセスのメモリ使用量の表示
Dirtyのカラムは、メモリ内で変更されてディスク側へ保存されていないページサイズ

❯ pmap -x 8998
// 一部省略
8998:   node server.js
Address           Kbytes     RSS   Dirty Mode  Mapping
0000000000400000   31320   22132       0 r-x-- node
0000000000400000       0       0       0 r-x-- node
0000000002495000       8       8       8 r---- node
0000000002495000       0       0       0 r---- node
0000000002497000      84      84      32 rw--- node
0000000002497000       0       0       0 rw--- node
00000000024ac000     104     100     100 rw---   [ anon ]
00007f631b198000       4       0       0 -----   [ anon ]
00007f631b198000       0       0       0 -----   [ anon ]
00007f631ccf3000       4       4       4 rw--- libdl-2.27.so
00007f631ccf3000       0       0       0 rw--- libdl-2.27.so
00007f631ccf4000     156     156       0 r-x-- ld-2.27.so
00007f631ccf4000       0       0       0 r-x-- ld-2.27.so
00007ffd501d2000     136      56      56 rw---   [ stack ]
00007ffd501d2000       0       0       0 rw---   [ stack ]
00007ffd501fe000       0       0       0 r-x--   [ anon ]
ffffffffff600000       4       0       0 r-x--   [ anon ]
ffffffffff600000       0       0       0 r-x--   [ anon ]
---------------- ------- ------- ------- 
total kB          575736   52096   25988

sar

フィールド

pgpgin/s	システムが1秒間にディスクからページインしたキロバイトの合計
pgpgout/s	システムが1秒間にディスクにページアウトしたキロバイトの合計
fault/s	システムによって1秒間に発生したページフォールト(major + minor)の回数. 一部のページフォールトはI/Oなしで解決できる為、これはI/Oが発生するページフォールトの回数ではない.
majflt/s	システムが1秒間に行ったメジャーフォールトの(ディスクからメモリへページを読み込む必要があった)回数
pgfree/s	システムによって1秒間に空きリストに配置されたページの数
pgscank/s	kswapdデーモンによって1秒間にスキャンされたページの数
pgscand/s	1秒間に直接スキャンされたページ数
pgsteal/s	メモリへの要求を満たすためにシステムが1秒間にキャッシュ(pagecache/swapcache)から回収したページ数
%vmeff	ページ再利用の指標(一定時間内にページがスキャンされなかった場合、このフィールドはゼロとして表示される)

❯ sar -B 1
Linux 5.0.0-36-generic (ubuntu)   12/01/2019  _x86_64_  (4 CPU)

04:58:42 PM  pgpgin/s pgpgout/s   fault/s  majflt/s  pgfree/s pgscank/s pgscand/s pgsteal/s    %vmeff
04:58:43 PM      0.00      0.00      1.00      0.00     13.00      0.00      0.00      0.00      0.00
04:58:44 PM      0.00      0.00     23.00      0.00     24.00      0.00      0.00      0.00      0.00
^C

Average:         0.00      0.00     12.00      0.00     18.50      0.00      0.00      0.00      0.00

oomkill

カーネルのOOMKillerをトレースし、強制終了時のシステム負荷平均などの基本的な詳細を出力する

# これでOOMKillされる優先順位をあげる
❯ sudo echo 1000 > /proc/18169/oom_score_adj

# 優先順位の確認
❯ dstat --top-oom
--out-of-memory---
    kill score    
node          1.0k

# リクエストを投げつけてメモリの確保を大量にさせる(内容としては、投げつけたsize分のランダムに生成したバイトをglobalのarrayにpushしている)
❯ curl localhost:3000/?size=2147483647
{"rss":1160204288,"heapTotal":16543744,"heapUsed":11553040,"external":34359797528}

# 別タブで観測しておく
❯ sudo /usr/share/bcc/tools/oomkill 
Tracing OOM kills... Ctrl-C to stop.
22:47:29 Triggered by PID 18854 ("node"), OOM kill of PID 18169 ("node"), 2035372 pages, loadavg: 2.77 1.29 0.69 6/714 19862
^C

memleak

メモリリークを検出するために、未解決の割り当てとその呼び出しのスタックのサマリを出力する

# リクエストを投げつけてメモリの確保をさせる
❯ curl localhost:3000/?size=2147483
{"rss":51503104,"heapTotal":24977408,"heapUsed":17034168,"external":2430550}

# 別タブでnodeのprocessにアタッチさせておく
❯ sudo /usr/share/bcc/tools/memleak -p 20294
Attaching to pid 20294, Ctrl+C to quit.
[22:55:08] Top 10 stacks with outstanding allocations:

  2147483 bytes in 1 allocations from stack
    v8::internal::JSArrayBuffer::SetupAllocatingData(v8::internal::Handle<v8::internal::JSArrayBuffer>, v8::internal::Isolate*, unsigned long, bool, v8::internal::SharedFlag)+0x93 [node]
    v8::internal::(anonymous namespace)::ConstructBuffer(v8::internal::Isolate*, v8::internal::Handle<v8::internal::JSFunction>, v8::internal::Handle<v8::internal::JSReceiver>, v8::internal::Handle<v8::internal::Object>, bool)+0x74 [node]
    v8::internal::Builtin_ArrayBufferConstructor(int, v8::internal::Object**, v8::internal::Isolate*)+0xa3 [node]
    [unknown]
    [unknown]
    [unknown]
    v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle<v8::internal::Object>, v8::internal::Handle<v8::internal::Object>, int, v8::internal::Handle<v8::internal::Object>*)+0x103 [node]
    v8::Function::Call(v8::Local<v8::Context>, v8::Local<v8::Value>, int, v8::Local<v8::Value>*)+0x179 [node]
    node::MakeCallback(v8::Isolate*, v8::Local<v8::Object>, v8::Local<v8::Function>, int, v8::Local<v8::Value>*, node::async_context)+0x1b2 [node]
    node::Environment::CheckImmediate(uv_check_s*)+0xbc [node]
    uv__run_check+0x8c [node]
    uv_run+0x153 [node]
    node::Start(v8::Isolate*, node::IsolateData*, std::vector<std::string, std::allocator<std::string> > const&, std::vector<std::string, std::allocator<std::string> > const&)+0x565 [node]
    node::Start(int, char**)+0x469 [node]
    __libc_start_main+0xe7 [libc-2.27.so]
    [unknown]

shmsnoop

SystemV共有メモリのシステムコールをトレースする
対象はshmget, shmat, shmdt, shmctl っぽい

フィールド

PID	プロセスID
COMM	コマンド名(親プロセス)
SYS	syscall
RET	syscallの戻り値
ARGs	syscallの引数

❯ sudo /usr/share/bcc/tools/shmsnoop
PID    COMM                SYS              RET ARGs
1243   Xorg              SHMAT     7fe099431000 shmid: 0x1b8004, shmaddr: 0x0, shmflg: 0x0
1243   Xorg             SHMCTL                0 shmid: 0x1b8004, cmd: 2, buf: 0x7ffd1012f130
1243   Xorg              SHMDT                0 shmaddr: 0x7fe099431000
1243   Xorg              SHMAT     7fe099431000 shmid: 0x1c0004, shmaddr: 0x0, shmflg: 0x0
1243   Xorg             SHMCTL                0 shmid: 0x1c0004, cmd: 2, buf: 0x7ffd1012f130
1243   Xorg              SHMDT                0 shmaddr: 0x7fe099431000
3209   gnome-shell      SHMGET           1c8004 key: 0x0, size: 49152, shmflg: 0x3ff (IPC_CREAT|0777)
3209   gnome-shell       SHMAT     7effebf5b000 shmid: 0x1c8004, shmaddr: 0x0, shmflg: 0x0
3209   gnome-shell      SHMCTL                0 shmid: 0x1c8004, cmd: 0, buf: 0x0
1243   Xorg              SHMAT     7fe099426000 shmid: 0x1c8004, shmaddr: 0x0, shmflg: 0x0
1243   Xorg             SHMCTL                0 shmid: 0x1c8004, cmd: 2, buf: 0x7ffd1012f130
3209   gnome-shell      SHMGET           1d000f key: 0x0, size: 32768, shmflg: 0x3ff (IPC_CREAT|0777)
3209   gnome-shell       SHMAT     7effebf53000 shmid: 0x1d000f, shmaddr: 0x0, shmflg: 0x0
3209   gnome-shell      SHMCTL                0 shmid: 0x1d000f, cmd: 0, buf: 0x0
1243   Xorg              SHMAT     7fe09941e000 shmid: 0x1d000f, shmaddr: 0x0, shmflg: 0x0
1243   Xorg             SHMCTL                0 shmid: 0x1d000f, cmd: 2, buf: 0x7ffd1012f130
1243   Xorg              SHMDT                0 shmaddr: 0x7fe099426000
3209   llvmpipe-0        SHMDT                0 shmaddr: 0x7effebf5b000
3209   llvmpipe-0       SHMCTL ffffffffffffffea shmid: 0x1c8004, cmd: 0, buf: 0x0
3209   gnome-shell      SHMGET           1d8004 key: 0x0, size: 49152, shmflg: 0x3ff (IPC_CREAT|0777)
3209   gnome-shell       SHMAT     7effebf5b000 shmid: 0x1d8004, shmaddr: 0x0, shmflg: 0x0
3209   gnome-shell      SHMCTL                0 shmid: 0x1d8004, cmd: 0, buf: 0x0
1243   Xorg              SHMAT     7fe099426000 shmid: 0x1d8004, shmaddr: 0x0, shmflg: 0x0
1243   Xorg             SHMCTL                0 shmid: 0x1d8004, cmd: 2, buf: 0x7ffd1012f130
1243   Xorg              SHMDT                0 shmaddr: 0x7fe09941e000
3209   llvmpipe-0        SHMDT                0 shmaddr: 0x7effebf53000
3209   llvmpipe-0       SHMCTL ffffffffffffffea shmid: 0x1d000f, cmd: 0, buf: 0x0
3209   gnome-shell      SHMGET           1e000f key: 0x0, size: 131072, shmflg: 0x3ff (IPC_CREAT|0777)
3209   gnome-shell       SHMAT     7effebf3b000 shmid: 0x1e000f, shmaddr: 0x0, shmflg: 0x0
3209   gnome-shell      SHMCTL                0 shmid: 0x1e000f, cmd: 0, buf: 0x0
1243   Xorg              SHMAT     7fe099245000 shmid: 0x1e000f, shmaddr: 0x0, shmflg: 0x0
1243   Xorg             SHMCTL                0 shmid: 0x1e000f, cmd: 2, buf: 0x7ffd1012f130
1243   Xorg              SHMDT                0 shmaddr: 0x7fe099426000
3209   llvmpipe-0        SHMDT                0 shmaddr: 0x7effebf5b000
3209   llvmpipe-0       SHMCTL ffffffffffffffea shmid: 0x1d8004, cmd: 0, buf: 0x0
1243   Xorg              SHMDT                0 shmaddr: 0x7fe099245000
3209   llvmpipe-0        SHMDT                0 shmaddr: 0x7effebf3b000
3209   llvmpipe-0       SHMCTL ffffffffffffffea shmid: 0x1e000f, cmd: 0, buf: 0x0

例えば下のやつについて見てみる
1243 Xorg SHMAT 7fe099431000 shmid: 0x1b8004, shmaddr: 0x0, shmflg: 0x0

呼び出されているsyscallはshmatで、これのmanを読むと、
呼び出したプロセスのアドレス空間にshmidで指定されたSystem V共有メモリセグメントをアタッチする
今回でいうとshmaddrはnull(0x0)なので、使用されていないアドレスに対してアタッチ(0x1b8004)する
そしてそのアドレスを返す(7fe099431000)

drsnoop

direct reclaimイベントをトレースし、どのプロセスがdirect reclaimでページを割り当てているかを表示する

stessでメモリに負荷をかけて計測してみた

❯ sudo /usr/share/bcc/tools/drsnoop
COMM           PID     LAT(ms) PAGES
stress         29720      0.53   387
stress         29720      1.11   179
stress         29720      0.70   362
stress         29720      0.40    69
stress         29720      0.24    36
stress         29720      0.28   127
stress         29720      0.26    78
stress         29720      0.33   102
stress         29720      0.15    36
stress         29718      0.16   189
stress         29718      0.15   130
stress         29718      0.14   172
stress         29718      0.14   147
stress         29719      0.54   324
stress         29719      1.10   422
stress         29719      0.68   101
stress         29719      0.18   134
stress         29719      0.24   277
stress         29719      0.22    93
stress         29719      0.29    70
stress         29719      0.15   165
stress         29719      0.25   197
stress         29719      0.16    74

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]'