Thread: Trigger and deadlock
Hello,
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?
Thanks :)
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
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.albe@wien.gv.at>
It would be interesting to know what relation 2027300 of database 2026760 is.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?
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
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@gmail.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 here1286781 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 X1286785 22142 2013-07-26 13:55:25 CEST ERROR: deadlock detected1286785 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 Y1286785 22142 2013-07-26 13:55:25 CEST STATEMENT: insert into XProcess 22426 waits for ShareLock on transaction 1286782; blocked by process 22429.1286785 22142 2013-07-26 13:55:25 CEST LOG: execute S_3: ROLLBACKI will try to query pg_locks to see more infoThanks2013/7/26 Albe Laurenz <laurenz.albe@wien.gv.at>It would be interesting to know what relation 2027300 of database 2026760 is.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?
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
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@gmail.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 | ftuple | 2026760 | 2027300 | 365 | 42 | | | | | | 5/113 | 9273 | ExclusiveLock | frelation | 2026760 | 2027300 | | | | | | | | 3/2532 | 9104 | AccessShareLock | trelation | 2026760 | 2027300 | | | | | | | | 3/2532 | 9104 | RowShareLock | trelation | 2026760 | 2027300 | | | | | | | | 3/2532 | 9104 | RowExclusiveLock | trelation | 2026760 | 2027300 | | | | | | | | 5/113 | 9273 | AccessShareLock | trelation | 2026760 | 2027300 | | | | | | | | 5/113 | 9273 | RowShareLock | trelation | 2026760 | 2027300 | | | | | | | | 5/113 | 9273 | RowExclusiveLock | ttuple | 2026760 | 2027300 | 365 | 42 | | | | | | 3/2532 | 9104 | ExclusiveLock | trelation | 2026760 | 2027300 | | | | | | | | 6/313 | 9274 | AccessShareLock | trelation | 2026760 | 2027300 | | | | | | | | 6/313 | 9274 | RowShareLock | t29-07-2013 10:12:29,004 ERROR GrailsExceptionResolver - PSQLException occurred when processing request: [POST] /api/annotation.jsonERROR: deadlock detectedDé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 ySET count_x = count_x + 1WHERE y.id = NEW.y_id"PL/pgSQL function "incrementy" line 6 at SQL statement. Stacktrace follows:org.postgresql.util.PSQLException: ERROR: deadlock detectedI 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ïc2013/7/29 Loïc Rollus <loicrollus@gmail.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 here1286781 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 X1286785 22142 2013-07-26 13:55:25 CEST ERROR: deadlock detected1286785 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 Y1286785 22142 2013-07-26 13:55:25 CEST STATEMENT: insert into XProcess 22426 waits for ShareLock on transaction 1286782; blocked by process 22429.1286785 22142 2013-07-26 13:55:25 CEST LOG: execute S_3: ROLLBACKI will try to query pg_locks to see more infoThanks2013/7/26 Albe Laurenz <laurenz.albe@wien.gv.at>It would be interesting to know what relation 2027300 of database 2026760 is.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?
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
Loïc Rollus wrote: > 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. You mean "SELECT FOR UPDATE", richt? Great that you could figure out where the problem was. Yours, Laurenz Albe