Y-110's Wiki

_ ログ解析ツール pqa

pqa(Practical Query Analyzer) は, PostgreSQL のログ解析ツールです。
クエリの実行時間等を一覧表示できるため, ボトルネックになっている SQL の調査には非常に役に立ちます。
現時点(2006/5/25)での最新バージョンは 1.6 で, log_duration がサポートされている PostgreSQL 7.3 以降に対応しています。

_ install

PgFoundry:pqa から pqa の最新パッケージをダウンロードします。
ダウンロードしたパッケージを解凍して, pqa.rb を適当なディレクトリにコピーすれば OK。
pqa は Rubyで記述されているので, Ruby も必要です。

_ PostgreSQL ログの設定

log_duration = true(8系は log_duration = on) にして, 実行時間をログに出力するようにしましょう。
その他のログに関する設定は適当でも柔軟に解析してくれるようです。*1

_ 実行と出力

pqa の実行と出力結果は以下のような感じになります。
PostgreSQL 8.1.3 にて pgbench を行った結果をログに出力して解析したものです。
解析には割りと時間がかかるので, コーヒーでも飲みながらゆっくり待ちましょう。

$ ruby pqa.rb -logtype pglog -file postgres.log
######## Overall statistics
38649 queries (29991 unique), longest ran in 0.36414 seconds), parsed in 8.283365 seconds
######## Queries by type
SELECTs: 6454  (17%)
INSERTs: 6419  (17%)
UPDATEs: 19200  (50%)
DELETEs: 1     (0%)
######## Queries that took up the most time
5.437 seconds: END;
2.135 seconds: UPDATE tellers SET tbalance = tbalance + 7862 WHERE tid = 4;
2.119 seconds: UPDATE tellers SET tbalance = tbalance + 114 WHERE tid = 4;
2.034 seconds: UPDATE tellers SET tbalance = tbalance + 7086 WHERE tid = 8;
2.028 seconds: UPDATE tellers SET tbalance = tbalance + 5986 WHERE tid = 4;
2.023 seconds: UPDATE tellers SET tbalance = tbalance + 2878 WHERE tid = 4;
1.906 seconds: UPDATE tellers SET tbalance = tbalance + 4189 WHERE tid = 4;
1.859 seconds: UPDATE tellers SET tbalance = tbalance + 9960 WHERE tid = 4;
1.832 seconds: UPDATE tellers SET tbalance = tbalance + 834 WHERE tid = 9;
1.821 seconds: UPDATE tellers SET tbalance = tbalance + 2518 WHERE tid = 3;
######## Slowest queries
2.135 seconds: UPDATE tellers SET tbalance = tbalance + 7862 WHERE tid = 4;
2.119 seconds: UPDATE tellers SET tbalance = tbalance + 114 WHERE tid = 4;
2.034 seconds: UPDATE tellers SET tbalance = tbalance + 7086 WHERE tid = 8;
2.028 seconds: UPDATE tellers SET tbalance = tbalance + 5986 WHERE tid = 4;
2.023 seconds: UPDATE tellers SET tbalance = tbalance + 2878 WHERE tid = 4;
1.906 seconds: UPDATE tellers SET tbalance = tbalance + 4189 WHERE tid = 4;
1.859 seconds: UPDATE tellers SET tbalance = tbalance + 9960 WHERE tid = 4;
1.832 seconds: UPDATE tellers SET tbalance = tbalance + 834 WHERE tid = 9;
1.821 seconds: UPDATE tellers SET tbalance = tbalance + 2518 WHERE tid = 3;
1.797 seconds: UPDATE tellers SET tbalance = tbalance + 3317 WHERE tid = 8;
######## Most frequent queries
6400 times: END;
66 times: SET search_path = public
39 times: CREATE OR REPLACE FUNCTION
10 times: copy accounts from stdin
5 times: UPDATE branches SET bbalance = bbalance + 6160 WHERE bid = 1;
5 times: COMMENT ON TYPE SENNA IS 'Senna index data type';
5 times: UPDATE branches SET bbalance = bbalance + 7710 WHERE bid = 1;

• Overall statistics
  • 全体的な統計結果です
• Queries by type
  • 問い合わせの種類とその割合で, サイトの性質がわかります
• Queries that took up the most time
  • 実行回数 × 実行時間の大きい SQL が表示されます
• Slowest queries
  • 単独の SQL が遅い順に表示されます
• Most frequent queries
  • 実行回数の多い SQL が表示されます

_ pqa の主要オプション

-logtype   ログファイルの形式。pglog|syslog|mysql の中から選択可能。
-top n     上位 n クエリのみ表示する。
-normalize パラメータの違いを吸収し, SQL を正規化して評価する
-format    解析結果出力形式。text|html の中から選択可能。
-file      ログファイル名

オプションに -normalize を指定すれば, パラメータの違いを無視してログ解析を行ってくれます。

例えば, 上記の例の解析に -normalize をつけて実行すると,

UPDATE tellers SET tbalance = tbalance + '' WHERE tid = '';

が本質的に同一の SQL文とみなされ, Queries that took up the most time の結果が変わります。

######## Queries that took up the most time
1032.140 seconds: UPDATE tellers SET tbalance = tbalance + { } WHERE tid = { };
148.606 seconds: UPDATE branches SET bbalance = bbalance + { } WHERE bid = { };
9.329 seconds: UPDATE accounts SET abalance = abalance + { } WHERE aid = { };
5.437 seconds: END;

クエリの正規化を行わない解析では, END の実行がトップでしたが, クエリの正規化を行うことで

UPDATE tellers SET tbalance = tbalance + { } WHERE tid = { }

の実行に一番時間がかかっているということがわかります。

_ 対策

pqa でログを解析すると, 実行に時間がかかっている SQL が簡単にわかります。
後は, ボトルネックとなっている SQL文の実行計画を確認して SQLをチューニングします。
最低限, EXPLAIN で下記の基本的な事項を確認して対処してください。

• インデックスの適切な利用がされているか
• 無駄なテーブルジョインが行われていないか
• WHERE 条件の指定の順番が適切か
• 複雑すぎる SQL を発行していないか