実行が遅いSQL文をpg_stat_statementsで抽出する

PostgreSQL Advent Calendar 2012（全部俺）のDay 3です。

3日目となる今回はSQL文の実行状況を解析するツールとしてpg_stat_statementsを使ってみます。

■SQLパフォーマンスをどのように分析するか

特定のSQL文が遅いことが判明している場合は別ですが、通常、SQLのパフォーマンス分析を行う場合には、「どのSQL文が問題なのか」というところから調査します。その時の判断の軸としては、主に以下の2つがあります。

・実行回数の多いSQL文
・実行時間の長いSQL文

特定のSQL文を修正して得られるパフォーマンス向上の成果は、

・1つのSQL文の改善量×実行回数

となります。

例えば、1回実行するのに1秒かかるSQL文を1万回実行すると、トータルで1万秒となりますが、一回あたりの実行時間を0.5秒に短縮できればトータルの実行時間としては1万秒から5000秒に短縮されることになります。

このようにして、「クエリ1回の実行時間×クエリの実行回数」の大きいものから改善してくと、SQLチューニングに投入する費用対効果（時間も含む）が高くなります。

そのため、これらの軸でSQL文をランキングしておくことが重要になります。

■「pg_stat_statements」とは

pg_stat_statementsは、PostgreSQLのバージョン8.4で導入されたcontribモジュールで、専用のビューから上記に挙げたSQLの実行回数や総実行時間などを取得することができるようになります（バージョンによって取得できる情報が若干異なります）。

詳細は以下のマニュアルを参照してください。

F.29. pg_stat_statements
http://www.postgresql.jp/document/9.0/html/pgstatstatements.html

■インストール／設定方法

pg_stat_statementsはcontribモジュールなので、Day 2で紹介した方法でインストールすることができるのですが、PostgreSQLの内部のフックを使っている関係上、もう一つ追加の設定が必要です。

postgresql.conf の shared_preload_libraries というパラメータに "pg_stat_statements" の記載を追加します。

shared_preload_libraries = 'pg_stat_statements'

shared_preload_librariesパラメータの詳細については以下を参照してください。

18.4. 資源の消費
http://www.postgresql.jp/document/9.0/html/runtime-config-resource.html#GUC-SHARED-PRELOAD-LIBRARIES

モジュールの読み込みの設定ができたらサーバを再起動し、contribモジュールの作法の通り、

$ psql -f pg_stat_statements.sql testdb

または

testdb=# CREATE EXTENSION pg_stat_statements;

として登録を行います。

特にエラーが出ず、データベース上にpg_stat_statementsというビューが作成されていたら成功です。

testdb=# \d
               List of relations
 Schema |        Name        | Type |  Owner
--------+--------------------+------+----------
 public | pg_stat_statements | view | postgres
(1 row)

testdb=#

■pg_stat_statementsの動作

pg_stat_statementsは同一のSQL文について、SQL文、実行時間、実行回数、取得した（または更新した）レコード数を積算します。

pg_stat_statementsは、デフォルトでは1000種類のクエリについて情報を収集・蓄積します。つまり、pg_stat_statementsビューの最大行数は（デフォルトでは）1000行、ということです。

実行されるクエリの種類が1000種類を超えると、実行回数の少ないものから計測の対象から外れていきます。（実行回数の多いものが残ります）

■pg_stat_statementsの読み方

pg_stat_statementsは、主に以下のような観点で読みます。

・総実行時間（total_time）が大きいクエリはどれか
・各クエリの平均実行時間（total_time / calls）はどれくらいか

以下は、ベンチマークツールであるpgbenchを実行中に、total_timeの長い順に10件のランキングを取っている例です。

testdb=> select substr(query, 0, 60) as query,calls,total_time FROM pg_stat_statements
 ORDER BY total_time DESC LIMIT 10;
                            query                            | calls |    total_time
-------------------------------------------------------------+-------+------------------
 UPDATE pgbench_branches SET bbalance = bbalance + ? WHERE b | 22566 | 1690292.36300003
 UPDATE pgbench_tellers SET tbalance = tbalance + ? WHERE ti | 22575 | 615662.877999972
 UPDATE pgbench_accounts SET abalance = abalance + ? WHERE a | 22589 | 36555.3669999999
 INSERT INTO pgbench_history (tid, bid, aid, delta, mtime) V | 22566 | 6013.40700000065
 SELECT abalance FROM pgbench_accounts WHERE aid = ?;        | 22588 | 5045.90600000038
 BEGIN;                                                      | 22591 | 474.965999999924
 END;                                                        | 22565 | 135.650000000064
 select * FROM pg_stat_statements LIMIT ?;                   |     1 |             4.15
 SELECT pg_catalog.quote_ident(c.relname) FROM pg_catalog.pg |     2 |             3.44
 select query,calls,total_time FROM pg_stat_statements ORDER |     1 |            0.158
(10 rows)

