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 

>  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 
>
>> 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 : insert
>> into X...
>> 1286780 22426 2013-07-26 13:55:22 CEST LOG:  execute : 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 : insert
>> into X
>> 1286785 22142 2013-07-26 13:55:25 CEST ERROR:  deadlock detected
>> 1286785 2214

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 

> 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 : insert
> into X...
> 1286780 22426 2013-07-26 13:55:22 CEST LOG:  execute : 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 : 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 
>
>> Loïc Rollus

Re: [GENERAL] Trigger and deadlock

2013-07-28 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 : insert into
X...
1286780 22426 2013-07-26 13:55:22 CEST LOG:  execute : 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 : 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 

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


[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 :)