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

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';

20 seconds - 13 seconds (execution time) = 7 seconds

So it also happens when they are not close to each other.

The hint with the log_min_duration is a good idea.

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?
>