PostgreSQL Query Performance Analysis

This is a PostgreSQL query performance analyzer. I have used this for several years (so it's older and there are a couple things I would do differently) to find index and query parse problems. Since it just runs off the Postgres logfile (normally just sent to the bit bucket) you can use real life data, without much of a application performance loss (It shouldn't effect query time).

You should just have to reroute the log file from the /dev/null to a real file. The default logfile options should work.

The Output:

Total: gives you the total time of execution of a particular sql statement over the entire logfile, this gives a rough estimation of what you should be looking at.
Cost: comes from PostgreSQL query optimizer as the cost (based on time) to run the query. This is the Max cost of the query.
Avg: is the average cost (only really useful after changes)
IDX: IDX means an index was used for the main loop, SEQ the main loop was a Sequential scan of rows
Query: The actual query

#!/usr/bin/perl
use strict;
use warnings;
use Getopt::Long;

my $sort_fld = 'tot';
my $show = 25;
GetOptions ("show=i" => \$show, "sort=s" => \$sort_fld) || usage('Inva
+lid Option');
my $fn = $ARGV[0] || usage('Please specify a logfile');
usage("$fn does not exist") if (! -e $fn);
usage("$fn is not readable. Check permissions") if (! -r $fn);
usage("$fn is 0 size") if (-z $fn);
usage("$fn is not a regular file") if (! -f $fn);
usage('Invalid sort option') if (! ($sort_fld eq 'tot' or $sort_fld eq
+ 'avg' or $sort_fld eq 'cost'));

my ($lines ) = `wc -l $fn`;
$lines =~ s/\D+//g;
my %q;
my $get_q = 0;
my $query = '';
my $buffer = '';
open(FH,'<',$fn) or die "Could not open $fn: $!";
print "Reading file...\n";
my $cnt = 0;
while (my $line = <FH>) {
    if ($line =~/^DEBUG:  query:/){
        $get_q++;
    } elsif ($get_q and $line =~ /^DEBUG: /) {
        $query = $buffer;
        $buffer = '';
        $get_q = 0;
    }
    if ($get_q) {
        $buffer .= $line;
        $buffer =~ s/^DEBUG:  query://g;
        $buffer =~ s/\s+/ /g;
    }
    if (!$get_q and $line =~ /^\s+:total_cost\s+(\S+)/) {
        my $cost = $1;
        no warnings;
        $cost =~ s/([\d.]+)/$1/g;
        $q{$_}{cost} = 0 if ($q{$_}{cost} =~ /[^\d.]/);
        $q{$query}{cost} = $cost > $q{query}{cost} ? $cost : $q{$query
+}{cost};
        $q{$query}{tot} += $cost;
        push(@{$q{$query}{costs}},$cost);
        $q{$query}{cnt}++;
        use warnings;
    }
    $q{$query}{scan} = 'SEQ' if (!$get_q and $line =~ /^\s+{\s+SEQSCAN
+/);
    $q{$query}{scan} = 'IDX' if (!$get_q and $line =~ /^\s+{\s+INDEXSC
+AN/);

    $cnt++;
    print "Reading line: $cnt of $lines\r" if (!($cnt % 1000));
}
print "\n Cleaning...";
foreach ( keys %q ) {
    if (/pg_/){ delete $q{$_}; next } #skip internal tables
    my $tot;
    foreach my $cost (@{$q{$_}{costs}}) {
        $tot += $cost;
    }

    $q{$_}{cost} = 0 if (!$q{$_}{cost} or $q{$_}{cost} =~ /[^\d.]/);
    $tot ||= 0;
    $q{$_}{cnt} ||= 0;
    if ($q{$_}{cnt}) {
        $q{$_}{avg} = $tot / $q{$_}{cnt};
    }
    $q{$_}{avg} ||= 0;
    $q{$_}{tot} ||= 0;
}

print "\n DONE\n Sorting... ";

my @srt_keys =  sort { $q{$a}{$sort_fld} <=> $q{$b}{$sort_fld} } keys 
+%q;
@srt_keys = @srt_keys[$#srt_keys-($show-1)..$#srt_keys];

print "\n";
print " Total     Cost      Avg    IDX  Query\n";
print "-------- -------- --------  ---  ------->\n";
foreach (@srt_keys) {
    printf("%8s ",sprintf("%.3f",$q{$_}{tot}));
    printf("%8s ",sprintf("%.3f",$q{$_}{cost}));
    printf("%8s ",sprintf("%.3f",$q{$_}{avg}));
    print " $q{$_}{scan} $_\n";
}


sub usage {
    print "@_\n" if (@_);
    print "plog [--sort=tot|cost|avg] [--show=1000] /path/to/logfile\n
+";
    print "\t--sort : sort results by tot(Total Time) cost(Max Cost) o
+r avg(Average Cost)\n";
    print "\t--show : show number of lines (default: 25)\n";

    exit();
}
[download]

Some Sample Output:

 
 Total     Cost      Avg    IDX  Query
-------- -------- --------  ---  ------->
 138.780    5.140    5.140  IDX  select description from products wher
+e sku = '142-1007'
 138.780    5.140    5.140  IDX  select sale_price from products where
+ sku = '142-1007'
 143.920    5.140    5.140  IDX  select sale_price from products where
+ sku = '140-1028'
 143.920    5.140    5.140  IDX  select thumb from products where sku 
+= '00024'
 143.920    5.140    5.140  IDX  select sku from products where sku = 
+'142-1009'
 143.920    5.140    5.140  IDX  select option_type from products wher
+e sku = '140-1028'
 149.060    5.140    5.140  IDX  select gift_cert from products where 
+sku = '140-1028'
 154.700    5.950    5.950  IDX  select * from options where code = '1
+42-1007'
 154.700    5.950    5.950  IDX  select * from options where code = '1
+12-9083'
 154.700    5.950    5.950  IDX  select * from options where code = '1
+40-1028'
 164.480    5.140    5.140  IDX  select description from products wher
+e sku = '140-1028'
 185.040    5.140    5.140  IDX  select sku from products where sku = 
+'142-1011'
 231.300    5.140    5.140  IDX  select sku from products where sku = 
+'142-1035'
 233.100    3.150    3.150  IDX  SELECT o_group,price FROM options whe
+re sku = '142-1035' and price != ''
 233.100    3.150    3.150  IDX  SELECT o_group,price FROM options whe
+re sku = '142-1030' and price != ''
 246.720    5.140    5.140  IDX  select sku from products where sku = 
+'gift-cert'
 267.280    5.140    5.140  IDX  select thumb from products where sku 
+= '112-9083'
 267.280    5.140    5.140  IDX  select thumb from products where sku 
+= '140-1028'
 267.280    5.140    5.140  IDX  select thumb from products where sku 
+= '142-1007'
 287.840    5.140    5.140  IDX  select sku from products where sku = 
+'00024'
 292.830   97.610   97.610  SEQ  select * from products
[download]

grep

XP matters not. Look at me. Judge me by my XP, do you?

Comment on PostgreSQL Query Performance Analysis Select or Download Code

Replies are listed 'Best First'.
Re: PostgreSQL Query Performance Analysis by aufflick (Deacon) on Nov 19, 2006 at 11:44 UTC
You may also be interested in http://pqa.projects.postgresql.org/ - I have found it incredibly useful over the past few years.	[reply]