Hi,
On Fri, 3 Feb 2017 18:12:01 +0900
vinayak <pokale_vinayak...@lab.ntt.co.jp> wrote:
> Hello,
>
> I have tested some scenarios of inserting data into two foreign tables
> using postgres_fdw. All the test cases works fine except Test 5.
>
> In Test 5, I am expecting error as both the rows violates the
> constraint. But at the COMMIT time transaction does not give any error
> and it takes lock waiting for a transaction to finish.
I can reproduce this with REL9_6_STABLE.
The local process (application_name = psql) is waiting
"COMMIT TRANSACTION" for returning at pgfdw_xact_callback()
(in postgres_fdw/connection.c), and the remote process
(application_name = postgres_fdw) is stuck at _bt_doinsert()
with XactLockTableWait.
I attached the backtrace results.
I can't figure out yet why _bt_check_unique() returns without
calling ereport().
Regards,
>
> Please check the below tests:
>
> postgres=# CREATE SERVER loopback1 FOREIGN DATA WRAPPER POSTGRES_FDW
> OPTIONS (dbname 'postgres');
> CREATE SERVER
> postgres=# CREATE SERVER loopback2 FOREIGN DATA WRAPPER POSTGRES_FDW
> OPTIONS (dbname 'postgres');
> CREATE SERVER
> postgres=# CREATE USER MAPPING FOR CURRENT_USER SERVER loopback1;
> CREATE USER MAPPING
> postgres=# CREATE USER MAPPING FOR CURRENT_USER SERVER loopback2;
> CREATE USER MAPPING
>
> -- Here local table is created to refer as foreign table. The table has
> constraints which are deferred till end of transaction.
> -- This allows COMMIT time errors to occur by inserting data which
> violates constraints.
>
> postgres=# *CREATE TABLE lt(val int UNIQUE DEFERRABLE INITIALLY DEFERRED);*
> CREATE TABLE
> postgres=# CREATE FOREIGN TABLE ft1_lt (val int) SERVER loopback1
> OPTIONS (table_name 'lt');
> CREATE FOREIGN TABLE
> postgres=# CREATE FOREIGN TABLE ft2_lt (val int) SERVER loopback2
> OPTIONS (table_name 'lt');
> CREATE FOREIGN TABLE
>
> *Test 1: **
> **=======*
> In a transaction insert two rows one each to the two foreign tables and
> it works fine.
>
> postgres=# BEGIN;
> BEGIN
> postgres=# INSERT INTO ft1_lt VALUES (1);
> INSERT 0 1
> postgres=# INSERT INTO ft2_lt VALUES (3);
> INSERT 0 1
> postgres=# COMMIT;
> COMMIT
> postgres=# SELECT * FROM lt;
> val
> -----
> 1
> 3
> (2 rows)
>
> *Test 2:**
> **=======*
> In a transaction insert two rows one each to the two foreign tables.
> One of the rows violates the constraint and other not. At the time of
> COMMIT one of the foreign server violates the constraints so it return
> error. I think this is also expected behavior.
> postgres=# BEGIN;
> BEGIN
> postgres=# INSERT INTO ft1_lt VALUES (1); -- Violates constraint
> INSERT 0 1
> postgres=# INSERT INTO ft2_lt VALUES (4);
> INSERT 0 1
> postgres=# COMMIT;
> 2017-02-03 15:26:28.667 JST [3081] ERROR: duplicate key value violates
> unique constraint "lt_val_key"
> 2017-02-03 15:26:28.667 JST [3081] DETAIL: Key (val)=(1) already exists.
> 2017-02-03 15:26:28.667 JST [3081] STATEMENT: COMMIT TRANSACTION
> 2017-02-03 15:26:28.668 JST [3075] ERROR: duplicate key value violates
> unique constraint "lt_val_key"
> 2017-02-03 15:26:28.668 JST [3075] DETAIL: Key (val)=(1) already exists.
> 2017-02-03 15:26:28.668 JST [3075] CONTEXT: Remote SQL command: COMMIT
> TRANSACTION
> 2017-02-03 15:26:28.668 JST [3075] STATEMENT: COMMIT;
> 2017-02-03 15:26:28.668 JST [3081] WARNING: there is no transaction in
> progress
> WARNING: there is no transaction in progress
> ERROR: duplicate key value violates unique constraint "lt_val_key"
> DETAIL: Key (val)=(1) already exists.
> CONTEXT: Remote SQL command: COMMIT TRANSACTION
> postgres=#
> postgres=#
> postgres=# SELECT * FROM lt;
> val
> -----
> 1
> 3
> (2 rows)
>
> *Test 3:**
> **=======*
> In a transaction insert two rows one each to the two foreign tables.
> One of the rows violates the constraint and other not. At the time of
> COMMIT one of the foreign server violates the constraints so it return
> error. I think this is also expected behavior.
> postgres=# BEGIN;
> BEGIN
> postgres=# INSERT INTO ft1_lt VALUES (4);
> INSERT 0 1
> postgres=# INSERT INTO ft2_lt VALUES (3); -- Violates constraint
> INSERT 0 1
> postgres=# COMMIT;
> 2017-02-03 15:27:14.331 JST [3084] ERROR: duplicate key value violates
> unique constraint "lt_val_key"
> 2017-02-03 15:27:14.331 JST [3084] DETAIL: Key (val)=(3) already exists.
> 2017-02-03 15:27:14.331 JST [3084] STATEMENT: COMMIT TRANSACTION
> 2017-02-03 15:27:14.332 JST [3075] ERROR: duplicate key value violates
> unique constraint "lt_val_key"
> 2017-02-03 15:27:14.332 JST [3075] DETAIL: Key (val)=(3) already exists.
> 2017-02-03 15:27:14.332 JST [3075] CONTEXT: Remote SQL command: COMMIT
> TRANSACTION
> 2017-02-03 15:27:14.332 JST [3075] STATEMENT: COMMIT;
> 2017-02-03 15:27:14.332 JST [3084] WARNING: there is no transaction in
> progress
> WARNING: there is no transaction in progress
> ERROR: duplicate key value violates unique constraint "lt_val_key"
> DETAIL: Key (val)=(3) already exists.
> CONTEXT: Remote SQL command: COMMIT TRANSACTION
> postgres=# SELECT * FROM lt;
> val
> -----
> 1
> 3
> 4
> (3 rows)
> *Test 4:**
> **=======*
> In a transaction insert two rows one each to the two foreign tables.
> Both the rows violates the constraint. So at the time of COMMIT it
> returns error. I think this is also expected behavior.
>
> postgres=# BEGIN;
> BEGIN
> postgres=# INSERT INTO ft1_lt VALUES (1); -- Violates constraint
> INSERT 0 1
> postgres=# INSERT INTO ft2_lt VALUES (3); -- Violates constraint
> INSERT 0 1
> postgres=# COMMIT;
> 2017-02-03 15:29:18.857 JST [3081] ERROR: duplicate key value violates
> unique constraint "lt_val_key"
> 2017-02-03 15:29:18.857 JST [3081] DETAIL: Key (val)=(1) already exists.
> 2017-02-03 15:29:18.857 JST [3081] STATEMENT: COMMIT TRANSACTION
> 2017-02-03 15:29:18.858 JST [3075] ERROR: duplicate key value violates
> unique constraint "lt_val_key"
> 2017-02-03 15:29:18.858 JST [3075] DETAIL: Key (val)=(1) already exists.
> 2017-02-03 15:29:18.858 JST [3075] CONTEXT: Remote SQL command: COMMIT
> TRANSACTION
> 2017-02-03 15:29:18.858 JST [3075] STATEMENT: COMMIT;
> 2017-02-03 15:29:18.858 JST [3081] WARNING: there is no transaction in
> progress
> WARNING: there is no transaction in progress
> ERROR: duplicate key value violates unique constraint "lt_val_key"
> DETAIL: Key (val)=(1) already exists.
> CONTEXT: Remote SQL command: COMMIT TRANSACTION
> postgres=#
> postgres=# SELECT * FROM lt;
> val
> -----
> 1
> 3
> 4
> (3 rows)
> *Test 5:**
> **=======*
> In a transaction insert two rows one each to the two foreign tables.
> Both the rows violates the constraint. Here error is expected at COMMIT
> time but transaction does not give any error and it takes lock waiting
> for a transaction to finish.
> postgres=# BEGIN;
> BEGIN
> postgres=# INSERT INTO ft1_lt VALUES *(3)*; -- Violates constraint
> INSERT 0 1
> postgres=# INSERT INTO ft2_lt VALUES *(3)*; -- Violates constraint
> INSERT 0 1
> postgres=# COMMIT;
> .
> .
> .
>
> postgres=# select datid,datname,pid,wait_event_type,wait_event,query
> from pg_stat_activity;
> -[ RECORD 1
> ]---+---------------------------------------------------------------------------------
> datid | 13123
> datname | postgres
> pid | 3654
> wait_event_type | *Lock*
> wait_event | *transactionid*
> query | COMMIT TRANSACTION
>
> Note: Test 4 and Test 5 are same but in Test 5 both the foreign servers
> trying to insert the same data.
>
> Is this a expected behavior of postgres_fdw?
>
> Regards,
> Vinayak Pokale
>
> NTT Open Source Software Center
>
--
Yugo Nagata <nag...@sraoss.co.jp>
test=# select * from pg_stat_activity ;
-[ RECORD 1 ]----+---------------------------------
datid | 16384
datname | test
pid | 16626
usesysid | 10
usename | yugo-n
application_name | psql
client_addr |
client_hostname |
client_port | -1
backend_start | 2017-02-07 20:38:28.629562+09
xact_start | 2017-02-07 20:41:21.978381+09
query_start | 2017-02-07 20:41:29.118791+09
state_change | 2017-02-07 20:41:29.118796+09
wait_event_type |
wait_event |
state | active
backend_xid |
backend_xmin |
query | end;
-[ RECORD 2 ]----+---------------------------------
datid | 16384
datname | test
pid | 16796
usesysid | 10
usename | yugo-n
application_name | postgres_fdw
client_addr |
client_hostname |
client_port | -1
backend_start | 2017-02-07 20:38:49.664541+09
xact_start | 2017-02-07 20:41:25.25321+09
query_start | 2017-02-07 20:41:25.254316+09
state_change | 2017-02-07 20:41:25.254369+09
wait_event_type |
wait_event |
state | idle in transaction
backend_xid | 9088
backend_xmin | 9088
query | DEALLOCATE pgsql_fdw_prep_4
-[ RECORD 3 ]----+---------------------------------
datid | 16384
datname | test
pid | 16840
usesysid | 10
usename | yugo-n
application_name | postgres_fdw
client_addr |
client_hostname |
client_port | -1
backend_start | 2017-02-07 20:38:54.579606+09
xact_start | 2017-02-07 20:41:27.815021+09
query_start | 2017-02-07 20:41:29.118962+09
state_change | 2017-02-07 20:41:29.118966+09
wait_event_type | Lock
wait_event | transactionid
state | active
backend_xid | 9089
backend_xmin | 9088
query | COMMIT TRANSACTION
$ sudo gdb -p 16626
...
(gdb) bt
#0 0x00007f4116434fc0 in __poll_nocancel () at
../sysdeps/unix/syscall-template.S:81
#1 0x00007f410c3b82a6 in poll (__timeout=<optimized out>, __nfds=1,
__fds=0x7ffcb6936100) at /usr/include/x86_64-linux-gnu/bits/poll2.h:46
#2 pqSocketPoll (end_time=-1, forWrite=0, forRead=1, sock=<optimized out>) at
fe-misc.c:1134
#3 pqSocketCheck (conn=conn@entry=0x2481850, forRead=forRead@entry=1,
forWrite=forWrite@entry=0, end_time=end_time@entry=-1)
at fe-misc.c:1076
#4 0x00007f410c3b8b90 in pqWaitTimed (forRead=forRead@entry=1,
forWrite=forWrite@entry=0, conn=conn@entry=0x2481850,
finish_time=finish_time@entry=-1) at fe-misc.c:1008
#5 0x00007f410c3b8bdc in pqWait (forRead=forRead@entry=1,
forWrite=forWrite@entry=0, conn=conn@entry=0x2481850) at fe-misc.c:991
#6 0x00007f410c3b6e39 in PQgetResult (conn=conn@entry=0x2481850) at
fe-exec.c:1732
#7 0x00007f410c3b712e in PQexecFinish (conn=conn@entry=0x2481850) at
fe-exec.c:2018
#8 0x00007f410c3b71f2 in PQexec (conn=conn@entry=0x2481850,
query=query@entry=0x7f410c5e1041 "COMMIT TRANSACTION") at fe-exec.c:1852
#9 0x00007f410c5ded9f in do_sql_command (conn=0x2481850,
sql=sql@entry=0x7f410c5e1041 "COMMIT TRANSACTION") at connection.c:355
#10 0x00007f410c5df900 in pgfdw_xact_callback (event=XACT_EVENT_PRE_COMMIT,
arg=<optimized out>) at connection.c:624
#11 0x00000000004d33bd in CallXactCallbacks (event=XACT_EVENT_PRE_COMMIT) at
xact.c:3336
#12 CommitTransaction () at xact.c:1980
#13 0x00000000004d42a5 in CommitTransactionCommand () at xact.c:2881
#14 0x00000000006b9925 in finish_xact_command () at postgres.c:2457
#15 0x00000000006bd262 in finish_xact_command () at postgres.c:2448
#16 exec_simple_query (query_string=0x2440ea0 "end;") at postgres.c:1111
#17 PostgresMain (argc=<optimized out>, argv=argv@entry=0x23ed370,
dbname=0x23ed258 "test", username=<optimized out>) at postgres.c:4076
#18 0x000000000046b5fe in BackendRun (port=0x23eaf00) at postmaster.c:4271
#19 BackendStartup (port=0x23eaf00) at postmaster.c:3945
#20 ServerLoop () at postmaster.c:1701
#21 0x0000000000663246 in PostmasterMain (argc=argc@entry=1,
argv=argv@entry=0x23c3140) at postmaster.c:1309
#22 0x000000000046c0fe in main (argc=1, argv=0x23c3140) at main.c:228
$ sudo gdb -p 16840
...
(gdb) bt
#0 0x00007f41164429f3 in __epoll_wait_nocancel () at
../sysdeps/unix/syscall-template.S:81
#1 0x000000000069d926 in WaitEventSetWaitBlock (nevents=1,
occurred_events=0x7ffcb6935830, cur_timeout=-1, set=0x2494d40) at latch.c:990
#2 WaitEventSetWait (set=set@entry=0x2494d40, timeout=timeout@entry=-1,
occurred_events=occurred_events@entry=0x7ffcb6935830,
nevents=nevents@entry=1) at latch.c:944
#3 0x000000000069dd46 in WaitLatchOrSocket (latch=0x7f411532465c,
wakeEvents=wakeEvents@entry=1, sock=sock@entry=-1, timeout=-1,
timeout@entry=0) at latch.c:347
#4 0x000000000069dddd in WaitLatch (latch=<optimized out>,
wakeEvents=wakeEvents@entry=1, timeout=timeout@entry=0) at latch.c:302
#5 0x00000000006ac33b in ProcSleep (locallock=locallock@entry=0x23e9030,
lockMethodTable=lockMethodTable@entry=0x8f9960 <default_lockmethod>) at
proc.c:1221
#6 0x00000000006a7438 in WaitOnLock (locallock=locallock@entry=0x23e9030,
owner=owner@entry=0x23eeef8) at lock.c:1703
#7 0x00000000006a8a05 in LockAcquireExtended
(locktag=locktag@entry=0x7ffcb6935b60, lockmode=lockmode@entry=5,
sessionLock=sessionLock@entry=0 '\000', dontWait=dontWait@entry=0 '\000',
reportMemoryError=reportMemoryError@entry=1 '\001')
at lock.c:998
#8 0x00000000006a8d71 in LockAcquire (locktag=locktag@entry=0x7ffcb6935b60,
lockmode=lockmode@entry=5,
sessionLock=sessionLock@entry=0 '\000', dontWait=dontWait@entry=0 '\000')
at lock.c:688
#9 0x00000000006a6aae in XactLockTableWait (xid=xid@entry=9088,
rel=rel@entry=0x7f4116fdff18, ctid=ctid@entry=0x2494c70,
oper=oper@entry=XLTW_InsertIndex) at lmgr.c:587
#10 0x00000000004ad585 in _bt_doinsert (rel=rel@entry=0x7f4116fdff18,
itup=itup@entry=0x2494c70,
checkUnique=checkUnique@entry=UNIQUE_CHECK_EXISTING,
heapRel=heapRel@entry=0x7f4116fdc010) at nbtinsert.c:183
#11 0x00000000004afc81 in btinsert (rel=0x7f4116fdff18, values=<optimized out>,
isnull=<optimized out>, ht_ctid=0x7ffcb69363c4,
heapRel=0x7f4116fdc010, checkUnique=UNIQUE_CHECK_EXISTING) at nbtree.c:284
#12 0x000000000055ab2b in unique_key_recheck (fcinfo=<optimized out>) at
constraint.c:167
#13 0x000000000059a337 in ExecCallTriggerFunc
(trigdata=trigdata@entry=0x7ffcb6936400, tgindx=tgindx@entry=0,
finfo=finfo@entry=0x2490db0,
instr=instr@entry=0x0, per_tuple_context=per_tuple_context@entry=0x23f8048)
at trigger.c:1909
#14 0x000000000059b8a3 in AfterTriggerExecute (trigdesc=0x2490ca0,
trigdesc=0x2490ca0, trig_tuple_slot2=0x0, trig_tuple_slot1=0x0,
per_tuple_context=0x23f8048, instr=0x0, finfo=0x2490db0,
rel=0x7f4116fdc010, event=0x2492ec0) at trigger.c:3640
#15 afterTriggerInvokeEvents (events=events@entry=0xc027f0 <afterTriggers+16>,
firing_id=1, estate=0x2490a80, estate@entry=0x0,
delete_ok=delete_ok@entry=1 '\001') at trigger.c:3831
#16 0x000000000059fc80 in AfterTriggerFireDeferred () at trigger.c:4063
#17 0x00000000004d3385 in CommitTransaction () at xact.c:1969
#18 0x00000000004d42a5 in CommitTransactionCommand () at xact.c:2881
#19 0x00000000006b9925 in finish_xact_command () at postgres.c:2457
#20 0x00000000006bd262 in finish_xact_command () at postgres.c:2448
#21 exec_simple_query (query_string=0x2442f20 "COMMIT TRANSACTION") at
postgres.c:1111
#22 PostgresMain (argc=<optimized out>, argv=argv@entry=0x23ed378,
dbname=0x23ed258 "test", username=<optimized out>) at postgres.c:4076
#23 0x000000000046b5fe in BackendRun (port=0x23eaf00) at postmaster.c:4271
#24 BackendStartup (port=0x23eaf00) at postmaster.c:3945
#25 ServerLoop () at postmaster.c:1701
#26 0x0000000000663246 in PostmasterMain (argc=argc@entry=1,
argv=argv@entry=0x23c3140) at postmaster.c:1309
#27 0x000000000046c0fe in main (argc=1, argv=0x23c3140) at main.c:228
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
