Hi, all.
Postgres 8.4.4, quite often I have situation like this:
011-05-26 18:25:38.842 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SET LOG: duration: 0.029 ms statement: BEGIN; SET TRANSACTION
ISOLATION LEVEL READ COMMITTED
2011-05-26 18:25:38.843 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.259 ms statement: SELECT
2011-05-26 18:25:38.847 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 2.205 ms statement: SELECT
2011-05-26 18:25:38.850 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.185 ms statement: SELECT
2011-05-26 18:25:39.250 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.232 ms statement: SELECT
2011-05-26 18:25:39.252 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.289 ms statement: SELECT
2011-05-26 18:25:39.255 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.639 ms statement: SELECT
2011-05-26 18:25:39.257 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.135 ms statement: SELECT
2011-05-26 18:25:39.258 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
SELECT LOG: duration: 0.156 ms statement: SELECT
2011-05-26 18:25:51.624 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
COMMIT LOG: duration: 11159.202 ms statement: COMMIT
2011-05-26 18:26:05.788 CEST [16163] <ample@knjiz> [192.168.1.5(32431)]
COMMIT LOG: duration: 326.856 ms statement: COMMIT
This is a grep from a postgres log when I had logging of all statements
enabled. I did grep by the local pid (16163), and what I don't
understand is:
- why is first COMMIT taking 11 seconds, when there are only SELECTs in
the transaction? SELECTS don't call any user defined functions, just
plain reads from the tables.
- what is that second COMMIT? If I issue COMMIT without 'BEGIN'
shouldn't I get: "COMMIT WARNING: there is no transaction in progress"
Mario
