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

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

Michael Fuhr wrote:
> On Thu, Aug 25, 2005 at 01:55:08PM -0600, Michael Fuhr wrote:
>
>>Are the updates happening inside a transaction? Is it possible
>>that they're being blocked by other transactions that update the
>>same record around the same time and don't commit immediately?
>>I can duplicate the results you're seeing by doing that.
>
>
> As for why you don't see long durations with EXPLAIN ANALYZE, here's
> a possible explanation: "ordinary" updates of the same record might
> happen close together because that's how the application works, but
> by the time you run EXPLAIN ANALYZE no other transactions are updating
> that record so the update executes immediately.
>