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

On Fri, Aug 26, 2005 at 02:27:04PM +0100, Aldor wrote:
> 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.

Perhaps you're overlooking the possibility that the first update
was part of a transaction that didn't commit until ~20 seconds after
the update was issued, and that the second update was started
sometime in between. Another possibility is that other transactions
were happening but weren't logged because their statements executed
in less time than the log_min_duration_statement setting (but the
transactions themselves might have lasted much longer). Marc, what
*is* the log_min_duration_statement setting?

Here's a hypothetical example that would account for the above log
entries, using T1, T2, and T3 for three different transactions (of
which only T2 and T3 are shown in the log excerpt, and then only
their long-lasting UPDATE statements):

14:53:29 T1 BEGIN
14:53:30 T1 UPDATE (completes immediately)
14:53:31 T2 BEGIN
14:53:32 T2 UPDATE (blocks because of T1's UPDATE)
14:53:33 T1 COMMIT (T2's UPDATE unblocks and is logged as taking 1192.789 ms)
14:53:40 T3 BEGIN
14:53:41 T3 UPDATE (blocks)
14:53:53 T2 COMMIT (T3's UPDATE unblocks and is logged as taking 12159.162 ms)

Depending on the application, a transaction lasting 20 seconds or
more might not be unreasonable (or it might indeed be unreasonable,
yet still happening). But Marc will have to investigate to see
what's really going on; I simply offer one possible explanation.

--
Michael Fuhr