[Pgpool-general] Different insert query order on nodes

Mon Nov 15 10:54:52 UTC 2010

Hi!

We're running pgpool-II 2.3.3 with two Postgresql 8.3.11 nodes.
Certain tables sport an 'id' field, tied to a SEQUENCE as the default
value. INSERT queries for these tables come in two flavours:
- read next id from SEQUENCE and INSERT with that id explicitly set
- INSERT without setting the id, let Postgresql set it automatically

Two weeks ago, out second node got degenerated for a "duplicate key"
backend mismatch violation, because the order of INSERTs was different
on the backend nodes!

pgpool:
 - INSERT with id ...68
 - INSERT without id
 - INSERT with id ...70

node0:
 - INSERT with id ...68
 - INSERT without id => 69
 - INSERT with id ...70
 - INSERT with id ...71

node1:
 - INSERT with id ...68
 - INSERT with id ...70
 - INSERT with id ...71
 - INSERT without id => ERROR!

This is rather worrisome - any ideas what might have caused that?

Real logs (sensitive data anonymized, otherwise intact):

- pgpool.log:
2010-11-01T00:01:36.000+01:00 pg1 pgpool: LOG:   pid 12242: SimpleQuery:
Error or notice message from backend: : DB node id: 1 backend pid: 27451
statement:
INSERT INTO "zaehler"("timestamp") SELECT "timestamptz"('2010-11-01
00:01:34.300484+01'::text)  FROM "dslsessions" WHERE  XXX;
 message: ERROR:  duplicate key value violates unique constraint
"zaehler_id_idx"
2010-11-01T00:01:36.000+01:00 pg1 pgpool:
2010-11-01T00:01:36.000+01:00 pg1 pgpool: ERROR: pid 12242:
read_kind_from_backend: 1 th kind E does not match with master or
majority connection kind C
2010-11-01T00:01:36.000+01:00 pg1 pgpool: ERROR: pid 12242: kind
mismatch among backends. Possible last query was: "INSERT INTO
"zaehler"("timestamp") SELECT "timestamptz"('2010-11-01
00:01:34.300484+01'::text)  FROM "dslsessions" WHERE  XXX;" kind details
are: 0[C] 1[E: ERROR:  duplicate key value violates unique constraint
"zaehler_id_idx"
2010-11-01T00:01:36.000+01:00 pg1 pgpool: ]
2010-11-01T00:01:36.000+01:00 pg1 pgpool: LOG:   pid 12242:
notice_backend_error: 1 fail over request from pid 12242
2010-11-01T00:01:36.000+01:00 pg1 pgpool: LOG:   pid 19627: starting
degeneration. shutdown host XXX(5433)
2010-11-01T00:01:36.000+01:00 pg1 pgpool: LOG:   pid 19627: execute
command: ./sendalarm.sh alarm "pgpool.fail.node1" nok "Fail=XXX:5433
New_Master_Node=0";
2010-11-01T00:01:36.000+01:00 pg1 pgpool: LOG:   pid 19627:
failover_handler: set new master node: 0
2010-11-01T00:01:36.000+01:00 pg1 pgpool: LOG:   pid 19627: failover
done. shutdown host XXX(5433)

- Node 0:
2010-11-01 00:01:34.108 CET [26244] LOG:  duration: 0.611 ms  statement:
INSERT INTO "zaehler"("timestamp", "id") VALUES
("timestamptz"('2010-11-01 00:01:35.094187+01'::text),2681,15310168)
2010-11-01 00:01:34.128 CET [26244] LOG:  duration: 14.814 ms
statement: COMMIT
2010-11-01 00:01:34.129 CET [26244] LOG:  duration: 0.019 ms  statement:
BEGIN
2010-11-01 00:01:34.351 CET [12621] LOG:  duration: 0.064 ms  statement:
SELECT now()
2010-11-01 00:01:34.352 CET [12621] LOG:  duration: 1.487 ms  statement:
INSERT INTO "zaehler"("timestamp") SELECT "timestamptz"('2010-11-01
00:01:34.300484+01'::text) FROM "dslsessions" WHERE XXX
2010-11-01 00:01:35.088 CET [26209] LOG:  duration: 0.044 ms  statement:
SET DateStyle TO 'ISO'
2010-11-01 00:01:35.092 CET [26209] LOG:  duration: 0.042 ms  statement:
COMMIT
2010-11-01 00:01:35.094 CET [26209] LOG:  duration: 0.025 ms  statement:
BEGIN
2010-11-01 00:01:35.097 CET [26209] LOG:  duration: 0.100 ms  statement:
SELECT nextval('zaehler_id_seq') AS id;/*XXX*/;
2010-11-01 00:01:35.105 CET [26209] LOG:  duration: 0.063 ms  statement:
SELECT now()
2010-11-01 00:01:35.106 CET [26209] LOG:  duration: 0.272 ms  statement:
INSERT INTO "zaehler"("timestamp", "id") VALUES
("timestamptz"('2010-11-01 00:01:35.094187+01'::text),15310170)
2010-11-01 00:01:35.120 CET [26209] LOG:  duration: 1.337 ms  statement:
COMMIT
2010-11-01 00:01:35.121 CET [26209] LOG:  duration: 0.022 ms  statement:
BEGIN
2010-11-01 00:01:35.180 CET [26244] LOG:  duration: 0.033 ms  statement: END
2010-11-01 00:01:35.181 CET [26244] LOG:  duration: 0.061 ms  statement:
 DISCARD ALL
2010-11-01 00:01:35.238 CET [26209] LOG:  duration: 0.026 ms  statement:
SET DateStyle TO 'ISO'
2010-11-01 00:01:35.242 CET [26209] LOG:  duration: 0.022 ms  statement:
COMMIT
2010-11-01 00:01:35.243 CET [26209] LOG:  duration: 0.026 ms  statement:
BEGIN
2010-11-01 00:01:35.246 CET [26209] LOG:  duration: 0.073 ms  statement:
SELECT nextval('zaehler_id_seq') AS id;/*XXX*/;
2010-11-01 00:01:35.254 CET [26209] LOG:  duration: 0.057 ms  statement:
SELECT now()
2010-11-01 00:01:35.254 CET [26209] LOG:  duration: 0.238 ms  statement:
INSERT INTO "zaehler"("timestamp","id") VALUES
("timestamptz"('2010-11-01 00:01:35.243617+01'::text),15310171)
2010-11-01 00:01:35.269 CET [26209] LOG:  duration: 3.709 ms  statement:
COMMIT
2010-11-01 00:01:35.271 CET [26209] LOG:  duration: 0.022 ms  statement:
BEGIN
2010-11-01 00:01:36.736 CET [25974] LOG:  disconnection: session time:
0:02:15.848 user=XXX database=XXX host=XXX port=41708
...several more disconnects due to degeneration...

- Node 1:
2010-11-01 00:01:34.084 CET [21884] LOG:  duration: 0.790 ms  statement:
INSERT INTO "zaehler"("timestamp", "id") VALUES
("timestamptz"('2010-11-01 00:01:34.092686+01'::text),15310168)
2010-11-01 00:01:34.087 CET [21884] LOG:  duration: 0.328 ms  statement:
COMMIT
2010-11-01 00:01:34.104 CET [21884] LOG:  duration: 0.035 ms  statement:
BEGIN
2010-11-01 00:01:34.271 CET [27451] LOG:  duration: 0.045 ms  statement:
SET DateStyle TO 'ISO'
2010-11-01 00:01:34.273 CET [27451] LOG:  duration: 0.039 ms  statement:
COMMIT
2010-11-01 00:01:34.275 CET [27451] LOG:  duration: 0.030 ms  statement:
BEGIN
2010-11-01 00:01:35.064 CET [21860] LOG:  duration: 0.051 ms  statement:
SET DateStyle TO 'ISO'
2010-11-01 00:01:35.066 CET [21860] LOG:  duration: 0.038 ms  statement:
COMMIT
2010-11-01 00:01:35.069 CET [21860] LOG:  duration: 0.034 ms  statement:
BEGIN
2010-11-01 00:01:35.073 CET [21860] LOG:  duration: 0.117 ms  statement:
SELECT nextval('zaehler_id_seq') AS id;/*XXX*/;
2010-11-01 00:01:35.082 CET [21860] LOG:  duration: 0.400 ms  statement:
INSERT INTO "zaehler"("timestamp", "id") VALUES
("timestamptz"('2010-11-01 00:01:35.094187+01'::text),15310170)
2010-11-01 00:01:35.092 CET [21860] LOG:  duration: 8.237 ms  statement:
COMMIT
2010-11-01 00:01:35.097 CET [21860] LOG:  duration: 0.031 ms  statement:
BEGIN
2010-11-01 00:01:35.154 CET [21884] LOG:  duration: 0.040 ms  statement: END
2010-11-01 00:01:35.156 CET [21884] LOG:  duration: 0.086 ms  statement:
 DISCARD ALL
2010-11-01 00:01:35.213 CET [21860] LOG:  duration: 0.034 ms  statement:
SET DateStyle TO 'ISO'
2010-11-01 00:01:35.216 CET [21860] LOG:  duration: 0.031 ms  statement:
COMMIT
2010-11-01 00:01:35.219 CET [21860] LOG:  duration: 0.027 ms  statement:
BEGIN
2010-11-01 00:01:35.222 CET [21860] LOG:  duration: 0.091 ms  statement:
SELECT nextval('zaehler_id_seq') AS id;/*XXX*/;
2010-11-01 00:01:35.230 CET [21860] LOG:  duration: 0.294 ms  statement:
INSERT INTO "zaehler"("timestamp", "id") VALUES
("timestamptz"('2010-11-01 00:01:35.243617+01'::text),15310171)
2010-11-01 00:01:35.240 CET [21860] LOG:  duration: 7.248 ms  statement:
COMMIT
2010-11-01 00:01:35.246 CET [21860] LOG:  duration: 0.031 ms  statement:
BEGIN
2010-11-01 00:01:36.710 CET [27451] ERROR:  duplicate key value violates
unique constraint "zaehler_id_idx"
2010-11-01 00:01:36.710 CET [27451] STATEMENT:  INSERT INTO
"zaehler"("timestamp") SELECT "timestamptz"('2010-11-01 00:01:
34.300484+01'::text) FROM "dslsessions" WHERE XXX
2010-11-01 00:01:36.711 CET [27451] LOG:  disconnection: session time:
326:01:11.113 user=XXX database=XXX host=XXX port=40242

Yours,

Karsten