Re: Trigger and deadlock

Hi,

It's ok.
Before the insert, The foreign key constraint locked the row. If
transaction A and B lock the row with FK, before doing UPDATE, they were
stuck.
I found a solution by creating an "before insert" trigger with a simple
SELECT FROM UPDATE on the row.

Loïc

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

> 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
>>>
>>
>>
>