データベースの運用管理にログの情報は不可欠ですが、オープンソースのDBMSであるPostgreSQLが出力するログは、直接取り扱うのに適した形式とは言えません。そこで本記事では、オープンソースのログ収集ツールであるFluentdを使って、PostgreSQLのログを運用管理に活用しやすい形に加工する方法を紹介します。
PostgreSQLの運用管理に使う稼働統計情報とログ
データベースを安定稼働させるには、データベースを健全な状態に保つ運用管理が必要不可欠です。データベースの運用管理には一般的に死活監視、リソース監視、性能分析、チューニング、バックアップといった項目が挙げられますが、まずは監視によって正しく現状を把握することが、運用管理の第一歩と言えるでしょう。PostgreSQLで監視に使える機能には、稼働統計情報とログがあります。稼働統計情報はPostgreSQLの様々な稼働情報を蓄積したもので、通常は専用のビューにSQL文で参照できます。稼働統計情報では、接続中のクライアントの実行状態や実行中のSQL文、データベース単位のコミット／ロールバック回数やSQLの実行回数、テーブル単位で更新されたレコード数といった情報を参照でき、性能分析やチューニングに活用できます（リスト1）。
リスト1：稼働統計情報からデータベースのキャッシュヒット率を取得
1 | # SELECT datname, round(blks_hit*100/(blks_hit+blks_read), 2) AS cache_hit_ratio |
2 | FROM pg_stat_database WHERE blks_read > 0 |
3 | datname | cache_hit_ratio |
4 | ---------+----------------- |
ログにはPostgreSQLサーバから出力された様々な情報が記録されます。例えば、サーバが即停止するような深刻なレベルからサーバの稼働に影響しない警告レベルまで何らかの事象が発生したことを示すメッセージや、処理されたSQL文、チェックポイント、自動VACUUMの実行状況、デッドロックの発生状況といった情報は全てログに出力させることが可能です。またPostgreSQLのログは、任意のファイルにテキスト形式で出力する以外に、syslogやWindowsのイベントログへの出力や、外部ツールで扱いやすいCSV形式での出力も可能です。
リスト2：PostgreSQLのログファイルの中身
1 | [2014-06-26 06:32:14 GMT][11550][53abb2b8.2d1e-21][0][00000](postgres, fluentd, [local], psql) LOG: duration: 20020.457 ms statement: select pg_sleep(20); |
2 | [2014-06-26 07:36:38 GMT][17077][53abcc5a.42b5-1][0][00000]LOG: checkpoint starting: time |
3 | [2014-06-26 07:36:39 GMT][17077][53abcc5a.42b5-2][0][00000]LOG: checkpoint complete: wrote 4 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.303 s, sync=0.004 s, total=0.320 s; sync files=3, longest=0.002 s, average=0.001 s |
ログにしか出力されない情報もあるため、運用管理にはログも活用したいところですが、PostgreSQLのログにはいくつか扱いづらい点があります。特にPostgreSQLは1つのファイルに全てのログを出力するため、エラーレベルや事象の種別で分割することができず、ログから必要な情報を探したり、分析に活用したりするのが困難です。そこで本記事では、オープンソースのログ収集ツールであるFluentdを使って、PostgreSQLのログを分析しやすい形に加工する方法を紹介していきます。
Fluentdの概要
Fluentdは軽量でプラガブルなログ収集ツールで、Apache License Version 2.0のもとOSSとして公開されており、自由に使うことができます。またFluentdは、ログ管理を3つの層（インプット、バッファ、アウトプット）に分けて管理しており、しかも各層がプラガブルなアーキテクチャになっています。そのため用途に応じたプラグインを追加するだけで、柔軟に機能拡張できるメリットがあります。Fluentdの詳細はドキュメントをご覧ください。
PostgreSQLのログを加工する
ここからはPostgreSQLのログをFluentdで収集し、分析しやすい形に加工する手順を解説します。図1はPostgreSQLサーバが出力したログをFluentdプロセスが収集・加工して、最終的にPostgreSQLデータベースのテーブルにログデータを格納するまでの処理の流れを図示したものです。なお、テキスト形式のログデータをデータベースのテーブルに格納するのは、使い慣れたSQLでログデータの抽出や分析を可能にすることを狙ったからです。
図1：処理の流れ（クリックで拡大）
なお、今回の環境で利用するソフトウェアは以下のとおりです。
| プロダクト名 | バージョン |
|---|
| CentOS | 6.4（64bit） |
| PostgreSQL | 9.3.5 |
| td-agent （Fluentd） | 1.1.20（0.10.50） |
| fluent-plugin-rewrite-tag-filter | 1.4.1 |
| fluent-plugin-parser | 0.3.4 |
| fluent-plugin-pgjson | 0.0.4 |
Fluentdのセットアップ
Fluentdはバイナリパッケージ、RubyGems、ソースパッケージからと様々なインストール方法があります。今回は「td-agent」という名称でTreasure Data, Inc.から提供されているRPMパッケージを利用します。
PostgreSQLのセットアップ
リスト4：PostgreSQLのインストールパッケージとデータベースへの接続確認
PostgreSQLはサーバ、クライアントモジュールがRPMパッケージですでにインストールされており、psqlコマンドでデータベースに接続できる状態を前提とします。
01 | # rpm -qa | grep postgres |
02 | postgresql93-contrib-9.3.5-1PGDG.rhel6.x86_64 |
03 | postgresql93-libs-9.3.5-1PGDG.rhel6.x86_64 |
04 | postgresql93-devel-9.3.5-1PGDG.rhel6.x86_64 |
05 | postgresql93-server-9.3.5-1PGDG.rhel6.x86_64 |
06 | postgresql93-9.3.5-1PGDG.rhel6.x86_64 |
PostgreSQLの設定ファイル（postgresql.conf）は以下のように編集します。今回はCSV形式のログを使用するため、log_destinationに「csvlog」を加えます。なお、ここではログに出せる情報を全て出力する設定にしていますが、ログの量が増大するとパフォーマンスに影響するため、実運用時は本当に必要なログのみ出力するようにしてください。
リスト5：postgresql.confの設定
01 | log_destination = 'stderr,csvlog' # CSV形式のログを出力 |
03 | log_directory = '/tmp' # ログを /tmp 配下に出力 |
04 | log_filename = 'postgresql.log' |
06 | log_line_prefix = '[%t][%p][%c-%l][%x][%e]%q (%u, %d, %r, %a)' |
07 | log_rotation_age = 0 # Fluentdからファイル名固定でアクセスするためローテーションを無効化 |
08 | log_rotation_size = 0 # Fluentdからファイル名固定でアクセスするためローテーションを無効化 |
09 | log_min_duration_statement = '1s' # 1秒以上かかったSQLをログに出力 |
10 | log_autovacuum_min_duration = 0 # 全ての自動VACUUMMのログを出力 |
11 | log_checkpoints = 'on' # チェックポイント処理をログに出力 |
12 | log_lock_waits = 'on' # ロック待ちのセッション情報をログに出力 |
13 | log_temp_files = 0 # 作成された全ての一時ファイルの情報をログに出力 |
上記の設定を適用したPostgreSQLサーバは、以下のような形式のCSVログ（postgresql.csv）を生成します。
リスト6：CSVログの中身
1 | 2014-06-26 07:19:23.292 GMT,,,14376,,53abc97b.3828,1,,2014-06-26 07:19:23 GMT,,0,LOG,00000,"database system is ready to accept connections",,,,,,,,,"" |
2 | 2014-06-26 07:19:23.293 GMT,,,14383,,53abc97b.382f,1,,2014-06-26 07:19:23 GMT,,0,LOG,00000,"autovacuum launcher started",,,,,,,,,"" |
3 | 2014-06-26 07:22:20.667 GMT,"postgres","fluentd",14782,"[local]",53abc9ff.39be,1,"SELECT",2014-06-26 07:21:35 GMT,3/0,0,LOG,00000,"duration: 30031.664 ms statement: select pg_sleep(30);",,,,,,,,,"psql" |
Fluentdのプラグインとデータの流れ
ここからは、Fluentdプロセスの中で行われる処理に着目します。今回はCSV形式のサーバログを入力とし、PostgreSQLデータベースへログデータを格納するまでに4つのプラグインを経由しており、それぞれ様々な処理を行っています。それぞれのプラグインの役割と設定方法について、以下に解説していきます。
図2：Fluentdプラグインとデータの流れ（クリックで拡大）
tail インプットプラグイン
ログファイルに書き込まれた情報を常時取り込んでいくインプットプラグインで、Fluentdに標準で組み込まれています。このプラグインを使ってPostgreSQLのCSVログをパースし、後続の処理に渡すJSONデータを生成します。Fluentdの設定ファイルに記載するこのプラグイン用の設定は、以下のようになります。なお、この記事ではFluentdをRPMパッケージでインストールしており、デフォルトで読み込まれる設定ファイルは「/etc/td-agent/td-agent.conf」になります。プラグインの設定は、このファイルに追記していくことにします。
リスト7：tailプラグインの設定（td-agent.confに追記）
3 | path /tmp/postgresql.csv |
4 | pos_file /var/log/td-agent/postgresql.log.pos |
7 | format_firstline /^\d{4}-\d{2}-\d{2}/ |
8 | format1 /^(?<time>[^",]*),"?(?<user_name>(?:[^",]|"")*)"?,"?(?<database_name>(?:[^",]|"")*)"?,(?<process_id>[^",]*),"?(?<connection_from>(?:[^",]|"")*)"?,(?<session_id>[^",]*),(?<session_line_num>[^",]*),"?(?<command_tag>(?:[^",]|"")*)"?,(?<session_start_time>[^",]*),(?<virtual_transaction_id>[^",]*),(?<transaction_id>[^",]*),(?<error_severity>[^",]*),(?<sql_state_code>[^",]*),"?(?<message>(?:[^"]|"")*)"?,(?<detail>[^",]*),"?(?<hint>(?:[^",]|"")*)"?,(?<internal_query>[^",]*),(?<internal_query_pos>[^",]*),(?<context>[^",]*),"?(?<query>(?:[^"]|"")*)"?,(?<query_pos>[^",]*),(?<location>[^",]*),"?(?<application_name>(?:[^",]|"")*)"?$/ |
PostgreSQLのログは、1件の情報内に改行が含まれる可能性があるため、「format」は複数行に対応可能な「multiline」に設定し、ログを区切る文字列を「format_firstline」に指定します。また、「format1」の部分にCSVデータのカラムをパースしてJSONデータに変換するルールを正規表現で定義し、PostgreSQLのログデータであることを区別するため「postgresql」という名前のタグを付けることにします。
上記の設定により、PostgreSQLのCSVログは以下のようなJSONデータに変換されます。
リスト8：変換されたJSONデータ
3 | "time": "2014-06-30 01:12:02+00", |
4 | {"user_name":"","database_name":"","process_id":"27136","connection_from":"","session_id":"53b0b980.6a00", |
5 | "session_line_num":"10","command_tag":"","session_start_time":"2014-06-30 01:12:32 GMT", |
6 | "virtual_transaction_id":"","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000", |
7 | "message":"checkpoint starting: xlog","detail":"","hint":"","internal_query":"","internal_query_pos":"","context":"", |
8 | "query":"","query_pos":"","location":"","application_name":""} |
fluent-plugin-rewrite-tag-filter
データの内容によって、タグを書き換えるバッファプラグインです。このプラグインを使い、ログの内容に応じてタグを分別してみます。このプラグインは以下のようにインストールできます。
リスト9：fluent-plugin-rewrite-tag-filterプラグインのインストール
1 | $ sudo /usr/lib64/fluent/ruby/bin/fluent-gem install fluent-plugin-rewrite-tag-filter |
このプラグインの設定は以下のようになります。「rewriterule1～9」の部分に定義された正規表現にログメッセージがマッチしたら、対応するタグに置き換えられます。例えば、スロークエリのログなら「raw.postgresql.slow_query」、一時ファイル出力のログなら「postgresql.tempfiles」という名前のタグが付けられます。
リスト10：fluent-plugin-rewrite-tag-filterプラグインの設定（td-agent.confに追記）
02 | type rewrite_tag_filter |
03 | rewriterule1 message ^duration: raw.postgresql.slow_query |
04 | rewriterule2 message ^checkpoints\sare\soccurring\stoo\sfrequently postgresql.checkpoints.frequently |
05 | rewriterule3 message ^checkpoint\sstarting: postgresql.checkpoint.start |
06 | rewriterule4 message ^checkpoint\scomplete: postgresql.checkpoint.complete |
07 | rewriterule5 message ^automatic postgresql.vacuum |
08 | rewriterule6 message ^temporary file: postgresql.tempfiles |
09 | rewriterule7 message ^process.*detected\sdeadlock postgresql.deadlock |
10 | rewriterule8 message ^process.*(still waiting|acquired) postgresql.lockwait |
11 | rewriterule9 message .* postgresql.others |
fluent-plugin-parser
Fluentd上に流れるデータの任意のフィールドを、さらに分解するバッファプラグインです。このプラグインを使ってスロークエリログの処理時間、SQL文のデータを分解し、後から分析しやすくなるよう別の要素としてJSONに付与します。このプラグインも以下のようにインストールできます。
リスト11：fluent-plugin-parserプラグインのインストール
1 | $ sudo /usr/lib64/fluent/ruby/bin/fluent-gem install fluent-plugin-parser |
このプラグインの設定は以下のようになります。「format」の部分にキー「message」のデータを変換するルールを正規表現で定義しています。
リスト12：fluent-plugin-parserプラグインの設定（td-agent.confに追記）
1 | <match raw.postgresql.slow_query> |
6 | format /^duration: (?<duration>[0-9\.]+) ms statement: (?<statement>.+)$/ |
この設定により、リスト13のスロークエリログは「duration」「statement」というキーが追加されて、リスト14のような形に変換されます。
リスト13：変換前のスロークエリログ
2 | "tag": "raw.postgresql.slow_query", |
3 | "time": "2014-06-30 01:12:02+00", |
4 | “user_name”:“postgres”,“database_name”:“fluentd”, …, |
5 | “message”:“duration: 4004.423 ms statement: select pg_sleep(4);”, … ,"application_name":"psql"} |
リスト14：変換後のスロークエリログ
2 | "tag": "postgresql.slow_query", |
3 | "time": "2014-06-30 01:12:02+00", |
4 | “user_name”:“postgres”,“database_name”:“fluentd”, …, |
5 | “message”:“duration: 4004.423 ms statement: select pg_sleep(4);”, … ,"application_name":"psql", |
7 | "statement":"select pg_sleep(4);"} |
fluent-plugin-pgjson
ログデータをPostgreSQLのテーブルに出力するアウトプットプラグインです。このプラグインは、出力先にPostgreSQLのJSON型カラムを利用します。このプラグインのインストール方法も、他のものと同様です。
リスト15：fluent-plugin-pgjsonプラグインのインストール
1 | $ sudo /usr/lib64/fluent/ruby/bin/fluent-gem install fluent-plugin-pgjson |
このプラグインを使って、Fluentdで加工したJSON形式のログデータをPostgreSQLデータベース内のテーブルに挿入してみます。まず、ログデータを格納するテーブルをあらかじめ任意のデータベースに作成しておきます。
リスト16：ログデータ格納テーブルの作成
1 | # CREATE DATABASE fluentd; # fluentdという名のデータベースを作成 |
2 | # \c fluentd # ターゲットデータベースをfluentdに変更 |
3 | # CREATE TABLE fluentd ( # fluentdという名のテーブルを作成 |
4 | tag Text, time Timestamptz, record Json |
このプラグインの設定は以下のようになります。データを格納するPostgreSQLサーバのホスト名、ポート番号、データベース名、テーブル名といった、PostgreSQLデータベースに接続するために必要な情報を定義しています。
リスト17：fluent-plugin-pgjsonプラグインの設定（td-agent.confに追記）
01 | <match {postgresql.**}> |
ここまでの設定が終わったら、Fluentdのプロセスを起動します。今回はRPMパッケージでインストールしているので、以下のようにserviceコマンドで起動します。
リスト18：Fluentdプロセスの起動
1 | $ sudo service td-agent start |
起動してしばらくすると、ログデータ格納テーブルにログデータのレコードが蓄積されていきます。
収集したログをSQLで検索する
PostgreSQLにはJSONデータを操作する演算子が用意されており、JSON型のカラムに格納されたデータの任意のフィールドへSQLでアクセスすることが可能となります。各種のログデータを検索する例を以下に示します。
例: メッセージ深刻度レベルがERRORのメッセージを検索
全てのログメッセージには、重要度を表すメッセージ深刻度レベルが付与されています。これはFluentdテーブルにおけるrecordカラム内のJSONデータに「error_severity」というオブジェクトフィールドで格納されており、以下のSQLでメッセージ深刻度レベルが「ERROR」のものに絞り込んで参照することができます。また、WHERE句に「time」カラムの条件を加えることで、確認したい時間帯を絞り込むことも可能です。
01 | # SELECT time, record->>'user_name' as user, record->>'database_name' as database, |
02 | record->>'error_severity' as severity, record->>'message' as message, record->>'query' as query, |
03 | record->>'query_pos' as pos |
04 | FROM fluentd WHERE record->>'error_severity‘ = 'ERROR'; |
05 | -[ RECORD 1 ]-------------------------------------------------------------------------------------- |
06 | time | 2014-06-30 09:49:12+00 |
10 | message | column ""datname"" does not exist |
11 | query | select count(*) from fluentd where tag = 'postgresql.slow_query' and datname = 'postgres' |
例: スロークエリを検索（時間が長い10件）
スロークエリログと呼ばれる一定時間（今回の設定では1秒）以上かかったSQLの情報は、遅いSQLをチューニングするために必要な情報です。この情報は「postgresql.slow_query」というタグが付与されてtagカラムに格納されますので、WHERE句にタグを絞り込む条件を付与することでスロークエリの情報のみを参照できます。また、fluent-plugin-parserで「duration」「statement」というオブジェクトフィールドを追加しているため、以下のようにORDER BY句で時間順に並び替えることも可能です。
01 | # SELECT time, record->>'user_name' as user, record->>'database_name' as db, |
02 | record->>'duration' as duration, record->>'statement' as statement |
03 | FROM fluentd WHERE tag = 'postgresql.slow_query‘ |
04 | ORDER BY (record->>'duration')::numeric desc LIMIT 10; |
05 | time | user | db | duration | statement |
06 | ------------------------+------------+-----------+------------+----------------------- |
07 | 2014-07-01 07:32:03+00 | postgres | fluentd | 10011.009 | SELECT pg_sleep(10); |
08 | 2014-07-01 07:34:36+00 | postgres | fluentd | 10010.756 | SELECT pg_sleep(10); |
09 | 2014-07-01 07:32:40+00 | postgres | fluentd | 10010.394 | SELECT pg_sleep(10); |
10 | 2014-07-01 07:37:26+00 | postgres | fluentd | 10010.393 | SELECT pg_sleep(10); |
11 | 2014-07-01 07:32:27+00 | postgres | fluentd | 10010.384 | SELECT pg_sleep(10); |
12 | 2014-07-01 07:34:04+00 | postgres | fluentd | 10010.358 | SELECT pg_sleep(10); |
13 | 2014-07-01 07:34:21+00 | postgres | fluentd | 10010.342 | SELECT pg_sleep(10); |
14 | 2014-07-01 07:36:09+00 | postgres | fluentd | 10010.327 | SELECT pg_sleep(10); |
15 | 2014-07-01 07:36:27+00 | postgres | fluentd | 10010.279 | SELECT pg_sleep(10); |
16 | 2014-07-01 07:37:12+00 | postgres | fluentd | 10010.259 | SELECT pg_sleep(10); |
例: チェックポイントの実行状況
定期的に実行されるチェックポイントはデータベース負荷を高める原因になることがあるため、実行状況を把握しておくことが好ましいでしょう。この情報は「postgresql.checkpoint」というタグが付与されてtagカラムに格納されますので、WHERE句にタグを絞り込む条件を付与することで参照できます。
01 | # SELECT time, record->>‘message’ as message FROM fluentd WHERE tag like 'postgresql.checkpoint.%'; |
03 | -------------------------+------------------------------------------------------------------------- |
04 | 2014-06-30 01:17:32+00 | checkpoint starting: time |
05 | 2014-06-30 01:17:33+00 | checkpoint complete: wrote 5 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.403 s, sync=0.463 s, total=0.885 s; sync files=3, longest=0.460 s, average=0.154 s |
06 | 2014-06-30 01:27:32+00 | checkpoint starting: time |
07 | 2014-06-30 01:27:32+00 | checkpoint complete: wrote 1 buffers (0.0%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.000 s, sync=0.002 s, total=0.022 s; sync files=1, longest=0.002 s, average=0.002 s |
08 | 2014-06-30 01:30:13+00 | checkpoint starting: xlog |
09 | 2014-06-30 01:30:16+00 | checkpoint complete: wrote 1006 buffers (6.1%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=2.019 s, sync=0.272 s, total=2.396 s; sync files=19, longest=0.161 s, average=0.014 s |
10 | 2014-06-30 01:30:21+00 | checkpoint starting: xlog |
11 | 2014-06-30 01:30:24+00 | checkpoint complete: wrote 1894 buffers (11.6%); 0 transaction log file(s) added, 0 removed, 1 recycled; write=2.223 s, sync=0.209 s, total=2.518 s; sync files=9, longest=0.148 s, average=0.023 s |
例: デッドロックの発生情報
PostgreSQLにはデッドロックを自動的に検出して解決する機能がありますが、デッドロックが頻発するのは好ましい状況とはいえませんので、発生状況を把握して対策を講じるべきでしょう。この情報は「postgresql.deadlock」というタグが付与されてtagカラムに格納されますので、WHERE句にタグを絞り込む条件を付与することで参照できます。
1 | # SELECT time, record->>'database_name' as db, record->>'command_tag' as command, |
2 | record->>'message' as message, record->>'query' as query |
3 | FROM fluentd WHERE tag = 'postgresql.deadlock'; |
4 | -[ RECORD 1 ]-------------------------------------------------------------------------------------- |
5 | time | 2014-07-02 09:45:02+00 |
7 | command | LOCK TABLE waiting |
8 | message | process 8184 detected deadlock while waiting for ExclusiveLock on relation 16394 of database 16384 after 1000.235 ms |
9 | query | LOCK TABLE pgbench_history IN EXCLUSIVE MODE; |
PostgreSQLにJSON形式のログを格納する意義
JSON型は、PostgreSQLに標準で用意されているデータ型です。PostgreSQLのバージョンアップに伴いJSONサポートの機能が強化されており、PostgreSQLでJSONを扱いやすくする土壌が整いつつあります。一般的にログのようなデータは非定型な場合が多く、スキーマを一律に定義することが難しいため、ログをデータベースに格納する場合はスキーマ定義が不要なMongoDBを使うケースが多かったのではないでしょうか。ログデータをPostgreSQLに格納できれば、非定型なログを使い慣れたSQLで検索、分析できるようになります。また、元々PostgreSQLで管理しているマスターデータとのJOINなど、便利な使い方も可能になりそうです。
最後に
本記事ではPostgreSQLのログをFluentdで収集し、後から分析しやすい形に加工する方法を紹介しました。実際に運用管理を行う上でPostgreSQLの標準機能では少々物足りないログ機能も、他のツールと組み合わせることで運用を効率化できるという１つのヒントになればと考えています。
＜編集部より＞ Fluentdの綴りについて、正式には"F"が大文字だったため修正しました。（2014.10.3）
