Обсуждение: deadlock of lock-waits (on transaction and on tuple) using same update statement
deadlock of lock-waits (on transaction and on tuple) using same update statement
От
Andrej Vanek
Дата:
Hi,
My application runs many concurrent sessions with the same transaction code starting with an update statement.
I would expect locking and serialization of those transactions. But I get unexpected deadlocks.
As opposed to http://momjian.us/main/writings/pgsql/locking.pdf page 84 (waits for ShareLock on transaction only)
my case looks different:
ERROR: deadlock detected
DETAIL: Process 6973 waits for ShareLock on transaction 318396117; blocked by process 11039.
^^^^^^^^^^^^^^
Process 11039 waits for ExclusiveLock on tuple (4,9) of relation 16416 of database 16417; blocked by process 6973.
^^^^^^^^^^^^^^
Process 6973: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
Process 11039: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
Is this an expected behaviour, or maybe a bug?
Thanks, Andrej
---------------------------details
case is reproducible via my application.
I was unable to reproduce it via psql sessions (locking worked fine).
I was unable to reproduce it via shell for loop with psql sessions running same transactions (100 loops in 10 terminal windows).
postgres version: PostgreSQL 9.3.4 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.7 20120313 (Red Hat 4.4.7-4), 64-bit
postgres log:
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.021 ms execute S_2: ROLLBACK
2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 7.965 ms execute S_3: COMMIT
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.015 ms bind S_1: BEGIN
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.008 ms execute S_1: BEGIN
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.122 ms parse <unnamed>: select * from AELDATA_READ_VIEW where (SBO_GRP = '000015')
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.317 ms bind <unnamed>: select * from AELDATA_READ_VIEW where (SBO_GRP = '000015')
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.041 ms execute <unnamed>: select * from AELDATA_READ_VIEW where (SBO_GRP = '000015')
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.017 ms bind S_2: ROLLBACK
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.022 ms execute S_2: ROLLBACK
2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.017 ms bind S_1: BEGIN
2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.010 ms execute S_1: BEGIN
2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.083 ms parse <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.016 ms bind S_1: BEGIN
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.013 ms execute S_1: BEGIN
2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.174 ms bind <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.096 ms parse <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.152 ms bind <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[6973] LOG: process 6973 detected deadlock while waiting for ShareLock on transaction 318396117 after 1000.060 ms
2014-09-22 22:21:55 CEST:yy@xx1:[6973] STATEMENT: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: process 11039 still waiting for ExclusiveLock on tuple (4,9) of relation 16416 of database 16417 after 1000.038 ms
2014-09-22 22:21:55 CEST:yy@xx1:[11039] STATEMENT: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[6973] ERROR: deadlock detected
2014-09-22 22:21:55 CEST:yy@xx1:[6973] DETAIL: Process 6973 waits for ShareLock on transaction 318396117; blocked by process 11039.
Process 11039 waits for ExclusiveLock on tuple (4,9) of relation 16416 of database 16417; blocked by process 6973.
Process 6973: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
Process 11039: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[6973] HINT: See server log for query details.
2014-09-22 22:21:55 CEST:yy@xx1:[6973] STATEMENT: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: process 11039 acquired ExclusiveLock on tuple (4,9) of relation 16416 of database 16417 after 1000.224 ms
2014-09-22 22:21:55 CEST:yy@xx1:[11039] STATEMENT: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 1004.543 ms execute <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.084 ms parse <unnamed>: select AEL_ID, SBO_GRP, LOCK_KEY from AELDATA where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.128 ms bind <unnamed>: select AEL_ID, SBO_GRP, LOCK_KEY from AELDATA where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.048 ms execute <unnamed>: select AEL_ID, SBO_GRP, LOCK_KEY from AELDATA where (SBO_GRP = '000015')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.122 ms parse <unnamed>: select NUM_OF_SBO, AEL_ID, SBO_GRP, SBO_KEY, STATE, PROGRESS, LOCK_KEY from AEL_XT_DATA_VIEW where (AEL_ID = 15 and EN_NAME = 'H103')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.356 ms bind <unnamed>: select NUM_OF_SBO, AEL_ID, SBO_GRP, SBO_KEY, STATE, PROGRESS, LOCK_KEY from AEL_XT_DATA_VIEW where (AEL_ID = 15 and EN_NAME = 'H103')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.073 ms execute <unnamed>: select NUM_OF_SBO, AEL_ID, SBO_GRP, SBO_KEY, STATE, PROGRESS, LOCK_KEY from AEL_XT_DATA_VIEW where (AEL_ID = 15 and EN_NAME = 'H103')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.096 ms parse <unnamed>: update AEL_XT_DATA set NUM_OF_SBO = 31121, STATE = 0, PROGRESS = 0, LOCK_KEY = null where (AEL_ID = 15 and EN_NAME = 'H103')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.199 ms bind <unnamed>: update AEL_XT_DATA set NUM_OF_SBO = 31121, STATE = 0, PROGRESS = 0, LOCK_KEY = null where (AEL_ID = 15 and EN_NAME = 'H103')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.092 ms execute <unnamed>: update AEL_XT_DATA set NUM_OF_SBO = 31121, STATE = 0, PROGRESS = 0, LOCK_KEY = null where (AEL_ID = 15 and EN_NAME = 'H103')
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.011 ms bind S_3: COMMIT
2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 7.775 ms execute S_3: COMMIT
2014-09-22 22:21:55 CEST:yy@xx1:[6973] LOG: duration: 0.014 ms bind S_2: ROLLBACK
2014-09-22 22:21:55 CEST:yy@xx1:[6973] LOG: duration: 0.014 ms execute S_2: ROLLBACK
affected data structures:
xx1=> \d aeldata
Table "public.aeldata"
Column | Type | Modifiers
----------------+------------------------+-----------
ael_id | numeric(10,0) | not null
sbo_grp | character varying(6) | not null
ael_name | character varying(30) | not null
remark | character varying(200) |
mc_id | numeric(4,0) |
owner | character varying(30) |
lock_key | numeric(10,0) |
lock_column | numeric(1,0) |
default_ael | numeric(1,0) |
Indexes:
"aeldata_pkey" PRIMARY KEY, btree (ael_id)
"default_ael_uk" UNIQUE CONSTRAINT, btree (default_ael)
"uk_ael_name" UNIQUE CONSTRAINT, btree (ael_name)
"uk_sbo_grp" UNIQUE CONSTRAINT, btree (sbo_grp)
"idx_aeldata_mcid" btree (mc_id)
Foreign-key constraints:
"ael_mc_id_fk" FOREIGN KEY (mc_id) REFERENCES mcdata(mc_id)
Referenced by:
TABLE "alarm_table" CONSTRAINT "alarm_table_ael_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ul_bulk_operation_data" CONSTRAINT "bulk_operation_data_ael_id_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ul_job_data" CONSTRAINT "fkey_ael_id" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ael_groups" CONSTRAINT "fkey_lg_ael_id" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ael_esd" CONSTRAINT "ael_esd_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ael_que" CONSTRAINT "ael_que_aelid_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ael_awai" CONSTRAINT "ael_awai_aelid_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ael_xt_data" CONSTRAINT "ael_id_key" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
TABLE "ael_noacc" CONSTRAINT "ael_noacc_ael_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id) ON DELETE CASCADE
TABLE "ael_traffic" CONSTRAINT "ael_traffic_ael_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id) ON DELETE CASCADE
TABLE "ul_recs" CONSTRAINT "ul_recs_ael_fk" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
xx1=> \d+ ael_xt_data_view
View "public.ael_xt_data_view"
Column | Type | Modifiers | Storage | Description
-------------+-------------------------+-----------+----------+-------------
sbo_grp | character varying(6) | | extended |
ael_name | character varying(30) | | extended |
en_name | character varying(40) | | extended |
sbo_key | character varying(20) | | extended |
num_of_sbo | numeric | | main |
ael_en_lock | numeric(10,0) | | main |
ael_state | numeric(3,0) | | main |
job_id | character varying(32) | | extended |
state | numeric(1,0) | | main |
progress | numeric(1,0) | | main |
lock_key | numeric(10,0) | | main |
ael_id | numeric(10,0) | | main |
View definition:
SELECT aeldata.sbo_grp,
aeldata.ael_name,
ael_xt_data.en_name,
ael_xt_data.sbo_key,
ael_xt_data.num_of_sbo,
ael_xt_data.ael_en_lock,
ael_xt_data.ael_state,
ael_xt_data.job_id,
ael_xt_data.state,
ael_xt_data.progress,
ael_xt_data.lock_key,
ael_xt_data.ael_id
FROM ael_xt_data,
aeldata
WHERE aeldata.ael_id = ael_xt_data.ael_id;
Rules:
ael_xt_data_view_ir AS
ON INSERT TO ael_xt_data_view DO INSTEAD INSERT INTO ael_xt_data (en_name, sbo_key, ael_id, num_of_sbo, ael_en_lock, ael_state, job_id)
VALUES (new.en_name, new.sbo_key, gf_proc.get_aelid_sbo(new.sbo_grp), new.num_of_sbo, new.ael_en_lock, new.ael_state, new.job_id)
ael_xt_data_view_ud AS
ON DELETE TO ael_xt_data_view DO INSTEAD DELETE FROM ael_xt_data
WHERE ael_xt_data.ael_id = gf_proc.get_aelid_sbo(old.sbo_grp) AND ael_xt_data.en_name::text = old.en_name::text
ael_xt_data_view_ur AS
ON UPDATE TO ael_xt_data_view DO INSTEAD UPDATE ael_xt_data SET en_name = new.en_name, sbo_key = new.sbo_key, ael_id = gf_proc.get_aelid_sbo(new.sbo_grp), num_of_sbo = new.num_of_sbo, ael_en_lock = new.ael_en_lock, ael_state = new.ael_state, job_id = new.job_id
WHERE ael_xt_data.ael_id = gf_proc.get_aelid_sbo(old.sbo_grp) AND ael_xt_data.en_name::text = old.en_name::text
xx1=> \d ael_xt_data
Table "public.ael_xt_data"
Column | Type | Modifiers
-------------+-------------------------+--------------
ael_id | numeric(10,0) | not null
en_name | character varying(40) | not null
sbo_key | character varying(20) |
num_of_sbo | numeric |
ael_en_lock | numeric(10,0) |
ael_state | numeric(3,0) | default (-8)
job_id | character varying(32) |
state | numeric(1,0) |
progress | numeric(1,0) |
lock_key | numeric(10,0) |
Indexes:
"ael_xt_data_key" PRIMARY KEY, btree (ael_id, en_name)
"idx_aelxtdata_nename" btree (en_name)
Foreign-key constraints:
"ael_ad_en_name" FOREIGN KEY (en_name) REFERENCES en_names(en_name)
"ael_id_key" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id)
On Tue, 23 Sep 2014 20:00:27 +0200 Andrej Vanek <andrej.vanek.sk@gmail.com> wrote: > Hi, > > My application runs many concurrent sessions with the same transaction code > starting with an update statement. > I would expect locking and serialization of those transactions. But I get > unexpected deadlocks. > As opposed to *http://momjian.us/main/writings/pgsql/locking.pdf > <http://momjian.us/main/writings/pgsql/locking.pdf>* page 84 (waits for > ShareLock on transaction only) > my case looks different: > > ERROR: deadlock detected > DETAIL: Process 6973 waits for ShareLock on transaction 318396117; blocked > by process 11039. > ^^^^^^^^^^^^^^ > Process 11039 waits for ExclusiveLock on tuple (4,9) of relation > 16416 of database 16417; blocked by process 6973. > ^^^^^^^^^^^^^^ > Process 6973: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = > '000015') > Process 11039: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = > '000015') > > Is this an expected behaviour, or maybe a bug? This is most often caused by something earlier in the transactions setting up the situation, then these two statements actual causing the deadlock to be detectable. To help further, we're probably going to need all of the statements in each transaction, but if you look at them yourself in their entirety, it may become obvious what the problem is. > > Thanks, Andrej > ---------------------------details > case is reproducible via my application. > I was unable to reproduce it via psql sessions (locking worked fine). > I was unable to reproduce it via shell for loop with psql sessions running > same transactions (100 loops in 10 terminal windows). > > postgres version: PostgreSQL 9.3.4 on x86_64-unknown-linux-gnu, compiled by > gcc (GCC) 4.4.7 20120313 (Red Hat 4.4.7-4), 64-bit > > postgres log: > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.021 ms execute > S_2: ROLLBACK > 2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 7.965 ms execute > S_3: COMMIT > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.015 ms bind S_1: > BEGIN > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.008 ms execute > S_1: BEGIN > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.122 ms parse > <unnamed>: select * from AELDATA_READ_VIEW where (SBO_GRP = '000015') > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.317 ms bind > <unnamed>: select * from AELDATA_READ_VIEW where (SBO_GRP = '000015') > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.041 ms execute > <unnamed>: select * from AELDATA_READ_VIEW where (SBO_GRP = '000015') > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.017 ms bind S_2: > ROLLBACK > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.022 ms execute > S_2: ROLLBACK > > 2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.017 ms bind S_1: > BEGIN > 2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.010 ms execute > S_1: BEGIN > 2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.083 ms parse > <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.016 ms bind S_1: > BEGIN > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.013 ms execute > S_1: BEGIN > 2014-09-22 22:21:54 CEST:yy@xx1:[11039] LOG: duration: 0.174 ms bind > <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.096 ms parse > <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:54 CEST:yy@xx1:[6973] LOG: duration: 0.152 ms bind > <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] LOG: process 6973 detected deadlock > while waiting for ShareLock on transaction 318396117 after 1000.060 ms > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] STATEMENT: update AELDATA set > LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: process 11039 still waiting > for ExclusiveLock on tuple (4,9) of relation 16416 of database 16417 after > 1000.038 ms > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] STATEMENT: update AELDATA set > LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] ERROR: deadlock detected > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] DETAIL: Process 6973 waits for > ShareLock on transaction 318396117; blocked by process 11039. > Process 11039 waits for ExclusiveLock on tuple (4,9) of relation > 16416 of database 16417; blocked by process 6973. > Process 6973: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = > '000015') > Process 11039: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = > '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] HINT: See server log for query > details. > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] STATEMENT: update AELDATA set > LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: process 11039 acquired > ExclusiveLock on tuple (4,9) of relation 16416 of database 16417 after > 1000.224 ms > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] STATEMENT: update AELDATA set > LOCK_COLUMN = 1 where (SBO_GRP = '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 1004.543 ms > execute <unnamed>: update AELDATA set LOCK_COLUMN = 1 where (SBO_GRP = > '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.084 ms parse > <unnamed>: select AEL_ID, SBO_GRP, LOCK_KEY from AELDATA where (SBO_GRP = > '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.128 ms bind > <unnamed>: select AEL_ID, SBO_GRP, LOCK_KEY from AELDATA where (SBO_GRP = > '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.048 ms execute > <unnamed>: select AEL_ID, SBO_GRP, LOCK_KEY from AELDATA where (SBO_GRP = > '000015') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.122 ms parse > <unnamed>: select NUM_OF_SBO, AEL_ID, SBO_GRP, SBO_KEY, STATE, PROGRESS, > LOCK_KEY from AEL_XT_DATA_VIEW where (AEL_ID = 15 and EN_NAME = 'H103') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.356 ms bind > <unnamed>: select NUM_OF_SBO, AEL_ID, SBO_GRP, SBO_KEY, STATE, PROGRESS, > LOCK_KEY from AEL_XT_DATA_VIEW where (AEL_ID = 15 and EN_NAME = 'H103') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.073 ms execute > <unnamed>: select NUM_OF_SBO, AEL_ID, SBO_GRP, SBO_KEY, STATE, PROGRESS, > LOCK_KEY from AEL_XT_DATA_VIEW where (AEL_ID = 15 and EN_NAME = 'H103') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.096 ms parse > <unnamed>: update AEL_XT_DATA set NUM_OF_SBO = 31121, STATE = 0, PROGRESS = > 0, LOCK_KEY = null where (AEL_ID = 15 and EN_NAME = 'H103') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.199 ms bind > <unnamed>: update AEL_XT_DATA set NUM_OF_SBO = 31121, STATE = 0, PROGRESS = > 0, LOCK_KEY = null where (AEL_ID = 15 and EN_NAME = 'H103') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.092 ms execute > <unnamed>: update AEL_XT_DATA set NUM_OF_SBO = 31121, STATE = 0, PROGRESS = > 0, LOCK_KEY = null where (AEL_ID = 15 and EN_NAME = 'H103') > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 0.011 ms bind S_3: > COMMIT > 2014-09-22 22:21:55 CEST:yy@xx1:[11039] LOG: duration: 7.775 ms execute > S_3: COMMIT > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] LOG: duration: 0.014 ms bind S_2: > ROLLBACK > 2014-09-22 22:21:55 CEST:yy@xx1:[6973] LOG: duration: 0.014 ms execute > S_2: ROLLBACK > > affected data structures: > xx1=> \d aeldata > Table "public.aeldata" > Column | Type | Modifiers > ----------------+------------------------+----------- > ael_id | numeric(10,0) | not null > sbo_grp | character varying(6) | not null > ael_name | character varying(30) | not null > remark | character varying(200) | > mc_id | numeric(4,0) | > owner | character varying(30) | > lock_key | numeric(10,0) | > lock_column | numeric(1,0) | > default_ael | numeric(1,0) | > Indexes: > "aeldata_pkey" PRIMARY KEY, btree (ael_id) > "default_ael_uk" UNIQUE CONSTRAINT, btree (default_ael) > "uk_ael_name" UNIQUE CONSTRAINT, btree (ael_name) > "uk_sbo_grp" UNIQUE CONSTRAINT, btree (sbo_grp) > "idx_aeldata_mcid" btree (mc_id) > Foreign-key constraints: > "ael_mc_id_fk" FOREIGN KEY (mc_id) REFERENCES mcdata(mc_id) > Referenced by: > TABLE "alarm_table" CONSTRAINT "alarm_table_ael_fk" FOREIGN KEY > (ael_id) REFERENCES aeldata(ael_id) > TABLE "ul_bulk_operation_data" CONSTRAINT > "bulk_operation_data_ael_id_fk" FOREIGN KEY (ael_id) REFERENCES > aeldata(ael_id) > TABLE "ul_job_data" CONSTRAINT "fkey_ael_id" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) > TABLE "ael_groups" CONSTRAINT "fkey_lg_ael_id" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) > TABLE "ael_esd" CONSTRAINT "ael_esd_fk" FOREIGN KEY (ael_id) REFERENCES > aeldata(ael_id) > TABLE "ael_que" CONSTRAINT "ael_que_aelid_fk" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) > TABLE "ael_awai" CONSTRAINT "ael_awai_aelid_fk" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) > TABLE "ael_xt_data" CONSTRAINT "ael_id_key" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) > TABLE "ael_noacc" CONSTRAINT "ael_noacc_ael_fk" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) ON DELETE CASCADE > TABLE "ael_traffic" CONSTRAINT "ael_traffic_ael_fk" FOREIGN KEY > (ael_id) REFERENCES aeldata(ael_id) ON DELETE CASCADE > TABLE "ul_recs" CONSTRAINT "ul_recs_ael_fk" FOREIGN KEY (ael_id) > REFERENCES aeldata(ael_id) > > xx1=> \d+ ael_xt_data_view > View "public.ael_xt_data_view" > Column | Type | Modifiers | Storage | Description > -------------+-------------------------+-----------+----------+------------- > sbo_grp | character varying(6) | | extended | > ael_name | character varying(30) | | extended | > en_name | character varying(40) | | extended | > sbo_key | character varying(20) | | extended | > num_of_sbo | numeric | | main | > ael_en_lock | numeric(10,0) | | main | > ael_state | numeric(3,0) | | main | > job_id | character varying(32) | | extended | > state | numeric(1,0) | | main | > progress | numeric(1,0) | | main | > lock_key | numeric(10,0) | | main | > ael_id | numeric(10,0) | | main | > View definition: > SELECT aeldata.sbo_grp, > aeldata.ael_name, > ael_xt_data.en_name, > ael_xt_data.sbo_key, > ael_xt_data.num_of_sbo, > ael_xt_data.ael_en_lock, > ael_xt_data.ael_state, > ael_xt_data.job_id, > ael_xt_data.state, > ael_xt_data.progress, > ael_xt_data.lock_key, > ael_xt_data.ael_id > FROM ael_xt_data, > aeldata > WHERE aeldata.ael_id = ael_xt_data.ael_id; > Rules: > ael_xt_data_view_ir AS > ON INSERT TO ael_xt_data_view DO INSTEAD INSERT INTO ael_xt_data > (en_name, sbo_key, ael_id, num_of_sbo, ael_en_lock, ael_state, job_id) > VALUES (new.en_name, new.sbo_key, gf_proc.get_aelid_sbo(new.sbo_grp), > new.num_of_sbo, new.ael_en_lock, new.ael_state, new.job_id) > ael_xt_data_view_ud AS > ON DELETE TO ael_xt_data_view DO INSTEAD DELETE FROM ael_xt_data > WHERE ael_xt_data.ael_id = gf_proc.get_aelid_sbo(old.sbo_grp) AND > ael_xt_data.en_name::text = old.en_name::text > ael_xt_data_view_ur AS > ON UPDATE TO ael_xt_data_view DO INSTEAD UPDATE ael_xt_data SET > en_name = new.en_name, sbo_key = new.sbo_key, ael_id = > gf_proc.get_aelid_sbo(new.sbo_grp), num_of_sbo = new.num_of_sbo, > ael_en_lock = new.ael_en_lock, ael_state = new.ael_state, job_id = > new.job_id > WHERE ael_xt_data.ael_id = gf_proc.get_aelid_sbo(old.sbo_grp) AND > ael_xt_data.en_name::text = old.en_name::text > > > > xx1=> \d ael_xt_data > Table "public.ael_xt_data" > Column | Type | Modifiers > -------------+-------------------------+-------------- > ael_id | numeric(10,0) | not null > en_name | character varying(40) | not null > sbo_key | character varying(20) | > num_of_sbo | numeric | > ael_en_lock | numeric(10,0) | > ael_state | numeric(3,0) | default (-8) > job_id | character varying(32) | > state | numeric(1,0) | > progress | numeric(1,0) | > lock_key | numeric(10,0) | > Indexes: > "ael_xt_data_key" PRIMARY KEY, btree (ael_id, en_name) > "idx_aelxtdata_nename" btree (en_name) > Foreign-key constraints: > "ael_ad_en_name" FOREIGN KEY (en_name) REFERENCES en_names(en_name) > "ael_id_key" FOREIGN KEY (ael_id) REFERENCES aeldata(ael_id) -- Bill Moran I need your help to succeed: http://gamesbybill.com
Re: deadlock of lock-waits (on transaction and on tuple) using same update statement
От
Andrej Vanek
Дата:
Hi Bill,
thanks for your answer.
> most often caused by something earlier in the transactions
> need all of the statements in each transaction
It would be great if we could reveal an application error.
Whole transactions I've already posted (in postgres log: log_min_duration_statement=0).
Nothing suspicious yet:
- both sessions COMMIT/ROLLBACK before BEGIN
- both sessions run the same SQL statements
- deadlock: FIRST statement of both transactions
- deadlock: update single table, same row, column without any constraints (WHY?)
- no statements of other sessions executed in between
Any idea?
thanks, Andrej
Re: deadlock of lock-waits (on transaction and on tuple) using same update statement
От
Andrej Vanek
Дата:
Hi,
now I've checked release-notes of 9.3.5 (my version 9.3.4)- found a fix which probably could lead to my deadlocks:
> Fix race condition when updating a tuple concurrently locked by another process (Andres Freund,Álvaro Herrera)
How can I make sure I've run into this bug?
Re: deadlock of lock-waits (on transaction and on tuple) using same update statement
От
Alvaro Herrera
Дата:
Andrej Vanek wrote: > Hi, > > > now I've checked release-notes of 9.3.5 (my version 9.3.4)- found a fix > which probably could lead to my deadlocks: > > > Fix race condition when updating a tuple concurrently locked by another > > process (Andres Freund,Álvaro Herrera) > > How can I make sure I've run into this bug? Update and see if you can reproduce the bug there. If you can, let us know; I didn't trace through your example and won't unless you confirm it's still an issue. It's a bad idea to run any 9.3 version other than the latest one. There are some ugly bugs in there. -- Álvaro Herrera http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
Re: deadlock of lock-waits (on transaction and on tuple) using same update statement
От
Andrej Vanek
Дата:
Hi,
retested:
yes, this is still an issue in 9.3.5, same deadlock errors occured.
Do you need to extract some simplified reproducible testcase?
Best Regards, Andrej