Table of Contents

Overview

With Oracle we can enable session level trace and it makes sense that we can do the same thing with PostgreSQL Using DTrace we can attache ourselves to a session as so:

Tracing

Check the session

Check Session

jianhuiz=# select * from pg_stat_activity where usename=’jianhuiz’;
datid | datname | pid | usesysid | usename | application_name | client_addr | client_hostname | client_port | backend_start | xact_start | query_start | state_change | waiting | state | backend_xid | backend_xmin | query
——-+———-+——+———-+———-+——————+————-+—————–+————-+——————————-+——————————-+——————————-+——————————-+———+——–+————-+————–+———————————————————-
16384 | jianhuiz | 4139 | 16385 | jianhuiz | psql | | | -1 | 2015-04-15 17:06:43.916526-07 | 2015-04-15 17:11:53.436622-07 | 2015-04-15 17:11:53.436622-07 | 2015-04-15 17:11:53.436626-07 | f | active | | 1013 | select * from pg_stat_activity where usename=’jianhuiz’;
(1 row) 

Then we can attache to:

Attach to the session

root# ./query.d 4139
—– Ctrl_C to stop ——
select count(1) from foo; ends at 1429143285567982000
select count(1) from foo; starts at 1429143285556178000
select count(1) from foo; ends at 1429143293632244000
select count(1) from foo; starts at 1429143293631820000
select count(1) from foo; ends at 1429143296421384000
select count(1) from foo; starts at 1429143296420958000
select * from foo where i=10; ends at 1429143315062385000
select * from foo where i=10; starts at 1429143315059582000
select * from foo where i=20; ends at 1429143322032015000
select * from foo where i=20; starts at 1429143322031590000

Appendix

The script you can see below:

DTrace script

     #!/usr/sbin/dtrace -qs

    dtrace:::BEGIN
    {
    printf(” —– Ctrl_C to stop —— \n”);
    }

    postgresql$1:::query-start
    {
    @query_count[copyinstr(arg0)] = count();
    self->ts = walltimestamp;
    printf(” %60s starts at %30d \n”, copyinstr(arg0), self->ts);
    }

    postgresql$1:::query-done
    /self->ts/
    {
    self->te = walltimestamp;
    @query_time[copyinstr(arg0)] = sum(self->te – self->ts);
    printf(” %60s ends at %30d \n”, copyinstr(arg0), self->te);
    }

    dtrace:::END
    {
    printf(” —– Query Execution Count Summary —— \n”);
    printa(@query_count);
    printf(” —– Query Elapsed Time(ns) Summary —— \n”);
    printa(@query_time);
    }