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

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