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:
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:
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:
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:
Now, I generated a log file using the query:
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:
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.
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.