PostgreSQLのログをFluentdで収集する

2014年10月4日(土)
中西 剛紀

fluent-plugin-pgjson

ログデータをPostgreSQLのテーブルに出力するアウトプットプラグインです。このプラグインは、出力先にPostgreSQLのJSON型カラムを利用します。このプラグインのインストール方法も、他のものと同様です。

リスト15:fluent-plugin-pgjsonプラグインのインストール

$ sudo /usr/lib64/fluent/ruby/bin/fluent-gem install fluent-plugin-pgjson

このプラグインを使って、Fluentdで加工したJSON形式のログデータをPostgreSQLデータベース内のテーブルに挿入してみます。まず、ログデータを格納するテーブルをあらかじめ任意のデータベースに作成しておきます。

リスト16:ログデータ格納テーブルの作成

# CREATE DATABASE fluentd;    # fluentdという名のデータベースを作成
# \c fluentd                  # ターゲットデータベースをfluentdに変更
# CREATE TABLE fluentd (      # fluentdという名のテーブルを作成
    tag  Text,  time  Timestamptz,  record  Json
);

このプラグインの設定は以下のようになります。データを格納するPostgreSQLサーバのホスト名、ポート番号、データベース名、テーブル名といった、PostgreSQLデータベースに接続するために必要な情報を定義しています。

リスト17:fluent-plugin-pgjsonプラグインの設定(td-agent.confに追記)

<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コマンドで起動します。

リスト18:Fluentdプロセスの起動

$ 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)

TIS株式会社

戦略技術センター所属。過去に様々なDBMSと苦楽を共にし、現在はPostgreSQLをはじめするOSSの活用推進をテーマに活動中。アプリケーション基盤「ISHIGAKI Template」の開発とともに、日本PostgreSQLユーザ会、PostgreSQLコンソーシアムといったコミュニティを通じてPostgreSQLの普及活動にも力を注いでいる。

連載バックナンバー

Think ITメルマガ会員登録受付中

Think ITでは、技術情報が詰まったメールマガジン「Think IT Weekly」の配信サービスを提供しています。メルマガ会員登録を済ませれば、メルマガだけでなく、さまざまな限定特典を入手できるようになります。

Think ITメルマガ会員のサービス内容を見る

他にもこの記事が読まれています