PostgreSQLのバックトレースレポート機能

これは、PostgreSQL Advent Calendar 2019の20日目の記事です。

この記事で紹介する機能はPostgreSQL13で実装される予定の新機能です。
2019年11月にコミットされた機能となるため、試す場合はそれ以降のHEADを使用してみてください。(ちなみにまだPostgreSQL13のFeature Freezeはされていないので、この機能はRevertされる可能性があります。)

この機能ができた経緯

PostgreSQL(に限った話ではありませんが・・)では、ごく稀にSegmentation Faultによるクラッシュや長時間の意図しないハング状態を起こすことがあります。このような場合gdbなどのデバッガを使い、出力されたcoreファイルの解析を行ったり稼働中のプロセスにattachしてどこでハングしているかの解析を行うなどして原因を探ることが多いです。

しかし、coreを出力しない設定になっている(coreファイルが巨大になるのであえて出力させないこともあるでしょう)、再現性が低い、商用環境でTry&Errorでの解析が容易にはできない、などの状況が結構あります。

PostgreSQLコミュニティでも、トレースの取得方法をwikiにまとめるなどして、バグレポートの一助を図っています。しかし再現性の低いクリティカルなバグの証跡取得は難しいことが多く、少しでもそれを容易にするためいくつか改善が議論されており、その一つがこのバックトレースレポートの機能です。

機能の説明

この機能は以下2つのタイミングでPostgreSQLのサーバログにバックトレースを出力します。

• --enable-cassertを有効にしてビルドしたPostgreSQLにてAssert()にかかった場合
• backtrace_functionsパラメータに指定した関数内でelog()もしくはereport()が呼ばれた場合
  • elog()/ereport()はPostgreSQLのログ出力用のユーティリティ関数
  • 関数の指定はカンマ区切りで複数を指定可能

バックトレース情報の収集はglibcの仕組みを利用しています。具体的にはexecinfo.hのbacktrace()やbacktrace_symbols_fd()を利用し、上記のタイミングでバックトレース情報を出力しています。
backtrace_functionsパラメータで指定された関数はbacktrace_symbol_listという変数で保持します。そしてelog()/ereport()の処理時に呼び出し元の関数と変数内の関数リストを照合してマッチすればバックトレースも出力するようになっています。backtrace_functionsパラメータを変更するためにはPostgreSQLの再起動は不要で、reloadで済みます。スーパーユーザであればSETで動的に変更が可能です。また実在しない関数名も登録できるので、PostgreSQL起動後に動的にLOADされる拡張機能(Extension)内の関数の指定も可能です。注意点としては、elog()/ereport()の処理はERRORだけでなくLOGやNOTICEなどの正常処理でも呼ばれるため、指定する関数によってはバックトレースの出力量が増え、ログサイズが極端に肥大化する可能性があります。

またオプションとしてerrbacktrace()という関数も開発者向けに実装されています。この関数をereport()で呼ぶことにより、通常のエラーメッセージに加えてバックトレースも出力できるようになっています。これはPostgreSQLのコア開発や拡張機能開発の際のデバッグなどに役立つでしょう。

機能を使うための前提

前述のとおりglibcの仕組みに頼るため、一部のプラットホーム(Windowsなど)ではこの機能は使えません。
それ以外には特に必要なものはありません。--enable-debugなどのconfigureオプションも不要です。

backtrace_functionsパラメータを試してみる

簡単なエラーで実際の挙動を見てみましょう。まずエラーを発生させ、その発生箇所を特定します。

postgres=# select err;
ERROR:  column "err" does not exist
LINE 1: select err;
               ^
postgres=# \errverbose
ERROR:  42703: column "err" does not exist
LINE 1: select err;
               ^
LOCATION:  errorMissingColumn, parse_relation.c:3353

parse_relation.c:3353で当該のエラーが出力されています。src/backend/parser/parse_relation.cの3353行目はerrorMissingColumnという関数内にあたります。ではこの関数をbacktrace_functionsにセットし、有効化します。このパラメータはreloadで有効化されます。

postgres=# ALTER SYSTEM SET backtrace_functions = 'errorMissingColumn';
ALTER SYSTEM
postgres=# select pg_reload_conf();
 pg_reload_conf 
----------------
 t
(1 row)

postgres=# show backtrace_functions ;
 backtrace_functions 
---------------------
 errorMissingColumn
(1 row)

ちなみに、ALTER SYSTEMを使って設定変更をしていますが、postgresql.confにbacktrace_functions = 'errorMissingColumn'を追記してpg_ctl reloadを実行する方法でも構いません。
では、再度同じエラーを発生させてみます。すると、ログに以下のようなメッセージが出力されました。

ERROR:  column "err" does not exist at character 8
BACKTRACE:
        2   postgres                            0x000000010df9dcbd errorMissingColumn.cold.1 + 221
        3   postgres                            0x000000010dc4d26f errorMissingColumn + 463
        4   postgres                            0x000000010dc438df transformExprRecurse + 10735
        5   postgres                            0x000000010dc40ee6 transformExpr + 22
        6   postgres                            0x000000010dc4d606 transformTargetList + 230
        7   postgres                            0x000000010dc1e88f transformStmt + 4847
        8   postgres                            0x000000010dc1d332 parse_analyze + 194
        9   postgres                            0x000000010de172a8 exec_simple_query + 1336
        10  postgres                            0x000000010de1516f PostgresMain + 3471
        11  postgres                            0x000000010dda252b BackendRun + 427
        12  postgres                            0x000000010dda1c98 ServerLoop + 2968
        13  postgres                            0x000000010dd9ed31 PostmasterMain + 3569
        14  postgres                            0x000000010dd101a0 help + 0
        15  libdyld.dylib                       0x00007fff6b4113d5 start + 1
STATEMENT:  select err;

上記はMacOS(Mojave)での実行結果です。PostmasterMain()からerrorMissingColumn()`に至るまでの流れが分かります。おそらく他の環境(Linuxなど)では少々異なった出力がされるかもしれませんが、内容的にはほぼ同じだと思います。

この機能の使い所

正直なところ、この機能を活用するのは難しい・・と思いました。例で示したとおり、ログからバックトレースは分かりますが、異常の原因となりそうなおかしな値を持った変数などは分かりません。そのため、デバッグしやすい環境であればgdbなどのデバッグツールやelog()/ereport()によるデバッグログ出力、perfなどに頼る方が効率的でしょう。

商用環境の場合には--enable-cassertはCPUリソースを消費しやすいため無効にしますし、そもそもbacktrace_functionsに予め登録する関数を決められるケースは少ないです。おそらくユースケースとしては独自開発した拡張機能や独自パッチ内の関数をbacktrace_functionsに登録し、そのPostgreSQLの商用やステージング環境での運用での想定外のエラーに備えるような使い方がメインになると思います。あるいは、想定外のPostgreSQLのエラーがたまに発生する場合に、その発生フローや条件を捕捉するために使う、などでしょうか。

終わりに

PostgreSQLの新機能であるバックトレースレポートの機能について解説しました。まだ将来に向けた試作的な機能に近い(と思われる)ためユースケースは限られますが、意外な使い道がありそうで、面白いと思います。