Re: [GENERAL] Trigger and deadlock

2013-07-30 Thread Loïc Rollus 
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 loicrol...@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
| 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 loicrol...@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

Re: [GENERAL] Trigger and deadlock

2013-07-30 Thread Albe Laurenz 
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

-- 
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general

Re: [GENERAL] Trigger and deadlock

2013-07-29 Thread Loïc Rollus 
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.a...@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

Re: [GENERAL] Trigger and deadlock

2013-07-29 Thread Loïc Rollus 
 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 loicrol...@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.a...@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,

[GENERAL] Trigger and deadlock

2013-07-26 Thread Loïc Rollus 
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 :)

Re: [GENERAL] Trigger and deadlock

2013-07-26 Thread Albe Laurenz 
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

-- 
Sent via pgsql-general mailing list (pgsql-general@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-general