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.
