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
