PostgreSQLのログをFluentdで収集する
fluent-plugin-pgjson
ログデータをPostgreSQLのテーブルに出力するアウトプットプラグインです。このプラグインは、出力先にPostgreSQLのJSON型カラムを利用します。このプラグインのインストール方法も、他のものと同様です。
$ sudo /usr/lib64/fluent/ruby/bin/fluent-gem install fluent-plugin-pgjson
このプラグインを使って、Fluentdで加工したJSON形式のログデータをPostgreSQLデータベース内のテーブルに挿入してみます。まず、ログデータを格納するテーブルをあらかじめ任意のデータベースに作成しておきます。
# CREATE DATABASE fluentd; # fluentdという名のデータベースを作成 # \c fluentd # ターゲットデータベースをfluentdに変更 # CREATE TABLE fluentd ( # fluentdという名のテーブルを作成 tag Text, time Timestamptz, record Json );
このプラグインの設定は以下のようになります。データを格納する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>;
ここまでの設定が終わったら、Fluentdのプロセスを起動します。今回はRPMパッケージでインストールしているので、以下のようにserviceコマンドで起動します。
$ sudo service td-agent start
起動してしばらくすると、ログデータ格納テーブルにログデータのレコードが蓄積されていきます。
収集したログをSQLで検索する
PostgreSQLにはJSONデータを操作する演算子が用意されており、JSON型のカラムに格納されたデータの任意のフィールドへSQLでアクセスすることが可能となります。各種のログデータを検索する例を以下に示します。
例: メッセージ深刻度レベルがERRORのメッセージを検索
全てのログメッセージには、重要度を表すメッセージ深刻度レベルが付与されています。これはFluentdテーブルにおけるrecordカラム内のJSONデータに「error_severity」というオブジェクトフィールドで格納されており、以下のSQLでメッセージ深刻度レベルが「ERROR」のものに絞り込んで参照することができます。また、WHERE句に「time」カラムの条件を加えることで、確認したい時間帯を絞り込むことも可能です。
# 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件)
スロークエリログと呼ばれる一定時間(今回の設定では1秒)以上かかったSQLの情報は、遅いSQLをチューニングするために必要な情報です。この情報は「postgresql.slow_query」というタグが付与されてtagカラムに格納されますので、WHERE句にタグを絞り込む条件を付与することでスロークエリの情報のみを参照できます。また、fluent-plugin-parserで「duration」「statement」というオブジェクトフィールドを追加しているため、以下のようにORDER BY句で時間順に並び替えることも可能です。
# 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.checkpoint」というタグが付与されてtagカラムに格納されますので、WHERE句にタグを絞り込む条件を付与することで参照できます。
# SELECT time, record->>‘message’ as message FROM fluentd WHERE tag like 'postgresql.checkpoint.%'; time | message -------------------------+------------------------------------------------------------------------- 2014-06-30 01:17:32+00 | checkpoint starting: time 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 2014-06-30 01:27:32+00 | checkpoint starting: time 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 2014-06-30 01:30:13+00 | checkpoint starting: xlog 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 2014-06-30 01:30:21+00 | checkpoint starting: xlog 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句にタグを絞り込む条件を付与することで参照できます。
# SELECT time, record->>'database_name' as db, record->>'command_tag' as command, record->>'message' as message, record->>'query' as query FROM fluentd WHERE tag = 'postgresql.deadlock'; -[ RECORD 1 ]-------------------------------------------------------------------------------------- time | 2014-07-02 09:45:02+00 db | fluentd command | LOCK TABLE waiting message | process 8184 detected deadlock while waiting for ExclusiveLock on relation 16394 of database 16384 after 1000.235 ms query | LOCK TABLE pgbench_history IN EXCLUSIVE MODE;
PostgreSQLにJSON形式のログを格納する意義
JSON型は、PostgreSQLに標準で用意されているデータ型です。PostgreSQLのバージョンアップに伴いJSONサポートの機能が強化されており、PostgreSQLでJSONを扱いやすくする土壌が整いつつあります。一般的にログのようなデータは非定型な場合が多く、スキーマを一律に定義することが難しいため、ログをデータベースに格納する場合はスキーマ定義が不要なMongoDBを使うケースが多かったのではないでしょうか。ログデータをPostgreSQLに格納できれば、非定型なログを使い慣れたSQLで検索、分析できるようになります。また、元々PostgreSQLで管理しているマスターデータとのJOINなど、便利な使い方も可能になりそうです。
最後に
本記事ではPostgreSQLのログをFluentdで収集し、後から分析しやすい形に加工する方法を紹介しました。実際に運用管理を行う上でPostgreSQLの標準機能では少々物足りないログ機能も、他のツールと組み合わせることで運用を効率化できるという1つのヒントになればと考えています。
<編集部より> Fluentdの綴りについて、正式には"F"が大文字だったため修正しました。(2014.10.3)