ujunのブログ

BPFを用いてPostgreSQL共有バッファ読込を動的トレーシング

この記事は、 Sansan Advent Calendar 2018 - Adventar 22日目のエントリです。

目次

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;
}

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をベースにした活発なプロジェクトがいくつもあるようなので、要注目技術として追っていきたい。

参考資料