遅いSQLの見つけ方

OracleでSQLのチューニングをそこそこしていた人がPostgreSQLで同じことをやろうとした場合に
問題になるのはチューニング対象のSQLを探す作業だと思う。

Oracleであれば、SQL traceを仕掛けたり、$sql_textなどから引っ張ってきたり、Statspackのレポート読んだりと
色んな方法で遅いSQLを特定することが可能だ。
しかし、PostgreSQLではOracle程簡単に対象のSQLを特定するのは難しい。（この辺りの機能がもう少し欲しいところ）

ということで、今回は遅いSQLを見つける特定する方法です。

log_min_duration_statementの設定を変更する

postgresql.confにlog_min_duration_statementというパラメータがある。
指定したミリ秒数以上、時間がかかったSQLをログに出力してくれるものだ。
MySQLのスロークエリーログと同じような感じらしい（MySQLは全然詳しくないので伝聞ですが）

普段、遅いクエリが走っていないか、夜間バッチ等、会社に居ない間に実行されるクエリのパフォーマンスを
確認したい場合なんかに向いている機能ではないでしょうか。

こんな感じで出力されます。

2009-02-18 11:43:23 JST LOG:  duration: 2750.721 ms  statement: select count(*) from master_tbl;

ちなみにPDOを使っていた場合も、2行目にパラメータを出力してくれるので再実行する際も楽です。

2009-02-23 04:08:10 JST LOG:  duration: 8511.299 ms  execute pdo_pgsql_stmt_0098b4b0: SELECT COUNT(*) FROM tableA  WHERE id = $1 AND type = 0
2009-02-23 04:08:10 JST DETAIL:  parameters: $1 = '2782034'

気をつける点としては、このパラメータを変更すると閾値を上回ったSQLをすべてログに出力するので、下手するとログ出力がボトルネックになりかねないということ。
設定する際は、最初は大きめにとって徐々に閾値を下げていくという方向でやるのがいいでしょう。

実行中のSQLを取得

もうひとつの方法は、現在実行中のSQLを取得する方法。

下記のSQLを実行すると、現在実行中のSQLと実行時間を取得できます。

testdb=# SELECT
testdb-#    pid,
testdb-#    start,
testdb-#    now() - start AS lap,
testdb-#    current_query
testdb-# FROM
testdb-#    (SELECT
testdb(#        backendid,
testdb(#        pg_stat_get_backend_pid(S.backendid) AS pid,
testdb(#        pg_stat_get_backend_activity_start(S.backendid) AS start,
testdb(#        pg_stat_get_backend_activity(S.backendid) AS current_query
testdb(#    FROM
testdb(#        (SELECT pg_stat_get_backend_idset() AS backendid) AS S
testdb(#    ) AS S
testdb-# WHERE
testdb-#    current_query <> ''
testdb-# ORDER BY
testdb-#    lap DESC;
  pid  |             start             |       lap        |                           current_query

























































































































































































































































-




























































































































 10755 | 2009-02-23 23:42:46.152279+09 | -00:00:02.403189 | SELECT max(aid)  FROM tableA  WHERE id=3661012
 10757 | 2009-02-23 23:42:46.158289+09 | -00:00:01.109199 | SELECT * FROM tableB  WHERE id=7818 AND valid=true

遅いWebの画面の調査時なんかには、どのSQLが遅いか簡単に調べられます。
log_min_duration_statementを設定するのは、いつ遅いSQLが実行されるか分からない時、または夜間人が居ない時間帯に実行される時、
上記のSQLを実行するのは、遅いSQLが実行されるのが分かる時といった具合に使い分けるのがいいでしょう。

pg_stat_statements

8.3までは、上記の２つしか方法がなかったわけですが、PostgerSQL8.4からpg_stat_statementsが使えるようになるみたいです。

OracleのStatsPackの「SQL ordered by Elapsed Time」「SQL ordered by Executions」の項目と同じような値が簡単に取得で
きるようになります。

$ pgbench -i bench

postgres=# SELECT pg_stat_statements_reset();

$ pgbench -c10 -t300 -M prepared bench

postgres=# \x
postgres=# SELECT * FROM pg_stat_statements ORDER BY total_time DESC LIMIT 3;
[ RECORD 1 ]------------------------------------------------------------
userid     | 10
dbid       | 63781
query      | UPDATE branches SET bbalance = bbalance + $1 WHERE bid = $2;
calls      | 3000
total_time | 20.716706
rows       | 3000
[ RECORD 2 ]------------------------------------------------------------
userid     | 10
dbid       | 63781
query      | UPDATE tellers SET tbalance = tbalance + $1 WHERE tid = $2;
calls      | 3000
total_time | 17.1107649999999
rows       | 3000
[ RECORD 3 ]------------------------------------------------------------
userid     | 10
dbid       | 63781
query      | UPDATE accounts SET abalance = abalance + $1 WHERE aid = $2;
calls      | 3000
total_time | 0.645601
rows       | 3000

どのSQLが何回実行されて、トータル何秒処理時間が掛かっているかと出してくれます。
今までの方法だと、特定の遅いSQLは発見することが可能でしたが、実行回数が多くちょっとだけ遅いSQLの場合は、
発見するのが困難だったのでこれはいい改善点だと思います。

8.4が出たら早速使いたいと思いますが、移行するのがまた面倒な・・・・。

と、こんな感じでやればボトルネックとなっているSQLを特定することが可能だと思います。

他にもツールとか使えば、もっと簡単に特定できるかもしれせんが、その辺りは詳しくないので省略。