Re: timing queries

Gavin Sherry wrote:
>
> On Tue, 29 Jan 2002, Christopher Kings-Lynne wrote:
>
> > Hi hackers,
> >
> > Is there any way of logging all queries and their duration in postgres? I
> > know you can log queries - but I can't see any way of logging durations.
>
> I discussed auditing in PostgreSQL 7.3. This would probably be a useful
> bit of data to include in the audit trail.

I use the following code snippet to extract slow queries from postgresql
log

It could be improved trivially to include also the query text -
currently it
just shows the start time and backend number.

#!/usr/bin/python

""
020118.10:05:11.879 [27337] ProcessQuery
020118.10:05:11.879 [27337] CommitTransactionCommand
020118.10:05:11.882 [27337] StartTransactionCommand
020118.10:05:11.882 [27337] query: SET DateStyle TO 'ISO';
"""

import sys,string,time

def ts2time(ts):
yr = int(ts[ 0: 2])
mo = int(ts[ 2: 4])
dy = int(ts[ 4: 6])
hr = int(ts[ 7: 9])
mi = int(ts[10:12])
se = int(ts[13:15])
hu = float(ts[15:])
return time.mktime((yr,mo,dy,hr,mi,se,0,0,0)) + hu

file = sys.stdin
lnr = 0
trx_dict = {}

SLOW = 1 # longer than this seconds is slow

while 1:
pos = file.tell()
line = file.readline()
if not line: break
lnr = lnr + 1
try:
ts, pid, inf = string.split(line)[:3]
# print '-', ts, pid, inf
ti = ts2time(ts)
except:
continue
try:
lastlnr, lastpos, lasttime, lastts, lastinf = trx_dict[pid]
# print '*',lastlnr, lastpos, lasttime, lastts, lastinf
# if lastinf == 'ProcessQuery\n':
# print ti-lasttime, lastlnr, lastpos, lastts, ts
if((ti-lasttime) > SLOW) and (lastinf == 'ProcessQuery'):
print ti-lasttime, lastlnr, lastpos, lastts, ts
except:
pass
if inf=='exit(0)\n':
del trx_dict[pid]
else:
trx_dict[pid] = (lnr,pos,ti,ts,inf)

for key in trx_dict.keys():
print trx_dict[key]