testdb=>

この例では pgbench_branches テーブルに対するUPDATEが22,566回実行され、トータルで1,690,292ミリ秒（1690秒）かかっていることが分かります。この平均を計算すると、1回のクエリの実行に約74.9ミリ秒かかっている計算になります。

このように、総実行時間が大きい順にクエリを見ていき、現実的に改善できそうなクエリ、そして改善のインパクトが大きいクエリをピックアップして、改善すべき対象を絞り込んでいきます。

そして、クエリをチューニングしたら、再度pg_stat_statementsを計測して、パフォーマンスが改善しているかどうかを確認します（平均実行時間などを見る）。

なお、pg_stat_statementsビューの値をリセットするには、SQL関数である pg_stat_statements_reset() を呼び出します。

testdb=> SELECT pg_stat_statements_reset();

■pg_stat_statementsの制約（バージョン9.1以前）

pg_stat_statementsは非常に便利なのですが、9.1以前のバージョンでは利用に当たって制約があります。「同じSQL文」として認識されるためには、クエリが「まったく同じ文字列」である必要があるのです。

具体的に見て見ましょう。

testdb=# select * from pgbench_branches where bid=1;
 bid | bbalance | filler
-----+----------+--------
   1 |        0 |
(1 row)

testdb=# select * from pgbench_branches where bid=2;
 bid | bbalance | filler
-----+----------+--------
   2 |        0 |
(1 row)

testdb=# select * from pgbench_branches where bid=3;
 bid | bbalance | filler
-----+----------+--------
   3 |        0 |
(1 row)

testdb=# select substr(query, 0, 60) as query,calls,total_time FROM pg_stat_statements
 ORDER BY total_time DESC LIMIT 10;
                    query                    | calls | total_time
---------------------------------------------+-------+------------
 SELECT pg_stat_statements_reset();          |     1 |   0.001215
 select * from pgbench_branches where bid=1; |     1 |    2.6e-05
 select * from pgbench_branches where bid=3; |     1 |    2.1e-05
 select * from pgbench_branches where bid=2; |     1 |      2e-05
(4 rows)

testdb=#

上記は「select * from pgbench_branches where bid=なんとか」というクエリですが、bidが1、2、3と異なっていることによって、それぞれ別々のSQL文としてカウントされてしまっています。

このようなSQL文が大量に発生する場合、このままだとpg_stat_statementsは実質的には使えませんので、プリペアードクエリとバインド変数を使って個別の値を隠蔽する必要があります。

Javaでアプリケーションを書いている場合にはPreparedStatementを使ってプリペアードクエリに値をバインドして実行するのは一般的だと思いますが、その他のアプリケーションでは、場合によっては意識してプリペアードクエリを使う必要があるかもしれません。

■バージョン9.2以降のpg_stat_statements

前述のようにバージョン9.1までは、（実質的に）プリペアードクエリが必須だったのですが、9.2でこの制約と取り払う改善が行われました。

英文のドキュメントでは "normalization" と表現されていますが、異なるパラメータを持ったSQL文を同じSQL文として認識してくれる機能です。

具体的に見てみましょう。

testdb=# select * from pgbench_branches where bid=1;
 bid | bbalance | filler
-----+----------+--------
   1 |   -27861 |
(1 row)

testdb=# select * from pgbench_branches where bid=2;
 bid | bbalance | filler
-----+----------+--------
   2 |   154658 |
(1 row)

testdb=# select * from pgbench_branches where bid=3;
 bid | bbalance | filler
-----+----------+--------
   3 |   -33748 |
(1 row)

testdb=# select substr(query, 0, 60) as query,calls,total_time FROM pg_stat_statements
 ORDER BY total_time DESC LIMIT 10;
                            query                            | calls | total_time
-------------------------------------------------------------+-------+------------
 select * from pgbench_branches where bid=?;                 |     3 |      0.285
 select substr(query, ?, ?) as query,calls,total_time FROM p |     1 |       0.21
 select pg_stat_statements_reset();                          |     1 |      0.169
(3 rows)

testdb=#

上記の例は、bidをそれぞれ1、2、3と指定してクエリを実行しても、pg_stat_statementsビューの中では同じクエリ（select * from pgbench_branches where bid=?）を3回実行したものとして集計されていることが分かります。

この機能によって、プリペアードステートメントを使っていなくてもpg_stat_statementsのメリットを十分に受けることができるようになりました。

■まとめ

以上、pg_stat_statementsモジュールの使い方を簡単にご紹介してきました。

たくさんのSQL文が実行されている中で、パフォーマンスチューニングの対象とするSQL文を絞り込んでいく作業は非常に重要ですし、チューニングの効果が出たかどうかも確認しなければなりません。

pg_stat_statementsモジュールを使うと非常に簡単にSQL文を絞り込んでいくことができますので、まだ使ったことがない方は、ぜひ試しに使ってみてください。

では、また明日。