Re: Trigger and deadlock

Here is pg_lock for relation Y (= 2027300)

locktype | database | relation | page | tuple | virtualxid | transactionid
| classid | objid | objsubid | virtualtransaction | pid | mode
| granted
----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+------+------------------+---------
tuple | 2026760 | 2027300 | 365 | 42 | |
| | | | 6/313 | 9274 | ShareLock
| f
tuple | 2026760 | 2027300 | 365 | 42 | |
| | | | 5/113 | 9273 | ExclusiveLock
| f
relation | 2026760 | 2027300 | | | |
| | | | 3/2532 | 9104 | AccessShareLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 3/2532 | 9104 | RowShareLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 3/2532 | 9104 | RowExclusiveLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 5/113 | 9273 | AccessShareLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 5/113 | 9273 | RowShareLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 5/113 | 9273 | RowExclusiveLock
| t
tuple | 2026760 | 2027300 | 365 | 42 | |
| | | | 3/2532 | 9104 | ExclusiveLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 6/313 | 9274 | AccessShareLock
| t
relation | 2026760 | 2027300 | | | |
| | | | 6/313 | 9274 | RowShareLock
| t

29-07-2013 10:12:29,004 ERROR GrailsExceptionResolver - PSQLException
occurred when processing request: [POST] /api/annotation.json
ERROR: deadlock detected
Détail : Process 9273 waits for ExclusiveLock on tuple (365,42) of
relation 2027300 of database 2026760; blocked by process 9104.
Process 9104 waits for ShareLock on transaction 1286966; blocked by process
9273.
Indice : See server log for query details.
Où : SQL statement "UPDATE y
SET count_x = count_x + 1
WHERE y.id = NEW.y_id"
PL/pgSQL function "incrementy" line 6 at SQL statement. Stacktrace follows:
org.postgresql.util.PSQLException: ERROR: deadlock detected

I don't understand where the "ExclusiveLock" come from.
Postgresql Doc says (
http://www.postgresql.org/docs/9.1/static/explicit-locking.html)
"EXCLUSIVE: This lock mode is not automatically acquired on tables by any
PostgreSQL command."
In log, I just see that Hibernate just read the row y (365,42) (simple
select). No explicit lock.

Loïc

2013/7/29 Loïc Rollus <loicrollus(at)gmail(dot)com>

> Hi,
>
> Thanks for your quick reply!
> I found the table. But the ctid of the row has changed. But during my
> test, I update only 1 row from this table, so I know the row.
>
> I had already put log_statement to 'all'. It's strange because in the log,
> I only see simple "SELECT ... FROM" on this table (no UPDATE or SELECT FOR
> UPDATE). But I can't see request from trigger (not show by
> log_statement='all'?).
>
> Here is a log sample (simplify: insert into X should update the counter on
> the specific row from Y)
>
>
> 1286781 22142 2013-07-26 13:55:22 CEST LOG: execute <unnamed>: insert
> into X...
> 1286780 22426 2013-07-26 13:55:22 CEST LOG: execute <unnamed>: insert
> into X...
> ====> it should be UPDATE on Y from trigger here
> 1286781 22142 2013-07-26 13:55:22 CEST LOG: execute select this_.id as
> id54_0_,.... from ....
> [...22142 follow its way, commit, and carry another request ]
> 1286785 22142 2013-07-26 13:55:23 CEST LOG: execute <unnamed>: insert
> into X
> 1286785 22142 2013-07-26 13:55:25 CEST ERROR: deadlock detected
> 1286785 22142 2013-07-26 13:55:25 CEST DETAIL: Process 22142 waits for
> ShareLock on transaction 1286780; blocked by process 22426.
> Process 22426 waits for ExclusiveLock on tuple (365,13) of relation
> 2027300 of database 2026760; blocked by process 22142.
> 1286785 22142 2013-07-26 13:55:25 CEST HINT: See server log for query
> details.
> 1286785 22142 2013-07-26 13:55:25 CEST CONTEXT: SQL statement "UPDATE Y
> 1286785 22142 2013-07-26 13:55:25 CEST STATEMENT: insert into X
> Process 22426 waits for ShareLock on transaction 1286782; blocked by
> process 22429.
> 1286785 22142 2013-07-26 13:55:25 CEST LOG: execute S_3: ROLLBACK
>
> I will try to query pg_locks to see more info
>
> Thanks
>
>
>
>
>
>
>
> 2013/7/26 Albe Laurenz <laurenz(dot)albe(at)wien(dot)gv(dot)at>
>
>> Loïc Rollus wrote:
>> > I've try to make some concurrency robustness test with an web server
>> app that use Hibernate and
>> > Postgres.
>> > It seems that my trigger make deadlock when multiple thread use it.
>> >
>> > I will try to simplify examples:
>> > I have a table "films"(id, title,director) and a table
>> "directors"(id,name,nbreFilms). I want to
>> > automaticaly count directors's films.
>> >
>> > So I have this triggers after each insert on films:
>> >
>> > CREATE OR REPLACE FUNCTION incrementDirectors() RETURNS TRIGGER AS
>> $incDirectors$
>> > BEGIN
>> > UPDATE directors
>> > SET nbreFilm = nbreFilm + 1
>> > WHERE directors.id = NEW.director;
>> > RETURN NEW;
>> > END;
>> > $incDirectors$ LANGUAGE plpgsql;
>> > CREATE TRIGGER triggerIncrDirectors AFTER INSERT ON films FOR EACH ROW
>> EXECUTE PROCEDURE
>> > incrementDirectors();
>> >
>> >
>> > When I do a lot of INSERT films at the same time, I have this error:
>> >
>> >
>> ******************************************************************************************************
>> > ********
>> > 1286785 22142 2013-07-26 13:55:25 CEST ERROR: deadlock detected
>> > 1286785 22142 2013-07-26 13:55:25 CEST DETAIL: Process 22142 waits for
>> ShareLock on transaction
>> > 1286780; blocked by process 22426.
>> > Process 22426 waits for ExclusiveLock on tuple (365,13) of relation
>> 2027300 of database 2026760;
>> > blocked by process 22142.
>> > 1286785 22142 2013-07-26 13:55:25 CEST HINT: See server log for query
>> details.
>> >
>> ******************************************************************************************************
>> > ********
>> >
>> > If I look in postgresql log for process, I see this (its a web app):
>> > 1.Process 22142: take a ADD request from http,
>> > 2.Process 22426: take a ADD request from http,
>> > 3.Process 22142: do INSERT of new film
>> > 4.Process 22146: do INSERT of new film
>> > 5.Process 22142: continue request (Process 22146 seems to be blocked)
>> and do COMMIT
>> > 6.Process 22142: take a ADD request from http,
>> > 7.Process 22142: do INSERT of new film
>> > 8.DEADLOCK: process 22142 is waiting for 22146 and 22146 is waiting for
>> 22142
>> >
>> > I don't understant why the commit of the process 22142 won't unlock
>> process 22426.
>> >
>> > Have you an idea?
>>
>> It would be interesting to know what relation 2027300 of database 2026760
>> is.
>>
>> Then you could select the offending tuple with
>> SELECT * FROM <tablename> WHERE ctid='(365,13)';
>>
>> What I would do is to set log_statement='all' and see what
>> exact SQL statements are issued. Maybe Hibernate does something
>> you do not know.
>>
>> It may also be interesting to query pg_locks immediately before
>> commit to see what locks one transaction holds.
>>
>> Yours,
>> Laurenz Albe
>>
>
>