PostgreSQLの運用管理にログの情報は不可欠ですが、PostgreSQLが出力するログは直接取り扱うのに適した形式とは言えません。ここではFluentdを使って運用管理に活用しやすい形にPostgreSQLのログを加工する方法を紹介します。
PostgreSQLの運用管理とログ
データベースの運用管理には
- 死活監視、リソース監視
- 性能分析、チューニング
- バックアップ、リストア
といったものが考えられますが、現状を把握しなければ何も対策できないので、まずは必要な監視を正しく行うことが重要です。PostgreSQLで監視に使える機能には稼働統計情報とログがありますが、今回はログに注目してみます。
PostgreSQLのログからわかること
PostgreSQLが出力するログからは以下の様なことがわかります。
- 何らかの異常(エラー)が発生したこと
- 処理されたSQL
- チェックポイント、自動VACUUMの実行
- デッドロックの発生 等々
PostgreSQLのログには、深刻なもの(PANIC,FATAL)から特に影響ないもの(INFO)まで様々なレベルのエラー情報が出力されます。また、処理されたSQLの情報については、一定時間を超過したSQL(スロークエリ)のみを出力することも、監査目的で全てのSQLを出力することも可能です。
PostgreSQLのログで不便なこと
PostgreSQLのログで不便だと感じるのは以下の様な点です。
- 古くなったログを自動削除する機能がない
- 障害メッセージ出現時に警告できない
- レベルやカテゴリ別にログを分別できない
古いログの自動削除機能がない点は、logrotateやcronといったツールを組合せればある程度解消できますし、障害メッセージ出現時に警告できない点は、別途監視ツールを使うことで通常は解消できます。
一方、ログを分別する機能がない点については少々厄介です。前述のようにPostgreSQLのログには様々な種類の情報が出力されますが、エラーレベルやカテゴリで分けたりできず、なんでも1つのログファイルに吐き出すため、後で分析しようと思ってもログから必要な情報のみを探し出すのが面倒です。
正直、PostgreSQLサーバが起動できないような深刻なエラーメッセージと、後でゆっくり分析すればよいスロークエリログを同じファイルにしないで欲しいのですが、PostgreSQLの標準機能ではどうすることもできません。
ただ、PostgreSQLのログに出力される情報の中には性能分析/チューニングに活かせる以下の情報も含まれますので、なんとかログを分析しやすい形に加工したいところです。
- スロークエリのSQL文字列、処理時間
- チェックポイントの実行時間
- デッドロックの発生状況
- ロック待ちで長時間かかったプロセス情報
PostgreSQLのログをFluentdで収集する
そこで、PostgreSQLのログを収集し、分析しやすい形に加工するツールとしてFluentdを使ってみます。
Fluentdは軽量でプラガブルなログ収集ツールで、Apache License Version 2.0のもとOSS公開されているため、自由に使うことができます。また、Fluentdはログ管理を3つの層(インプット、バッファ、アウトプット)に分けて管理し、各層がプラガブルなアーキテクチャになっているため、用途に応じたプラグインを追加するだけで柔軟に機能拡張できるメリットがあります。Fluentdの詳細は (こちらの記事) に詳しく解説されています。
目指す形
今回は下図の様に、FluentdがPostgreSQLのサーバログを読み込み、分析しやすい形に変換した後、同じPostgreSQLデータベース内に用意したテーブルにログデータを格納するという構成を考えてみました。テキスト形式のログをデータベースのデータとして格納しているのは、使い慣れたSQLで様々な条件を設定してデータの抽出や分析を可能にすることを狙ってのことです。
PostgreSQLの設定
今回はpostgresql.confのログ設定を以下の様に変更しました。
ここではログに出せる情報を全て出力するよう意図的に設定していますが、ログの量が増大するため実運用時は本当に見たいログのみを出力する設定に変更してください。
log_destination = 'stderr,csvlog' # CSV形式のログを出力 logging_collector = on log_directory = '/tmp' log_filename = 'postgresql.log' log_file_mode = '0644' log_line_prefix = '[%t][%p][%c-%l][%x][%e]%q (%u, %d, %r, %a)' log_rotation_age = 0 # Fluentdからファイル名固定でアクセスするためローテーションを無効化 log_rotation_size = 0 # Fluentdからファイル名固定でアクセスするためローテーションを無効化 log_min_duration_statement = '1s' # 1秒以上かかったSQLをログに出力 log_autovacuum_min_duration = 0 # 全ての自動VACUUMMのログを出力 log_checkpoints = 'on' # チェックポイント処理をログに出力 log_lock_waits = 'on' # ロック待ちのセッション情報をログに出力 log_temp_files = 0 # 作成された全ての一時ファイルの情報をログに出力
上記の設定を適用したPostgreSQLサーバは以下の様な形式のCSVログ(postgresql.csv)を生成します。
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",,,,,,,,,"" 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",,,,,,,,,"" 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サーバログを入力とし、PostgreSQLデータベースへログデータを格納するまでに4つのFluentdプラグインを経由しており、それぞれ様々な処理を行っています。
それぞれのプラグインの役割を以下に解説していきます。
fluent-plugin-tail-multiline
ログファイルに書き込まれた情報を常時取り込んでいくインプットプラグインです。このプラグインを使ってPostgreSQLのCSVログをパースし、後続の処理に渡すJSONデータを生成します。Fluentdに組み込まれている標準プラグイン「in_tail」と同様の機能を持ちますが、1件の情報が複数行にわたるログに対応する点が異なります。PostgreSQLのCSVログは1件の情報内に改行が含まれる可能性があるため、こちらを使用することにします。
Fluentdの設定ファイルに定義するこのプラグイン用の設定は以下の様になります。「format」の部分にCSVデータのカラムをパースしてJSONデータに変換するルールが正規表現で定義されています。また、PostgreSQLのログデータであることを区別するため、「postgresql」という名前のタグを付けることにします。
<source>
type tail_multiline
time_format %Y-%m-%d %H:%M:%S.%L %Z
path /tmp/postgresql.csv
tag postgresql
pos_file /var/log/td-agent/postgresql.log.pos
format_firstline /^\d{4}-\d{2}-\d{2}/
format /^(?<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>(?:[^",]|"")*)"?$/
</source>
上記の設定により、PostgreSQLのCSVログは以下の様なJSONデータに変換されました。
{
"tag": "postgresql",
"time": "2014-06-30 01:12:02+00",
{"user_name":"","database_name":"","process_id":"27136","connection_from":"","session_id":"53b0b980.6a00",
"session_line_num":"10","command_tag":"","session_start_time":"2014-06-30 01:12:32 GMT",
"virtual_transaction_id":"","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000",
"message":"checkpoint starting: xlog","detail":"","hint":"","internal_query":"","internal_query_pos":"","context":"",
"query":"","query_pos":"","location":"","application_name":""}
}
fluent-plugin-rewrite-tag-filter
データ内容を条件に任意のタグに書き換えるプラグインです。このプラグインを使ってログの内容に応じてタグを分別してみます。
Fluentdの設定ファイルに定義するこのプラグイン用の設定は以下の様になります。「rewriterule1～9」の部分に定義された正規表現にログメッセージがマッチしたら対応するタグにそれぞれ置き換えられます。例えば、スロークエリのログなら「raw.postgresql.slow_query」、一時ファイル出力のログなら「postgresql.tempfiles」という名前のタグが付けられます。
<match postgresql> type rewrite_tag_filter rewriterule1 message ^duration: raw.postgresql.slow_query rewriterule2 message ^checkpoints\sare\soccurring\stoo\sfrequently postgresql.checkpoints.frequently rewriterule3 message ^checkpoint\sstarting: postgresql.checkpoint.start rewriterule4 message ^checkpoint\scomplete: postgresql.checkpoint.complete rewriterule5 message ^automatic postgresql.vacuum rewriterule6 message ^temporary file: postgresql.tempfiles rewriterule7 message ^process.*detected\sdeadlock postgresql.deadlock rewriterule8 message ^process.*(still waiting|acquired) postgresql.lockwait rewriterule9 message .* postgresql.others </match>
fluent-plugin-parser
Fluentd上に流れるデータの任意のフィールドをさらに分解するプラグインです。このプラグインを使ってスロークエリログの処理時間、SQL文のデータを分解し、後から分析しやすくなるよう別の要素としてJSONに付与してみます。
Fluentdの設定ファイルに定義するこのプラグイン用の設定は以下の様になります。「format」の部分にキー「message」の値を変換するルールが正規表現で定義されています。
<match raw.postgresql.slow_query> type parser remove_prefix raw reserve_data yes key_name message format /^duration: (?<duration>[0-9\.]+) ms statement: (?<statement>.+)$/ </match>
この設定により、次のスロークエリログは、
{
"tag": "raw.postgresql.slow_query",
"time": "2014-06-30 01:12:02+00",
"user_name":"postgres","database_name":"fluentd", ...,
"message":"duration: 4004.423 ms statement: select pg_sleep(4);", ... ,"application_name":"psql"}
}
次の様な形に変換されました。(duration,statementというキーが追加されています)
{
"tag": "postgresql.slow_query",
"time": "2014-06-30 01:12:02+00",
"user_name":"postgres","database_name":"fluentd", ...,
"message":"duration: 4004.423 ms statement: select pg_sleep(4);", ... ,"application_name":"psql",
"duration":"4004.423",
"statement":"select pg_sleep(4);"}
}
fluent-plugin-pgjson
ログデータをPostgreSQLのテーブルに出力するアウトプットプラグインです。このプラグインは出力先にPostgreSQLのJSON型カラムを利用します。このプラグインを使いFluentdで扱ったJSON形式のログデータをPostgreSQLデータベース内のテーブルに挿入してみます。
Fluentdの設定ファイルに定義するこのプラグイン用の設定は以下の様になります。データを格納するPostgreSQLサーバのホスト名、ポート番号、データベース名、テーブル名といった、PostgreSQLデータベースに接続するために必要な一般的な情報を定義しています。
<match {postgresql.**}>
type pgjson
host localhost
port 5432
sslmode prefer
database fluentd
table fluentd
user postgres
password postgres
time_col time
tag_col tag
record_col record
</match>
また、ログデータの格納先として以下のテーブルをあらかじめ作成しておきました。
CREATE TABLE fluentd (
tag Text,
time Timestamptz,
record Json
);
収集したログをSQLで検索する
PostgreSQLのテーブルに格納されたログデータは使い慣れたSQLで検索することが可能となります。便利ですよね。
例: 深刻度がERRORのメッセージを検索
# SELECT time, record->>'user_name' as user, record->>'database_name' as database,
record->>'error_severity' as severity, record->>'message' as message,
record->>'query' as query, record->>'query_pos' as pos
FROM fluentd
WHERE record->>'error_severity' = 'ERROR';
-[ RECORD 1 ]---------------------------------------------------------------------------------------------
time | 2014-06-30 09:49:12+00
user | postgres
database | fluentd
severity | ERROR
message | column ""datname"" does not exist
query | select count(*) from fluentd where tag = 'postgresql.slow_query' and datname = 'postgres'
pos | 70
例: スロークエリを検索（時間が長い10件）
# SELECT time, record->>'user_name' as user, record->>'database_name' as db,
record->>'duration' as duration, record->>'statement' as statement
FROM fluentd
WHERE tag = 'postgresql.slow_query'
ORDER BY (record->>'duration')::numeric desc LIMIT 10;
time | user | db | duration | statement
------------------------+------------+-----------+------------+-----------------------
2014-07-01 07:32:03+00 | postgres | fluentd | 10011.009 | SELECT pg_sleep(10);
2014-07-01 07:34:36+00 | postgres | fluentd | 10010.756 | SELECT pg_sleep(10);
2014-07-01 07:32:40+00 | postgres | fluentd | 10010.394 | SELECT pg_sleep(10);
2014-07-01 07:37:26+00 | postgres | fluentd | 10010.393 | SELECT pg_sleep(10);
2014-07-01 07:32:27+00 | postgres | fluentd | 10010.384 | SELECT pg_sleep(10);
2014-07-01 07:34:04+00 | postgres | fluentd | 10010.358 | SELECT pg_sleep(10);
2014-07-01 07:34:21+00 | postgres | fluentd | 10010.342 | SELECT pg_sleep(10);
2014-07-01 07:36:09+00 | postgres | fluentd | 10010.327 | SELECT pg_sleep(10);
2014-07-01 07:36:27+00 | postgres | fluentd | 10010.279 | SELECT pg_sleep(10);
2014-07-01 07:37:12+00 | postgres | fluentd | 10010.259 | SELECT pg_sleep(10);
PostgreSQLにJSON形式のログを格納する意義
JSON型はPostgreSQLに標準で用意されているデータ型で、バージョン9.3からはJSONサポートが強化されており、PostgreSQLでJSONを扱いやすくする土壌が整いつつあります。PostgreSQLのログはCSV形式で出力できるので、PostgreSQLのみを考えればCSVフォーマットに合わせて定義したテーブルにログデータを格納できます。ただ、PostgreSQL以外のログも合わせて格納しようと考えた場合、スキーマを一律に定義するのは難しく、スキーマ定義が不要なMongoDBを使うというケースが多くなるのではないでしょうか？
ログデータをPostgreSQLのJSON型カラムに格納することで、フォーマットが非定型なログを使い慣れたSQLで検索、分析できるようになるのは大きなメリットだと感じています。
最後に
今回はPostgreSQLのログをFluentdで収集して後から分析しやすい形に加工する方法を紹介しました。PostgreSQLの標準機能では少々物足りないログ機能も、他のツールを組み合わせることで運用を効率化できるという1つのヒントになればと考えています。皆さんはFluentdをどのように活用しますか？