Trigger and deadlock

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>

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

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

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