PostgreSQLでSQL毎の実行にかかった時間をログに残す方法

postgresql.conf に以下を設定します。

log_min_duration_statement = 0

これは指定ミリ秒以上時間がかかったSQL文をかかった時間と一緒にログに残すようにします。 0を設定するとすべてのSQL文をかかった時間とともにログに出力します。

※注意
この設定と log_statement を同時に設定すると、log_statement の設定によるSQL文のログとlog_min_duration_statement によるSQL文のログがそれぞれ出力されてしまう為、同じようなログが2重に出てしまいます。なので log_min_duration_statement=0 を使う場合は log_statement は無効にするべきです。

duration_statementを含んだログファイルを解析して統計情報を表示するスクリプト

以下のような Perl スクリプトを作成してログをパイプで流すことで、各SQL文毎の実行回数・平均時間・最大時間・合計時間がタブ区切りで出力されるので、ボトルネックを探すのに便利です。

analyze-log_min_duration_statement.pl

#!/usr/bin/perl
use strict;

my %count = ();
my %sum = ();
my %max = ();

while(my $line = <STDIN>) {
    next until($line =~ / duration: ([0-9\.]+) ms\s+statement: (.*)$/);
    my $msec = $1;
    my $statement = $2;
    $count{$statement}++;
    $sum{$statement} += $msec;
    if($max{$statement} < $msec) {
        $max{$statement} = $msec;
    }
}
foreach my $statement (keys %count) {
    my $c = $count{$statement};
    my $s = $sum{$statement};
    my $m = $max{$statement};
    my $a = $s / $c;
    print "$a\t$m\t$c\t$s\t$statement\r\n";
}