Re: deadlock of lock-waits (on transaction and on tuple) using same update statement

On Tue, 23 Sep 2014 20:00:27 +0200
Andrej Vanek <andrej(dot)vanek(dot)sk(at)gmail(dot)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(at)xx1:[6973] LOG: duration: 0.021 ms execute
> S_2: ROLLBACK
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[11039] LOG: duration: 7.965 ms execute
> S_3: COMMIT
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[6973] LOG: duration: 0.015 ms bind S_1:
> BEGIN
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[6973] LOG: duration: 0.008 ms execute
> S_1: BEGIN
> 2014-09-22 22:21:54 CEST:yy(at)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(at)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(at)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(at)xx1:[6973] LOG: duration: 0.017 ms bind S_2:
> ROLLBACK
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[6973] LOG: duration: 0.022 ms execute
> S_2: ROLLBACK
>
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[11039] LOG: duration: 0.017 ms bind S_1:
> BEGIN
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[11039] LOG: duration: 0.010 ms execute
> S_1: BEGIN
> 2014-09-22 22:21:54 CEST:yy(at)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(at)xx1:[6973] LOG: duration: 0.016 ms bind S_1:
> BEGIN
> 2014-09-22 22:21:54 CEST:yy(at)xx1:[6973] LOG: duration: 0.013 ms execute
> S_1: BEGIN
> 2014-09-22 22:21:54 CEST:yy(at)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(at)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(at)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(at)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(at)xx1:[6973] STATEMENT: update AELDATA set
> LOCK_COLUMN = 1 where (SBO_GRP = '000015')
> 2014-09-22 22:21:55 CEST:yy(at)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(at)xx1:[11039] STATEMENT: update AELDATA set
> LOCK_COLUMN = 1 where (SBO_GRP = '000015')
> 2014-09-22 22:21:55 CEST:yy(at)xx1:[6973] ERROR: deadlock detected
> 2014-09-22 22:21:55 CEST:yy(at)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(at)xx1:[6973] HINT: See server log for query
> details.
> 2014-09-22 22:21:55 CEST:yy(at)xx1:[6973] STATEMENT: update AELDATA set
> LOCK_COLUMN = 1 where (SBO_GRP = '000015')
> 2014-09-22 22:21:55 CEST:yy(at)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(at)xx1:[11039] STATEMENT: update AELDATA set
> LOCK_COLUMN = 1 where (SBO_GRP = '000015')
> 2014-09-22 22:21:55 CEST:yy(at)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(at)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(at)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(at)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(at)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(at)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(at)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(at)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(at)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(at)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(at)xx1:[11039] LOG: duration: 0.011 ms bind S_3:
> COMMIT
> 2014-09-22 22:21:55 CEST:yy(at)xx1:[11039] LOG: duration: 7.775 ms execute
> S_3: COMMIT
> 2014-09-22 22:21:55 CEST:yy(at)xx1:[6973] LOG: duration: 0.014 ms bind S_2:
> ROLLBACK
> 2014-09-22 22:21:55 CEST:yy(at)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