[Pgpool-general] Different insert query order on nodes

[Karsten Düsterloh]

Tatsuo Ishii wrote:
>> - SELECT count(*)
>>     FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c
>>     WHERE d.adrelid = c.oid
>>       AND d.adsrc ~ 'nextval'
>>       AND c.relname = 'zaehler'
>>   (where does this query come from? pgpool?)
> 
> Yes, pgpool issues this query to check if the table has SERIAL column
> or not.

JFTR: all of our tables have a SERIAL column named 'id'.

> The reason why you see this is, you don't lock the target table to
> properly serialize access order between different sessions.  pgpool
> guarantees the SQL order is same among servers in *a* session but does
> not among sessions. To synchronize the SQL order among sessions LOCK
> is nessessary. You could use insert_lock or could issume explicit
> LOCK by yourself.

Ah, sorry, that's me snipping the log too much, then. :-(
- We do have set insert_lock=true from the very beginning.
- We do *not* send any /*NO INSERT LOCK*/ comments.
Hence, LOCKs do show up in the log.

The queries come from two different clients, hence we end up with two
different postgresql threads trying to use the table.
I extracted both relevant threads from both postgres logs below
(irrelevant internals anonymized, other threads removed):

Node 0:
> 2010-11-16 00:16:53.964 CET [11518] LOG:  duration: 0.020 ms  statement: BEGIN
> 2010-11-16 00:16:53.967 CET [11518] LOG:  duration: 0.240 ms  statement: SELECT XXX FROM zaehler WHERE XXX ORDER BY XXX;/*s04.powerkill*/;
> 2010-11-16 00:16:53.972 CET [11518] LOG:  duration: 0.088 ms  statement: SELECT now()
> 2010-11-16 00:16:53.988 CET [11518] LOG:  duration: 16.720 ms  statement: INSERT INTO "zaehler"("timestamp") SELECT "timestamptz"('2010-11-16 00:16:53.964797+01'::text) FROM "dslsessions" WHERE XXX
> 2010-11-16 00:16:57.461 CET [7478] LOG:  duration: 0.040 ms  statement: SET DateStyle TO 'ISO'
> 2010-11-16 00:16:57.464 CET [7478] LOG:  duration: 0.042 ms  statement: COMMIT
> 2010-11-16 00:16:57.465 CET [7478] LOG:  duration: 0.025 ms  statement: BEGIN
> 2010-11-16 00:16:57.468 CET [7478] LOG:  duration: 0.324 ms  statement: SELECT nextval('zaehler_id_seq') AS id;/*XXX*/;
> 2010-11-16 00:16:57.475 CET [7478] LOG:  duration: 0.981 ms  statement: SELECT count(*) FROM pg_catalog.pg_attrdef AS d, pg_catalog.pg_class AS c WHERE d.adrelid = c.oid AND d.adsrc ~ 'nextval' AND c.relname = 'zaehler'
> 2010-11-16 00:17:00.832 CET [11518] LOG:  duration: 0.370 ms  statement: COMMIT
> 2010-11-16 00:17:00.832 CET [7478] LOG:  duration: 3356.080 ms  statement: LOCK TABLE "zaehler" IN SHARE ROW EXCLUSIVE MODE
> 2010-11-16 00:17:00.833 CET [11518] LOG:  duration: 0.020 ms  statement: BEGIN
> 2010-11-16 00:17:00.834 CET [7478] LOG:  duration: 1.229 ms  statement: SELECT attname, coalesce(d.adsrc = 'now()' OR d.adsrc LIKE '%''now''::text%', false) FROM pg_catalog.pg_class c, pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_attrdef d ON (a.attrelid = d.adrelid AND a.attnum = d.adnum) WHERE c.oid = a.attrelid AND a.attnum >= 1 AND a.attisdropped = 'f' AND c.relname = 'zaehler' ORDER BY a.attnum
> 2010-11-16 00:17:00.835 CET [7478] LOG:  duration: 0.105 ms  statement: SELECT now()
> 2010-11-16 00:17:00.836 CET [7478] LOG:  duration: 0.734 ms  statement: INSERT INTO "zaehler"("typ", "id") VALUES ('XXX',15409713)
> 2010-11-16 00:17:00.838 CET [7478] LOG:  disconnection: session time: 0:00:08.722 user=XXX database=XXX host=XX port=59138

Node 1:
> 2010-11-16 00:16:54.006 CET [27555] LOG:  duration: 0.028 ms  statement: BEGIN
> 2010-11-16 00:16:57.503 CET [6648] LOG:  duration: 0.047 ms  statement: SET DateStyle TO 'ISO'
> 2010-11-16 00:16:57.505 CET [6648] LOG:  duration: 0.038 ms  statement: COMMIT
> 2010-11-16 00:16:57.507 CET [6648] LOG:  duration: 0.034 ms  statement: BEGIN
> 2010-11-16 00:16:57.510 CET [6648] LOG:  duration: 0.634 ms  statement: SELECT nextval('zaehler_id_seq') AS id;/*XXX*/;
> 2010-11-16 00:17:00.870 CET [27555] LOG:  duration: 6839.607 ms  statement: INSERT INTO "zaehler"("timestamp") SELECT "timestamptz"('2010-11-16 00:16:53.964797+01'::text) FROM "dslsessions" WHERE XXX
> 2010-11-16 00:17:00.872 CET [27555] LOG:  duration: 0.325 ms  statement: COMMIT
> 2010-11-16 00:17:00.874 CET [6648] LOG:  duration: 0.352 ms  statement: LOCK TABLE "zaehler" IN SHARE ROW EXCLUSIVE MODE
> 2010-11-16 00:17:00.874 CET [27555] LOG:  duration: 0.028 ms  statement: BEGIN
> 2010-11-16 00:17:00.878 CET [6648] ERROR:  duplicate key value violates unique constraint "zaehler_pkey"
> 2010-11-16 00:17:00.878 CET [6648] STATEMENT:  INSERT INTO "zaehler"("typ", "id") VALUES ('XXX',15409713)
> 2010-11-16 00:17:00.883 CET [6648] LOG:  disconnection: session time: 0:00:08.725 user=XXX database=XXX host=XX port=35759
> 2010-11-16 00:17:00.998 CET [27555] LOG:  unexpected EOF on client connection
> 2010-11-16 00:17:00.998 CET [27555] LOG:  disconnection: session time: 85:56:45.651 user=XXX database=XXX host=XXX port=33638

Interestingly enough, only the thread using nextval is locking -
but, afaict, too late in the second case?

The order of events on node 0 is that of pgpool's own log,
so it seems to me that insert_lock=true isn't quite working as expected?


Karsten