2008年5月13日

PostgreSQLパフォーマンスチューニングのために　～重いSQLの見つけ方～

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

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

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


createdb test

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


<?php
$db = pg_connect('dbname=test');
$sql = "
    CREATE TABLE artist (
        artist_id serial primary key,
        name text not null
    )
";
pg_query($sql);
$sql = "
    CREATE TABLE music (
        music_id serial primary key,
        artist_id integer not null,
        title text not null
    )
";
pg_query($sql);
for ($i = 0; $i < 10000; $i++) {
    $a_name = serialize(time() + $i);
    $sql = "INSERT INTO artist(name) VALUES('{$a_name}')";
    $res = pg_query($sql);
    $sql = "SELECT artist_id FROM artist WHERE name = '{$a_name}'";
    $res = pg_query($sql);
    
    $tmp = pg_fetch_array($res);
    $artist_id = $tmp['artist_id'];
    
    for ($j = 0; $j < 50; $j++) {
        $title = serialize(time() + $j + $i);
        $sql = "INSERT INTO music(artist_id, title) VALUES({$artist_id}, '{$title}')";
        pg_query($sql);
    }
}
?>

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

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


syslog = 1
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が全て出力されると思います。


/etc/init.d/postgresql reload

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


local0.* /var/log/postgres.log

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


/etc/init.d/syslog restart

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


tail -f /var/log/postgres.log
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を実行します。


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

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

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

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


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

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


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文を実行すると、


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