bpftraceでPostgreSQLのバックエンドプロセスを追う
これは、Sansan Advent Calendar 2019 - Adventar の24日目のエントリーです。
PostgreSQLのUSDTを題材にしてbpftraceワンライナーをいくつか書いていきます。ここではuprobeは対象外としています。
はじめに
前提としてこれは遊びであり、PostgreSQLはマルチプロセスであるということから、現時点でよさげなUSDTトレーシング手法(つまり生まれては消えるバックエンドプロセスやらautovacuumワーカーやらパラレルクエリで起動するサブプロセスやら常駐するバックグラウンドプロセス全体を対象として隈なくUSDTを補足する方法)が見つけられない。USDTを補足する場合、既存のプロセスにアタッチする形をとるためである。
このような話題は以下で確認することができる。
一方でMySQLはスレッドモデルであり、プロセス全体としてUSDTを覗くのに適しているし、そのような例はググれば確かに見つかるし、今月発刊された以下の書籍のchapter13を通してMySQLの分析が出ており、こちらのほうが試し甲斐がきっとあるのだろう。自分としてはMySQLをあまり業務でさわったことがないが。
ただ、bpftraceは生のBCCと比較すると、よりアドホックな分析のために使われることが多く、何か現実に問題があったときにそのプロセスを対象として実施されることが多いはずで、各論的なアプローチがうまくいけば目的として十分達成されているというスタンスな気がする。
ということであるが、まずはbpftraceでPostgreSQLを追うに際して、利用できるUSDTを確認しておく。以下をver11.2で確認。
# bpftrace -l 'usdt:/usr/pgsql-11.2/bin/postgres' usdt:/usr/pgsql-11.2/bin/postgres:postgresql:clog__checkpoint__start ... ... usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__execute__start usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__execute__done usdt:/usr/pgsql-11.2/bin/postgres:postgresql:sort__start usdt:/usr/pgsql-11.2/bin/postgres:postgresql:sort__done
50個以上ある。
PostgreSQLのUSDTを題材にしてトレーシングの練習をしてみる。
クエリのライフサイクル
上記のUSDTの中で、バックエンド処理に関連しそうな query_* とか sort_* というUSDTを対象として、タイムスタンプとprobeをprintするワンライナーで実際に実行されている様子を観察すると以下のようになった。
# bpftrace -e 'usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query_* { printf(
"Passed: %ld, %s\n", nsecs, probe)} usdt:/usr/pgsql-11.2/bin/postgres:postgresql:sort_* { prin
tf("Passed: %ld, %s\n", nsecs, probe)}' -p <pid>
Attaching 12 probes...
Passed: 408581588562048, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__start
Passed: 408581588617673, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__parse__start
Passed: 408581588759128, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__parse__done
Passed: 408581588783823, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__rewrite__start
Passed: 408581588942843, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__rewrite__done
Passed: 408581588971818, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__plan__start
Passed: 408581589172124, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__plan__done
Passed: 408581589254474, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:sort__start
Passed: 408581589399734, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:sort__done
Passed: 408581589474509, usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__done
12個のUSDTが対象として登録され、バックエンド処理の話でよく解説されるようなリライト処理やプランナの処理が実行されていることがわかる。
これ自体なんてことはないが、各USDT処理のにフックして何らかの処理を行うという観点ではbpftraceが選択肢の1つに入るかもしれない。あるかわからないが。
発行されたクエリとそのduration
上記の query_start と query_done を対象として、発行されたクエリを文字列として得ることができるので、以下のようなbpftraceのMap型を利用した面白機能を実装可能である。
# bpftrace -e 'usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__start {
@start = nsecs; } usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__done { @query[str(arg0)] = (nsecs - @start) /1000;} END { clear(@start); }' -p <pid>
例えば以下のような結果を得られるだろう。
... @query[UPDATE pgbench_tellers SET tbalance = tbalance + 4794 WHERE tid]: 101 @query[UPDATE pgbench_tellers SET tbalance = tbalance + 4729 WHERE tid]: 101 @query[UPDATE pgbench_tellers SET tbalance = tbalance + 443 WHERE tid ]: 102 @query[SELECT abalance FROM pgbench_accounts WHERE aid = 82619;]: 102 @query[UPDATE pgbench_tellers SET tbalance = tbalance + 3678 WHERE tid]: 102 @query[UPDATE pgbench_tellers SET tbalance = tbalance + -2676 WHERE ti]: 102 @query[UPDATE pgbench_tellers SET tbalance = tbalance + 2617 WHERE tid]: 102 @query[UPDATE pgbench_tellers SET tbalance = tbalance + -884 WHERE tid]: 102 @query[UPDATE pgbench_tellers SET tbalance = tbalance + -1229 WHERE ti]: 102 ...
pgbench で起動したクライアントに対応するバックエンドプロセスにアタッチしたものであるが、要するにどんなクエリが発行されたかとそれのdurationを query_start と query_done のタイムスタンプの差分として出力している。
USDTのargsから得られるクエリ文字列が切れてしまったりしているので、もしかしていまのUSDTの実装的に最大長があるのかもしれず、全然実践向きでないが。面白機能としては楽しめる。
ヒストグラム
最後に見た目的に面白い機能として、hist() について。
上記のdurationのワンライナーをすこしいじって、最後にヒストグラムが出力されるようにする。
bpftrace -e 'usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__start { @start = nsecs; } usdt:/usr/pgsql-11.2/bin/postgres:postgresql:query__done { @ret = hist((nsecs
- @start) /1000);} END { clear(@start); }' -p <pid>
例えば以下のような結果を得られるだろう。
@ret: [4, 8) 41 |@ | [8, 16) 589 |@@@@@@@@@@@@@@@@@@@@ | [16, 32) 71 |@@ | [32, 64) 540 |@@@@@@@@@@@@@@@@@@@ | [64, 128) 1474 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@| [128, 256) 452 |@@@@@@@@@@@@@@@ | [256, 512) 6 | | [512, 1K) 0 | | [1K, 2K) 0 | | [2K, 4K) 0 | | [4K, 8K) 0 | | [8K, 16K) 788 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ | [16K, 32K) 201 |@@@@@@@ | [32K, 64K) 281 |@@@@@@@@@ | [64K, 128K) 280 |@@@@@@@@@ | [128K, 256K) 180 |@@@@@@ | [256K, 512K) 32 |@ | [512K, 1M) 3 | | [1M, 2M) 0 | | [2M, 4M) 0 | | [4M, 8M) 0 | | [8M, 16M) 0 | | [16M, 32M) 0 | | [32M, 64M) 0 | | [64M, 128M) 0 | | [128M, 256M) 0 | | [256M, 512M) 0 | | [512M, 1G) 0 | | [1G, 2G) 0 | | [2G, 4G) 1 | |
このままの実装だとクエリの内容は度外視であるが、アタッチしたプロセスが発行したクエリのdurationの分布を確認できている。
もうすこし凝ったことをしてクエリの内容と関連付けられれば何かが捗るかもしれない。そこまでやるにはbpftraceというよりもBCCスクリプトを自分で書いたほうがよりベターだとは思う。
まとめ
bpftraceのワンライナーでいろいろできることを確かめた。
bpftrace自体は、可観測性ツールという分野以外にも、なにやらTetrisを実装したりキータイピングのkprobeにフックしてオーディオ処理をしたり、楽しいハックがたくさんあるっぽい。
