アシアルブログ

こんにちは、牧野です。
先日、あるウェブサイトで使用しているPostgreSQLを見直す機会がありました。

PostgreSQLのパフォーマンスを手軽に上げるには、
・データベースの設定ファイルのパラメータを変更する
・アプリケーションの方で重いSQLを発行している場所を見つけて、その部分を直していく
・vaccumを実行する
など、いくつか方法が考えられます。
今回は、PostgreSQLで実行時間が長いSQLを見つける方法について紹介します。

本題に入る前に、まずはテスト用データベースを作っておきます。

1. createdb test

そして、次のようなプログラムを作成、実行して、ダミーデータも入れておきます。

1. <?php
2. $db = pg_connect('dbname=test');
3.  
4. $sql = "
5.     CREATE TABLE artist (
6.         artist_id serial primary key,
7.         name text not null
8.     )
9. ";
10. pg_query($sql);
11.  
12. $sql = "
13.     CREATE TABLE music (
14.         music_id serial primary key,
15.         artist_id integer not null,
16.         title text not null
17.     )
18. ";
19. pg_query($sql);
20.  
21. for ($i = 0; $i < 10000; $i++) {
22.     $a_name = serialize(time() + $i);
23.     $sql = "INSERT INTO artist(name) VALUES('{$a_name}')";
24.     $res = pg_query($sql);
25.  
26.     $sql = "SELECT artist_id FROM artist WHERE name = '{$a_name}'";
27.     $res = pg_query($sql);
28.     
29.     $tmp = pg_fetch_array($res);
30.     $artist_id = $tmp['artist_id'];
31.     
32.     for ($j = 0; $j < 50; $j++) {
33.         $title = serialize(time() + $j + $i);
34.         $sql = "INSERT INTO music(artist_id, title) VALUES({$artist_id}, '{$title}')";
35.         pg_query($sql);
36.     }
37. }
38. ?>

musicテーブルとartistテーブルの２テーブルだけで適当なデータですが、とりあえずこれでデータベースは準備できました。
次に、重いSQLが実行されたらログに出力するようにpostgresql.confを変更します。
postgresql.confは通常、PostgreSQLのデータディレクトリの中(例えば /var/lib/pgsql/data内)に置かれています。

自分のテストサーバはCentOS、PostgreSQL7.4系で、この場合だと以下の部分を変更します。

1. syslog = 1
2. log_min_duration_statement = 0

8系だとsyslog = 1ではなく、log_destination = 'syslog' というように変わっています。
log_min_duration_statementについてですが、設定された数字を上回る実行時間のSQLがログに出力されるようになります。
単位はミリセカンドです。※本番で行う場合は、最初は大きい値を設定しましょう。

設定についてはドキュメントに詳細が載っています。
http://www.postgresql.jp/document/pg831doc/html/runtime-config-logging.html

設定ファイルを再読み込みすると、/var/log/messagesに実行されたSQLが全て出力されると思います。

1. /etc/init.d/postgresql reload

PostgreSQL用のログファイルを作成する場合は、/etc/syslog.confに

1. local0.* /var/log/postgres.log

というように追記してsyslogを再起動します。

1. /etc/init.d/syslog restart

ログファイルを見ながらSQLを実行してみると、

1. tail -f /var/log/postgres.log
3. May 13 19:22:43 makmak postgres[14003]: [10-1] LOG:  duration: 4145.884 ms  statement: select * from music order by artist_id desc limit 10 offset 100;

こんな感じでログが出力されます。この例だと4秒以上かかっています。
重いSQLが見つかったらexplainを実行します。

1. test=>explain select * from music order by artist_id desc limit 10 offset 100;
3.                                 QUERY PLAN                                 
4. ---------------------------------------------------------------------------
5.  Limit  (cost=76910.28..76910.31 rows=10 width=40)
6.    ->  Sort  (cost=76910.03..78160.04 rows=500001 width=40)
7.          Sort Key: artist_id
8.          ->  Seq Scan on music  (cost=0.00..12046.01 rows=500001 width=40)
9. (4 rows)

cost=の部分が実行時間に関わってきます。マニュアルを見ると、
http://www.postgresql.jp/document/pg831doc/html/using-explain.html

cost=(数字)..(数字)

の最初の数字が、最初の行が返されるまでの時間、次の数字が全ての行が返されるまでの合計時間とありますが、バージョンによって違う場合があるそうです。が、とにかく、artist_idでソートするところとlimitのところで膨大な時間がかかっていることがわかります。
そこで、artist_idにインデックスを定義して、

1. test=> create index artist_id_index on music(artist_id);

それから実行してみると、

1. May 13 20:42:58 makmak postgres[15680]: [1-1] LOG:  duration: 49.107 ms  statement: select * from music order by artist_id desc limit 10 offset 100;

実行時間が80分の1以下になりました。
再度explain文を実行すると、

1. test=> explain select * from music order by artist_id desc limit 10 offset 100;
2.                                                QUERY PLAN                                               
3. --------------------------------------------------------------------------------------------------------
4.  Limit  (cost=344.61..379.07 rows=10 width=40)
5.    ->  Index Scan Backward using artist_id_index on music  (cost=0.00..1723054.54 rows=500000 width=40)
6. (2 rows)

作ったインデックスが使用されていることがわかります。

…これは極端な例ですが、このような地道な作業の繰り返しで相当パフォーマンスを上げられる場合があります。ユーザが頻繁にアクセスするようなところに一箇所でも重い部分があると、全体のパフォーマンスに大きく影響します。
PostgreSQLが重くて困っている方は試してみてはいかがでしょうか。