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

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?

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)