BPFを用いてPostgreSQL共有バッファ読込を動的トレーシング
この記事は、 Sansan Advent Calendar 2018 - Adventar 22日目のエントリです。
目次
- 目次
- AWRのSQL ordered by Readsのようにクエリごとにreadしたブロック数をPostgreSQLで知りたい
- bcc/BPFによるシステムの動的トレーシング
- PostgreSQLが提供するプローブ
- smgr-md-read-doneのコールバックで共有バッファ読込を観測するpython+c のコード
- 使用例
- Wrap-up / bccを利用した可観測性ツールが熱い
- 参考資料
AWRのSQL ordered by Readsのようにクエリごとにreadしたブロック数をPostgreSQLで知りたい
Oracle DBを運用していると、AWRやStatspackのお世話になることが多いはずである。
AWRでは、レポートの中に SQL ordered by Reads
というセクションがあり、ストレージからReadしたブロック数をクエリごとに集計して表示してくれる。
普段からブロック読込の多いクエリはここを見れば把握でき、Oracleを触っていた時はここをよく見ていたし、実際に性能改善の解決の糸口になったこともあったりした。
ブロックの読込が多い傾向にあればそれはそのままロングクエリになる可能性が高いし、直感的でわかりやすい指標だと思う。
データベースのパフォーマンスというのは、永続ストレージに如何にアクセスしないで済むかということに大きく絡むため、クエリごとにメモリに読み込んだブロックを把握することはパフォーマンス改善の点で非常に有用であるのだけど、PostgreSQLではどのようにそれを観測すればいいだろうか。
bcc/BPFによるシステムの動的トレーシング
データベースの話題から一旦それる。
BPF(Berkeley Packet Filter)は、Linuxカーネル内で小さなユーザスクリプトを動作させることができる仮想マシンである。名前の通りもともとパケットフィルタツールとして 開発されたものであったが、近年においては拡張され、LinuxOSの動的トレーシングに使われるように進化してきた。例えば、特定ファイルに対するアクセスを捕捉して動作する小さなプログラムを簡単に書くことができる。
このように拡張されたBPFは、特にeBPF(enhanced BPF) と呼ばれるが、単にBPFといった時にはeBPFをさすことが多いようである。
BPFを扱う上では、bcc(BPF Compiler Collection) を使うと良い。
GitHub - iovisor/bcc: BCC - Tools for BPF-based Linux IO analysis, networking, monitoring, and more
これは、カーネルレベルの処理にCを、それをフックして動作するフロントエンドにPythonとLuaを用いてで作成することで、BPFプログラムをより簡単に書くことができる。 パフォーマンス分析やネットワークトラフィック制御など、多くのタスクに適用可能である。
bcc/BPFは、RHEL8 BetaにもTechnology previewsとして導入され、今後注目すべき技術であることは間違いない。
Chapter 6. Technology previews - Red Hat Customer Portal
さて、PostgreSQLには、BPFをはじめとした分析ツールで動的トレーシングを行う時に使えるカーネルトレースポイント(USDT probe)があらかじめいくつも定義されている。標準で提供されるモニタリングツール以上にいろいろ運用上役立つものが多そうである。
クエリごとにreadしたブロック数
といったメトリクスは、そのプローブのうちの1つを使えば採取することができる。
PostgreSQLが提供するプローブ
PostgreSQLは動的トレーシングで利用できるプローブを数多く提供しており、標準で組み込まれるプローブはドキュメントにある通りである。
PostgreSQL: Documentation: 11: 28.5. Dynamic Tracing
独自のプローブを定義することも可能であるが、デフォルトでも多くのActivityを捕捉できそう。
前提として、 PostgreSQL自体が --enable-dtrace
コンパイルオプション付きでビルドされている必要がある。(なお、今回のすべてのオペレーションは、DigitalOceanのUbuntu 18.10 x64 Droplet / PostgreSQL11.1で行った)
# cd /path/to/postgresql-source # ./configure --enable-dtrace # make && make install
ちなみに、MySQLは多くのディストリビューションで、デフォルトでUSDT probe有効化されてビルドされているらしい。
smgr-md-read-doneのコールバックで共有バッファ読込を観測するpython+c のコード
上記プローブのうち、今回は smgr-md-read-done
に着目する。ドキュメント的には、 ブロックの読み込み終了を捕捉するプローブ
と説明されている。
以下が、特定のバックエンドプロセスにアタッチし、ブロック読込を捕捉して対象ブロック情報を表示するスクリプト。
使い方は、 blk_read_pgsql -p <postgres_backend_PID>
という感じである。
bpf script for block read into shared_buffer · GitHub
CのパートとPythonのパートの中から中心的な部分をそれぞれ挙げると、
- Cの部分
いきなりインラインでCを書いているが、やりたいことは、 smgr-md-read-done
の結果として得られる値を構造体に詰めて BPF_PERF_OUTPUT()
でイベントとしてユーザスペースに渡している。このイベントの出力を受け付けるのがpythonパートとなる。
#include <uapi/linux/ptrace.h> struct data_t { u64 timestamp; int pid; int oid; int blkno; int requested_size; int act_size; }; BPF_PERF_OUTPUT(events); int query_blk_read(struct pt_regs *ctx) { struct data_t data = {}; data.timestamp = bpf_ktime_get_ns(); bpf_usdt_readarg(5, ctx, &data.oid); bpf_usdt_readarg(2, ctx, &data.blkno); bpf_usdt_readarg(8, ctx, &data.requested_size); bpf_usdt_readarg(7, ctx, &data.act_size); data.pid = bpf_get_current_pid_tgid(); events.perf_submit(ctx, &data, sizeof(data)); return 0; }
- Pythonの部分
smgr-md-read-done
に対して先ほどCパートで定義したquery_blk_read()
をコールバックとして登録している。Data
クラスはイベントとして得られた値を格納する各種フィールドを持つ。イベント発生ごとに print_event()
が実行される。
usdts = map(lambda pid: USDT(pid=pid), args.pids) for usdt in usdts: usdt.enable_probe("smgr__md__read__done", "query_blk_read") bpf = BPF(text=program, usdt_contexts=usdts) class Data(ct.Structure): _fields_ = [ ("timestamp", ct.c_ulonglong), ("pid", ct.c_int), ("oid", ct.c_int), ("blkno", ct.c_int), ("requested_size", ct.c_int), ("act_size", ct.c_int), ] start = BPF.monotonic_time() def print_event(cpu, data, size): event = ct.cast(data, ct.POINTER(Data)).contents print("%-14.6f %-6d %-6d %-6d %-6d %-6d" % ( float(event.timestamp - start) / 1000000000, event.pid, event.oid, event.blkno, event.requested_size, event.act_size)) print("%-14s %-6s %-6s %-6s %-6s %-6s" % ("TIME(s)", "PID", "OID", "BLKNO", "REQ", "ACT")) bpf["events"].open_perf_buffer(print_event, page_cnt=64) while True: bpf.perf_buffer_poll()
使用例
バックエンドプロセスをてきとうに選んでアタッチすると、以下のような状態で待機ループに入る。
# pgrep -al postgres ... 10834 postgres: postgres database [local] idle ... # ./blk_read_pgsql -p 10834 TIME(s) PID OID BLKNO REQ ACT
pid: 10834
からなにかクエリを発行すると、上記の待機中のコンソールに、読み込んだブロックが表示される。
たとえば以下のような結果が得られたなら、OID: 24643
のオブジェクトを最初のブロックから順に共有バッファに読み込んだことになる。きっと初めて触るテーブルをフルスキャンすればこのような結果になるはずである。
TIME(s) PID OID BLKNO REQ ACT 7.021272 10834 24643 0 8192 8192 7.022607 10834 24643 1 8192 8192 7.023180 10834 24643 2 8192 8192 7.023365 10834 24643 3 8192 8192 7.023579 10834 24643 4 8192 8192 7.023738 10834 24643 5 8192 8192 ...
pg_buffercache
というcontribに含まれるextensionを使うと共有バッファの内訳を確認することができ、上記のクエリ直後だと以下のように OID: 24643
のブロックがshare_buffersに実際にのっていることがわかる。
database=# select relfilenode, relblocknumber from pg_buffercache where relfilenode = 24643; relfilenode | relblocknumber -------------+---------------- 24643 | 0 24643 | 1 24643 | 2 24643 | 3 24643 | 4 24643 | 5 ...
このあと別のバックエンドプロセスを blk_read_pgsql
で観測しながら同一のクエリを流してもブロック読み込が確認できないのは、既に共有バッファに必要なブロックが存在するからであることがわかる。
ちなみに VACUUM FULL
のようなOIDが変わる処理を実施するとshare_buffersからもそのブロック情報が完全に消し去られ、やはりもう一度 blk_read_pgsql
で読み込みが行われることが観察できる。きっとpg_repackとかpg_reorgでも同じことが確認できると思う。
Wrap-up / bccを利用した可観測性ツールが熱い
bcc/BPFを用いて、PostgreSQLが提供するUSDTを捕捉して低レベルなメトリクスを取得した。bccではPythonによる記述が非常に強力なのでこれは使える。
RHEL8の話題というとbcc/BPFが熱いと個人的には思っている。今回のPostgreSQL動的トレーシングの例はBPFの無限の可能性のうちの1つであって、実際にBPFをベースにした活発なプロジェクトがいくつもあるようなので、要注目技術として追っていきたい。