Skip site navigation (1) Skip section navigation (2)

Re: What is syslog:duration reporting ... ?

From: "Marc G(dot) Fournier" <scrappy(at)postgresql(dot)org>
To: Michael Fuhr <mike(at)fuhr(dot)org>
Cc: Aldor <an(at)mediaroot(dot)de>,"Marc G(dot) Fournier" <scrappy(at)postgresql(dot)org>,pgsql-admin(at)postgresql(dot)org
Subject: Re: What is syslog:duration reporting ... ?
Date: 2005-08-26 01:39:38
Message-ID: 20050825223750.E1044@ganymede.hub.org (view raw or flat)
Thread:
Lists: pgsql-admin
On Thu, 25 Aug 2005, Michael Fuhr wrote:

> On Fri, Aug 26, 2005 at 12:50:29AM +0100, Aldor wrote:
>> Aug 25 14:53:32 forgehouse-s1 postgres[23721]: [2-1] LOG:  duration:
>> 567.559 ms  statement: UPDATE session SET hit_time=now() WHERE
>> md5='7537b74eab488de54d6e0167d1919207';
>> Aug 25 14:53:32 forgehouse-s1 postgres[23722]: [2-1] LOG:  duration:
>> 565.966 ms  statement: UPDATE session SET hit_time=now() WHERE
>> md5='d84613009a95296fb511c2cb051ad618';
>> Aug 25 14:53:33 forgehouse-s1 postgres[23723]: [2-1] LOG:  duration:
>> 1192.789 ms  statement: UPDATE session SET hit_time=now() WHERE
>> md5='d84613009a95296fb511c2cb051ad618';
>> Aug 25 14:53:53 forgehouse-s1 postgres[23727]: [2-1] LOG:  duration:
>> 12159.162 ms  statement: UPDATE session SET hit_time=now() WHERE
>> md5='d84613009a95296fb511c2cb051ad618';
>> Aug 25 14:53:54 forgehouse-s1 postgres[23728]: [2-1] LOG:  duration:
>> 3283.185 ms  statement: UPDATE session SET hit_time=now() WHERE
>> md5='7537b74eab488de54d6e0167d1919207';
>> Aug 25 14:53:57 forgehouse-s1 postgres[23729]: [2-1] LOG:  duration:
>> 2116.516 ms  statement: UPDATE session SET hit_time=now() WHERE
>> md5='7537b74eab488de54d6e0167d1919207';
>>
>> Take a look to the timestamps... they are not really close to each other...
>
> Eh?  The timestamps show that the updates *are* close to each other.
> What we don't know is whether this log excerpt shows all statements
> that were executed during its time frame.  It might have been grep'ed
> from the full log file, or the log_min_duration_statement setting
> might be such that only statements lasting more than a certain
> amount of time are logged and we're not seeing similar updates that
> happened quickly, nor when any of the updates were committed.
>
> Marc, does my hypothesis of updates being blocked by other transactions
> sound plausible in your environment?  How complete a log did you
> post -- is it everything, or are there other statements that you
> omitted or that weren't logged because of the log_min_duration_statement
> setting?

I'm working on it from that perspective ... apparently, there has been no 
changes to teh database, only the application ... the weird thing is that 
the application/database on teh development server (much less powerful) 
isn't exhibiting the same problems, so I'm thinking there has to be 
somethign slightly different between the two that they aren't thinking of 
that they've made ...

Going to have to do a code review next, see if they've maybe thrown in a 
TRANSACTION wouldn't realizing/thinking of it :(

Thanks ...


----
Marc G. Fournier           Hub.Org Networking Services (http://www.hub.org)
Email: scrappy(at)hub(dot)org           Yahoo!: yscrappy              ICQ: 7615664

In response to

pgsql-admin by date

Next:From: Michael FuhrDate: 2005-08-26 02:47:44
Subject: Re: pgcrypto regression test: how can I change the port?
Previous:From: Michael FuhrDate: 2005-08-26 01:31:21
Subject: Re: What is syslog:duration reporting ... ?

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group