Friday, October 11, 2013

Generate pgbadger report from minimal information

0 comments
I was working for a client who was experiencing slowness in his application and I need to find out if it was database related.
He provided me some data of query logs in a table generated by application as follows:

2012-11-12 06:29:51.982 PST 11834.483 SELECT col1, id FROM table1
2012-11-12 08:09:30.066 PST 339736.318 SELECT id, event_type_cd, event_ts, source_id         2012-11-12 11:59:53.900 PST 54808.922 SELECT id, * FROM report re WHERE ...
2012-11-12 12:03:41.625 PST 53794.590 SELECT id, * FROM report re WHERE ...

He had two large log files only which they got from their Postgresql 8.4.

First thing, I was looking for pgbadger or pgfoiune report which they had not and it made my life difficult.
I, then, decided to load the logs information into a table so that I can query my own.
I created a table:

\d logtab
                   Table "public.logtab"
      Column       |            Type             | Modifiers
-------------------+-----------------------------+-----------
 t_stamp           | timestamp without time zone |
 execution_time_ms | double precision            |
 query             | text                        | 

Then, I restored log data in logtable using COPY command.

There was log from Feb 2012 to till date.

To find out the exact time of slowness, I planned to generate a pgbadger report using the above information.
Usually, pgbadger wants log_line_prefix to be "log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d '".
And log file looks like:
2013-09-01 00:00:57 EDT [0010]: [10-1] db=dbname,user=postgres LOG: duration: 23.755 ms statement:  SELECT relname,indexrelname,schemaname,pg_relation_size('"'||schemaname||'"."'||indexrelname||'"') as rawsize,idx_scan, idx_tup_read, idx_tup_fetch from pg_stat_user_indexes;

Here, I had
%t = t_stamp = 2013-09-01 00:00:57 EDT
Duration = execution_time_ms = 23.755
Statement = query =  SELECT relname,indexrelname,schemaname,pg_relation_size('"'||schemaname||'"."'||indexrelname||'"') as rawsize,idx_scan, idx_tup_read, idx_tup_fetch from pg_stat_user_indexes;

So, I planned to generate %p - the process ID and %l - the session number using the following query:

select t_stamp || ' EDT [' ||
lpad( (row_number() OVER (ORDER BY t_stamp))::text,4,'0') || ']: ' ||
'['|| (row_number() OVER ( PARTITION BY substr(t_stamp::text,1,10) ORDER BY t_stamp))::text || '-1] db=dbname,user=postgres '||
'LOG:  duration: '|| execution_time_ms::text||' ms  statement: '||
query
 as c
from logtab as a  
where t_stamp >= '2013-09-01 00:00:00'
limit 100

Now, I generated a log file using the query:

copy
(select t_stamp || ' EDT [' ||
lpad( (row_number() OVER (ORDER BY t_stamp))::text,4,'0') || ']: ' ||
'['|| (row_number() OVER ( PARTITION BY substr(t_stamp::text,1,10) ORDER BY t_stamp))::text || '-1] db=dbname,user=postgres '||
'LOG:  duration: '|| execution_time_ms::text||' ms  statement: '||
query
 as c
from logtab as a  
where t_stamp >= '2013-05-01 00:00:00'
) to '/tmp/pglog.log'

The next step is to generate a pgbadger report.
I got it from http://dalibo.github.io/pgbadger/index.html, installed in my machine and generated report using:

pgbadger /tmp/pglog.log  -o /tmp/pgbadger.html

I got the pgbadger report with graphs for example average queries duration graph

From here we find out a the dates where the db worked slowly and found the exact date where the client pushed some new codes in their application which modified db schema.









Leave a Reply

Labels