2012年12月4日

pgBadgerでSQLログを分析する

PostgreSQL Advent Calendar 2012(全部俺)のDay 4です。

負荷試験や本番稼働中のデータベースサーバでは、通常さまざまな種類のSQLが実行されています。

昨日紹介したpg_stat_statmentsシステムビューは、PostgreSQLの内部でSQLの実行状況を積算することのできるモジュールでしたが、「pg_stat_statementsを使うには制約が・・・」というケースもあるでしょう。

PostgreSQLには実行しているSQL文をサーバログに出力する機能があります。SQL文だけでなく実行時間なども出力することができるため、このサーバログを集計することによって、どのようなSQLがどれくらい実行されていて、どのSQLにパフォーマンス上の問題がありそうなのか、といったことを絞り込んでいくことができます。

■SQLログ解析ツール「pgBadger」


サーバログを集計するツールとしてはいくつかあるのですが、今日は「pgBadger」というツールを紹介します。

pgBadger
http://dalibo.github.com/pgbadger/

pgBadgerはPerlで作成されたスクリプトで、一昔前にPHPスクリプトで開発されていたpgFouineというプログラムと同様の機能を持っています。コマンドラインでサーバログを指定して実行すると、サーバログを分析したレポートをHTMLファイルで作成してくれます。

また、SQLだけではなく、サーバログに出ているエラーログなども集計してくれます。

■pgBadgerのインストール


それでは、pgBadgerをインストールしてみます。

「インストール」とは言うものの、単一のPerlスクリプトですので、ソースコードのtar.gzアーカイブを取得して展開するだけです。
[snaga@devsv02 pgsql]$ tar zxf pgbadger-2.2-1.tar.gz
[snaga@devsv02 pgsql]$ cd pgbadger-2.2
[snaga@devsv02 pgbadger-2.2]$ ls
ChangeLog  doc/  LICENSE  Makefile.PL  MANIFEST  META.yml  pgbadger*  README
[snaga@devsv02 pgbadger-2.2]$

■サーバログの設定


PostgreSQLはサーバログの設定によって出力される内容や形式が変わってきます。pgBadgerを使うためには、分析に必要な内容がサーバログに出力されている必要がありますので、まずはサーバログの設定を確認します。

pgBadgerでは以下の設定を推奨しています。(出力先にstderrを使う場合)
log_line_prefix = '%t [%p]: [%l-1] '
log_line_prefix = '%t [%p]: [%l-1] db=%d,user=%u '
また、サーバログの出力にsyslogを使う場合には、以下のいずれかの設定が推奨されています。
log_line_prefix = 'user=%u,db=%d '
log_line_prefix = 'db=%d,user=%u '
この辺りの詳細についてはpgBadgerのマニュアルを参照してください。

今回のログ関連の設定は以下の通りです。
testdb1=# SELECT name,setting FROM pg_settings WHERE name LIKE 'log%';
            name             |       setting
-----------------------------+----------------------
 log_autovacuum_min_duration | -1
 log_checkpoints             | off
 log_connections             | on
 log_destination             | stderr
 log_directory               | pg_log
 log_disconnections          | on
 log_duration                | off
 log_error_verbosity         | default
 log_executor_stats          | off
 log_file_mode               | 0600
 log_filename                | postgresql-%Y-%m.log
 log_hostname                | off
 log_line_prefix             | %t [%p]: [%l-1] db=%d,user=%u
 log_lock_waits              | off
 log_min_duration_statement  | 0
 log_min_error_statement     | error
 log_min_messages            | warning
 log_parser_stats            | off
 log_planner_stats           | off
 log_rotation_age            | 1440
 log_rotation_size           | 0
 log_statement               | none
 log_statement_stats         | off
 log_temp_files              | 0
 log_timezone                | Japan
 log_truncate_on_rotation    | on
 logging_collector           | on
(27 rows)

testdb1=#

■サーバログ解析の実施


それでは、実際にSQLログの解析をしてみます。

pgbadgerコマンドを実行する際、log_line_prefixの値を--prefixオプションで指定し、サーバログのファイル(ここでは/tmp/postgresql-2012-11.log)を引数として与えます。
[snaga@devsv02 pgbadger-2.2]$ ./pgbadger --prefix '%t [%p]: [%l-1] db=%d,user=%u ' /tmp/postgresql-2012-11.log
[========================>] Parsed 100810441 bytes of 100810441 (100.00%), queries: 486277, events: 1
[snaga@devsv02 pgbadger-2.2]$ ls
ChangeLog  LICENSE      MANIFEST  out.html   postgresql-2012-11.log
doc/       Makefile.PL  META.yml  pgbadger*  README
[snaga@devsv02 pgbadger-2.2]$
ログの集計が完了すると、上記のように out.html というレポートファイルが作成されます。

今回のレポートのサンプルは以下の通りです。

pgBadgerサンプルレポート

■レポートの読み方


レポートには、以下のセクションがあります。
  • Overall statistics (概要)
  • Hourly statistics (日付/時間帯別統計)
  • Queries by type (クエリ種別統計)
  • Sessions per database (データベース別セッション統計)
  • Sessions per user (ユーザ別セッション統計)
  • Sessions per host (接続元ホスト別セッション統計)
  • Connections per database (データベース別接続統計)
  • Connections per user (ユーザ別接続統計)
  • Connections per host (接続元ホスト別接続統計)
  • Slowest queries (遅いクエリランキング)
  • Queries that took up the most time (N) (総実行時間が長いクエリランキング)
  • Most frequent queries (N) (実行回数の多いクエリランキング)
  • Slowest queries (N) (平均実行時間が長いクエリランキング)
  • Most frequent events (N) (もっともよく発生したエラーランキング)
  • Logs per type (サーバログ種別統計)
レポートの内容が多岐に渡るため、レポートを読む時には読むための「軸」が必要です。以下に、いくつか例を示します。

・突出して遅いクエリを探す場合

Slowest queries を確認しましょう。実行時間が特に遅かったクエリを表示してくれます。

Slowest queriesには(N)が付いている統計と付いていない統計がありますが、ここで見るのは(N)が付いていない統計です。

・全体的に実行時間の遅いクエリを探す場合

Slowest queries(N) を見ましょう。こちらは(N)の付いている統計です。

(N)というのは、Day3のpg_stat_statementsシステムビューの時にも出てきたように、クエリのパラメータの値を「?」で置き換えた "normalize" した集計、という意味です。("normanlize" の詳細ついては、Day3のエントリを参照ください。)

・実行回数の多いクエリを探す場合

Most frequent queries(N) を見ましょう。似たようなクエリが何回実行されているか、多い順にランキングされます。

■まとめ


今日は、PostgreSQLのサーバログを集計してパフォーマンス分析をするツール「pgBadger」の使い方を紹介しました。

pgBadgerのようなツールは、あくまでもパフォーマンス分析を支援してくれる、楽にしてくれるツールです。作成されたレポートをどのように読むか、どのように解釈して改善につなげるかがDBAの腕の見せ所になります。

こういったツールを使って手間を省きつつ、ピンポイントで素早くパフォーマンスのボトルネックを特定して改善できるように、日頃から腕を磨いておきましょう。

ではまた。

0 件のコメント:

コメントを投稿