db tech showcase 2022 TokyoのDay2、11月17日12:00開始のD-11セッションで発表した内容です。
ソースコードは
https://github.com/insight-technology/pg96-strace にあります。
ツールの動画はこちらです
https://www.youtube.com/watch?v=EpbzkBD9_dA
システムコールとPostgreSQL
OSの上で走るプロセスはシステムコールを使うことでカーネルに問い合わせてファイルなどの協調が必要なリソースにアクセスできます。
PostgreSQLもOSの上で動くプロセスです。
つまりPostgreSQLが呼び出すシステムコールを見ればPostgreSQLが何をしているかわかる。
プログラムの動きを読むときにソースをあたるのとは別の方法としてstraceで具体的に何が起こっているか見ることにしましょう。
strace
straceはLinuxでプロセスが呼び出すシステムコールを取得するコマンドです。
straceを付けて起動するか起動済みのプロセスのIDを指定することでプロセスが発行したシステムコールを見ることができます。
$ strace コマンド
$ strace -p プロセスID
収集
環境
古めの方がきっと仕組みは単純だと思ったのでここでは9.6を使います。
環境はDockerコンテナで用意します。
OSからはコンテナの外でも中でもプロセスが見えるのでどちらからでもstraceを使用できますがpostgres起動のタイミングから追跡したかったのでdocker-entrypoint.shを書き換えます。
Dockerfile
FROM postgres:9.6
# ツール
## apt.postgres.orgにdebian strech用が保持されなくなったため削除
RUN rm /etc/apt/sources.list.d/pgdg.list \
&& apt update \
&& apt install strace
# postgres起動時にstraceを挟むように書き換える
## entrypointスクリプトの exec "$@" を starce "$@" にする
## -D デーモン
## -s データ操作の中身を128バイトまで表示
## -tt タイムスタンプをミリ秒まで表示
## -f forkしたプロセスを追跡対象
## -q straceのメッセージを非表示
## -e "!"で除外システムコール設定
## -o 出力ファイル名指定
RUN sed -i -e 's/exec "\$@"/strace -D -s 128 -tt -f -q -e "trace=!getpid,clock_gettime,gettimeofday,setitimer,semget,semop,set_robust_list,setsid,getrandom,rt_sigaction,rt_sigprocmask,rt_sigreturn,semctl,epoll_ctl,epoll_wait,fcntl,fstat,stat,mprotect,futex,set_tid_address,arch_prctl,statfs" -o \/tmp\/strace\/trace_\$(date +%Y%m%d-%H%M%S).log "\$@"/' /usr/local/bin/docker-entrypoint.sh
# postgresユーザーでアクセス可能にする
RUN mkdir /tmp/strace && chmod 0777 /tmp/strace
実行
# マウント時にコンテナの中のpostgresユーザーから書き込みできるようにパーミッションを777にする
$ mkdir ./log && chown 777 ./
$ docker build -t pgstrace ./
$ docker run -it -e POSTGRES_HOST_AUTH_METHOD=trust -v $(pwd)/log:/tmp/strace -p 5432:5432 pgstrace
その場の./logディレクトリにtrace_20221118-113933.logのようなファイルが作成されます。
ログ
こんな感じになります。
最初はだいたいライブラリ読み込みです。
69 16:53:09.330549 execve("/usr/lib/postgresql/9.6/bin/postgres", ["postgres"], [/* 17 vars */]) = 0
69 16:53:09.331020 brk(NULL) = 0x55c5ae64b000
69 16:53:09.331165 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
69 16:53:09.331379 access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
69 16:53:09.331615 open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
69 16:53:09.331895 mmap(NULL, 10219, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f26a7d67000
69 16:53:09.332007 close(3) = 0
69 16:53:09.332114 access("/etc/ld.so.nohwcap", F_OK) = -1 ENOENT (No such file or directory)
69 16:53:09.332274 open("/usr/lib/x86_64-linux-gnu/libxml2.so.2", O_RDONLY|O_CLOEXEC) = 3
69 16:53:09.332403 read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0\300\343\2\0\0\0\0\0@\0\0\
ファイルディスクリプタ
Everything is a file.
Unix系OSは標準入出力、ファイル、ソケット、デバイスはファイルとして抽象化されているのでLinuxとstraceでも開いたファイルの番号のファイルディスクリプタの操作が重要です。
ログ例
# open fd=4
85 19:44:44.940410 open("pg_stat_tmp/global.stat", O_RDONLY) = 4
# socket fd=8
77 19:40:44.774112 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 8
# epoll_create1
86 19:40:44.801103 epoll_create1(EPOLL_CLOEXEC) = 3
straceのオプション “-y” または “-yy” で同じ行に対応するファイル名などを出力することもできます。
$ strace -y cat /proc/cpuinfo
...
read(3</proc/cpuinfo>, "processor\t: 0\nvendor_id\t: Genuin"..., 131072) = 3132
シグナル
よくプロセスをシェルから終了させるためにkillコマンドを使いますね。
SIGINT, SIGTERMをプロセスに送ると行儀のよいプログラムなら終了してくれます。
シグナルは他にもあり、PostgreSQLはユーザー定義用に用途が限定されないSIGUSR1, SIGUSR2を使用しています。
シグナルを送るシステムコールもkillです。
kill(SIGUSR1)、これはもう脅迫ですね。プロセス達も緊張感を持って動いているのでしょう。
SIGUSR1の送信元88番がSQLを実行しているプロセス、送信先88番がWAL Writerの箇所
88 19:42:52.519959 recvfrom(9, "Q\0\0\0\25select * from t;\0", 8192, 0, NULL, NULL) = 22
88 19:42:52.520282 lseek(83, 0, SEEK_END) = 8192
88 19:42:52.520423 lseek(83, 0, SEEK_END) = 8192
88 19:42:52.520599 sendto(9, "T\0\0\0.\0\2a\0\0\0@\1\0\1\0\0\0\27\0\4\377\377\377\377\0\0b\0\0\0@\1\0\2\0\0\0\31\377\377\377\377\377\377\0\0D\0\0\0\24\0\2\0\0\0\0011\0\0\0\5test2C\0\0\0\rSELECT 1\0Z\0\0\0\5T", 88, 0, NULL, 0) = 88
88 19:42:52.520797 recvfrom(9, 0x5555b2c881a0, 8192, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
88 19:42:54.815981 recvfrom(9, "Q\0\0\0\16rollback;\0", 8192, 0, NULL, NULL) = 15
88 19:42:54.816135 kill(84, SIGUSR1) = 0
84 19:42:54.816189 --- SIGUSR1 {si_signo=SIGUSR1, si_code=SI_USER, si_pid=88, si_uid=999} ---
84 19:42:54.816210 write(10, "\0", 1 <unfinished ...>
88 19:42:54.816238 sendto(8, "\2\0\0\0x\1\0\0\0@\0\0\3\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1@\0\0UU\0\0\2\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\1\0\0\0\0\0\0\0"..., 376, 0, NULL, 0 <unfinished ...>
84 19:42:54.816272 <... write resumed> ) = 1
88 19:42:54.816292 <... sendto resumed> ) = 376
名所
dup()1000本ノック
起動後最初の方でファイルディスクリプタ0番を1000回複製してからすぐに閉じています。
開けるファイルディスクリプタ数を確認するための処理が走っていました。
69 11:39:34.213331 getrlimit(RLIMIT_NOFILE, {rlim_cur=1024*1024, rlim_max=1024*1024}) = 0
69 11:39:34.213517 dup(0) = 6
69 11:39:34.213694 dup(0) = 7
69 11:39:34.213878 dup(0) = 8
...
69 11:39:34.419447 dup(0) = 1004
69 11:39:34.419665 dup(0) = 1005
69 11:39:34.419881 close(6) = 0
69 11:39:34.420093 close(7) = 0
...
69 11:39:34.610000 close(1004) = 0
69 11:39:34.610181 close(1005) = 0
69 11:39:34.610365 pipe([6, 7]) = 0
69 11:39:34.610688 open("postmaster.opts", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 8
接続時
メインプロセスが待ち受けソケットでacceptして通信用ソケットを作成してプロセスをcloneしています。
cloneはファイルディスクリプタを引き継ぐので、各自いらないものを消してからワーカープロセスが接続情報を受信しています。
メインプロセスが77でワーカープロセスが87の例です。
77 19:40:49.653790 accept(3, {sa_family=AF_INET, sin_port=htons(41172), sin_addr=inet_addr("172.17.0.1")}, [128->16]) = 9
77 19:40:49.653838 getsockname(9, {sa_family=AF_INET, sin_port=htons(5432), sin_addr=inet_addr("172.17.0.2")}, [128->16]) = 0
77 19:40:49.653877 setsockopt(9, SOL_TCP, TCP_NODELAY, [1], 4) = 0
77 19:40:49.653901 setsockopt(9, SOL_SOCKET, SO_KEEPALIVE, [1], 4) = 0
77 19:40:49.654025 clone(child_stack=NULL, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD, child_tidptr=0x7f37fd2925d0) = 87
77 19:40:49.655066 close(9) = 0
87 19:40:49.655199 pipe([10, 11]) = 0
77 19:40:49.655459 select(6, [3 4 5], NULL, NULL, {tv_sec=60, tv_usec=0} <unfinished ...>
87 19:40:49.655817 close(7) = 0
87 19:40:49.656029 close(3) = 0
87 19:40:49.656330 close(4) = 0
87 19:40:49.656558 close(5) = 0
87 19:40:49.656948 epoll_create1(EPOLL_CLOEXEC) = 3
87 19:40:49.657651 recvfrom(9, "\0\0\0\10\4\322\26/", 8192, 0, NULL, NULL) = 8
87 19:40:49.657829 sendto(9, "N", 1, 0, NULL, 0) = 1
87 19:40:49.658169 recvfrom(9, "\0\0\0N\0\3\0\0user\0scott\0database\0scott\0application_name\0psql\0client_encoding\0UTF8\0\0", 8192, 0, NULL, NULL) = 78
クエリ実行時
insert into t values (2, repeat('a', 10 000 000)) 短いSQLで10000万文字(10MiB)を入れます。
クエリとメモリのところだけ抜き出すとinsertサイズと同じくらいの10002432byteをmmapで確保している場所がありますね。
88 19:43:34.656754 recvfrom(9, "Q\0\0\0005insert into t values (2, repeat('a', 10000000));\0", 8192, 0, NULL, NULL) = 54
88 19:43:34.657682 mmap(NULL, 10002432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f37eb66d000
88 19:43:34.678916 mmap(NULL, 10002432, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f37eace3000
88 19:43:34.687106 munmap(0x7f37eb66d000, 10002432) = 0
可視化
読んでこられた方もいよいよ眠くなってきたことでしょう。
今年はdb tech showcase: Data(base) Maverick Party! 🦍、退屈なコンテンツは許されません。
これだけなら普通のstrace。
でもここからが「
Maverick」なんです。
Unity
皆さん、Unityを用意して頂けますか？
2D/3Dのゲームエンジンです。
Uで始まるゲームエンジンが業界を二分している気がします。
そのうちの1つです。
ログ
straceはプロセスに関わるある瞬間のイベントです。
イベントの累積がある時点のプロセスの状態となります。
状態はプロセスとプロセスが掴んでいるファイルディスクリプタとメモリです。
straceログを再生用に変換します。
{"time": "19:40:44.438636", "event": {"name": "add_proc", "pid": 77, "ppid": 0}, "p_table": {"77": {"ppid": 0, "pid": 77, "name": "/usr/lib/postgresql/9.6/bin/postgres", "fd_table": {"0": {"class": "SStd", "fd": 0, "r": 0, "w": 0}, "1": {"class": "SStd", "fd": 1, "r": 0, "w": 0}, "2": {"class": "SStd", "fd": 2, "r": 0, "w": 0}}, "memory": 0}}}
{"time": "19:40:44.443218", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd32d000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.443911", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd10e000", "amount": 2488}, "p_table": null}
{"time": "19:40:44.447296", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fc8d6000", "amount": 12384}, "p_table": null}
{"time": "19:40:44.450209", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd32b000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.452377", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fbae1000", "amount": 6792}, "p_table": null}
{"time": "19:40:44.453333", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd32a000", "amount": 657}, "p_table": null}
{"time": "19:40:44.454362", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fb88e000", "amount": 14688}, "p_table": null}
{"time": "19:40:44.455362", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fb4f2000", "amount": 96}, "p_table": null}
{"time": "19:40:44.456031", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd29f000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.456410", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fb076000", "amount": 7680}, "p_table": null}
{"time": "19:40:44.459670", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f8e09000", "amount": 36968}, "p_table": null}
{"time": "19:40:44.460558", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f8be7000", "amount": 13384}, "p_table": null}
{"time": "19:40:44.461169", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd29d000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.462349", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f86f3000", "amount": 504}, "p_table": null}
{"time": "19:40:44.465932", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f7eab000", "amount": 6728}, "p_table": null}
{"time": "19:40:44.466548", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd29b000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.468809", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f786b000", "amount": 2888}, "p_table": null}
{"time": "19:40:44.469784", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f74d1000", "amount": 6864}, "p_table": null}
{"time": "19:40:44.472054", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd299000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.472428", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37f6d85000", "amount": 12896}, "p_table": null}
{"time": "19:40:44.476537", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd297000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.481669", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd295000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.482240", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd293000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.482372", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd291000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.484128", "event": {"name": "manip_mem", "pid": 77, "addr": "0x7f37fd28f000", "amount": 8192}, "p_table": null}
{"time": "19:40:44.496677", "event": {"name": "open_fd", "pid": 77, "fd": 3}, "p_table": {"77": {"ppid": 0, "pid": 77, "name": "/usr/lib/postgresql/9.6/bin/postgres", "fd_table": {"0": {"class": "SStd", "fd": 0, "r": 0, "w": 0}, "1": {"class": "SStd", "fd": 1, "r": 0, "w": 0}, "2": {"class": "SStd", "fd": 2, "r": 0, "w": 0}, "3": {"class": "SFile", "fd": 3, "target": "/var/lib/postgresql/data/postgresql.conf", "flag": "O_RDONLY", "r": 0, "w": 0}}, "memory": 215129}}}
{"time": "19:40:44.496928", "event": {"name": "read_fd", "pid": 77, "fd": 3, "content": "\"# -----------------------------\\n# PostgreSQL configuration file\\n# -----------------------------\\n#\\n# This file consists of lines \"...", "len": 8192}, "p_table": null}
{"time": "19:40:44.497097", "event": {"name": "read_fd", "pid": 77, "fd": 3, "content": "\"ommand = ''\\t\\t# command to use to archive a logfile segment\\n\\t\\t\\t\\t# placeholders: %p = path of file to archive\\n\\t\\t\\t\\t# \"...", "len": 8192}, "p_table": null}
{"time": "19:40:44.497253", "event": {"name": "read_fd", "pid": 77, "fd": 3, "content": "\"p'\\n\\n\\n# - Statistics Monitoring -\\n\\n#log_parser_stats = off\\n#log_planner_stats = off\\n#log_executor_stats = off\\n#log_statement_stat\"...", "len": 6216}, "p_table": null}
{"time": "19:40:44.497989", "event": {"name": "close_fd", "pid": 77, "fd": 3}, "p_table": {"77": {"ppid": 0, "pid": 77, "name": "/usr/lib/postgresql/9.6/bin/postgres", "fd_table": {"0": {"class": "SStd", "fd": 0, "r": 0, "w": 0}, "1": {"class": "SStd", "fd": 1, "r": 0, "w": 0}, "2": {"class": "SStd", "fd": 2, "r": 0, "w": 0}}, "memory": 215129}}}
時系列DBにありそうですね。
タイムスタンプと正規化したイベント、その瞬間のプロセス状態が1行のJSONになっています。
毎行プロセス状態を入れるとデータ量がすごいので前方向の差分で処理できるものは記録しないようにしています。
（もっと差分にできますができてないのでデータ量は元のログの10倍になっています）
リプレイ
冒頭の動画へ
https://www.youtube.com/watch?v=EpbzkBD9_dA
おお・・動いてる
プロセスができたり消えたり掴んでるファイルが増えたりします。
正直なところ高速で再生するとよくわからない。
人間の処理速度の限界がわかりました。
電脳化の実用が待たれます。
最初
1フレームずつ見てみましょう。
最初のプロセスがあります。
設定ファイルなどを読み込んだりロックファイルに書き込んだりします。
前回終了状態からのリカバリ処理のスタートアッププロセスが現れます。
スタートアッププロセスが終了するとおなじみのプロセスが立ち上がります。
クライアント接続時
一般的なマルチプロセスのネットワーク待ち受けです。
listenしているsocketがacceptして、ファイルディスクリプタごとcloneして各自いらないものをcloseしています。
大量接続
pgbenchを50接続で配置が密集してイクラ丼みたいになりました。
できなかったこと
ログを吐いた後に変換しているのでその場で追加の情報を得られていないです。
- プロセス名を書き換えた後の名前を知る
- psコマンドなどから見えるプロセス名を変えるために、各プロセス自身がargv[0]を書き換えているのを追跡できていない
- やっぱりメモリの中身を見たい
リアルタイムに取得して再生しながらVRで中からクエリとか投げたいですね。
まとめ
ソースコードを読む前にプロセスやファイルがどう動いているから見てみるのもいいのではないでしょうか
