Q:

Deadlock in a simple PL/pgsql stored procedure that updates a single row (called by Hibernate)

I wrote a simple stored procedure:
CREATE OR REPLACE FUNCTION "public"."update_table01" (
    int4, -- $1 (population)
    int2 -- $2 (id)
) RETURNS "pg_catalog"."void" AS
$body$
BEGIN
    UPDATE "table01"
    SET
            population = $1
    WHERE id = $2;
END;
$body$
LANGUAGE 'plpgsql'
VOLATILE
CALLED ON NULL INPUT
SECURITY INVOKER
COST 100;

I am calling this within my Java server (jre7), and I'm using Hibernate 4 with C3P0 as my connection pool. This is being executed on PostgreSQL 9.2.4. I have a Hibernate entity corresponding to table01 (mapped by annotations), and I specified this procedure to be used as SQL update:
@SQLUpdate(sql = "{call update_table01(?, ?)}", callable = true)

When I did a load test with multiple threads (around 20-30) that were frequently calling this, a few deadlocks occurred, much to my surprise. Here is the relevant part of the log:
2013-08-14 14:51:19 CEST [23495]: [3-1] LOG:  process 23495 detected deadlock while waiting for ShareLock on transaction 140127434 after 1000.048 ms
2013-08-14 14:51:19 CEST [23495]: [4-1] STATEMENT:  update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23495]: [5-1] ERROR:  deadlock detected
2013-08-14 14:51:19 CEST [23495]: [6-1] DETAIL:  Process 23495 waits for ShareLock on transaction 140127434; blocked by process 23481.
Process 23481 waits for ShareLock on transaction 140127431; blocked by process 23495.
Process 23495: update table01 set population=$1 where id=$2
Process 23481: update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23495]: [7-1] HINT:  See server log for query details.
2013-08-14 14:51:19 CEST [23495]: [8-1] STATEMENT:  update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23481]: [3-1] LOG:  process 23481 still waiting for ShareLock on transaction 140127431 after 1000.086 ms
2013-08-14 14:51:19 CEST [23481]: [4-1] STATEMENT:  update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23481]: [5-1] LOG:  process 23481 acquired ShareLock on transaction 140127431 after 1000.227 ms
2013-08-14 14:51:19 CEST [23481]: [6-1] STATEMENT:  update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23938]: [3-1] LOG:  process 23938 still waiting for ExclusiveLock on tuple (8,72) of relation 16890 of database 16751 after 1000.119 ms
2013-08-14 14:51:19 CEST [23938]: [4-1] STATEMENT:  update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23938]: [5-1] LOG:  process 23938 acquired ExclusiveLock on tuple (8,72) of relation 16890 of database 16751 after 1000.174 ms
2013-08-14 14:51:19 CEST [23938]: [6-1] STATEMENT:  update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23520]: [3-1] LOG:  duration: 970.319 ms  execute <unnamed>: update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23520]: [4-1] DETAIL:  parameters: $1 = '5731', $2 = '294'
2013-08-14 14:51:19 CEST [23481]: [7-1] LOG:  duration: 1000.361 ms  execute <unnamed>: update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23481]: [8-1] DETAIL:  parameters: $1 = '1586', $2 = '253'
2013-08-14 14:51:19 CEST [23524]: [3-1] LOG:  duration: 531.909 ms  execute <unnamed>: update table01 set population=$1 where id=$2
2013-08-14 14:51:19 CEST [23524]: [4-1] DETAIL:  parameters: $1 = '1546', $2 = '248'
2013-08-14 14:51:19 CEST [23938]: [7-1] LOG:  duration: 1004.863 ms  execute <unnamed>: update table01 set population=$1 where id=$2

I am bad at interpreting Postgres logs, so correct me if I am wrong. I think this says that two processes ended up in a deadlock. Both were executing the same statement.
A lot of stuff puzzles me her. The most important is: I do not understand how could two processes (that even update different rows) end up in a deadlock, when only a single row-level lock for a row that has that specific ID is obtained in the stored procedure? This is the only procedure that changes this table. Isn't it supposed to obtain an exclusive lock (the same when executing SELECT ... FOR UPDATE)? Where do ShareLocks come from? What is that process that show in later lines (23938)? My best guess is that 23938 was also waiting for the lock, and when 23495 was killed, it acquired the lock.
Then I tried the following:
CREATE OR REPLACE FUNCTION "public"."update_table01" (
    int4, -- $1 (population)
    int2 -- $2 (id)
) RETURNS "pg_catalog"."void" AS
$body$
BEGIN
    PERFORM 1 FROM "table01" WHERE id = $2 FOR UPDATE;

    UPDATE "table01"
    SET
            population = $1
    WHERE id = $2;
END;
$body$
LANGUAGE 'plpgsql'
VOLATILE
CALLED ON NULL INPUT
SECURITY INVOKER
COST 100;

When I ran it again, I couldn't reproduce it. There were no more deadlocks.
Why is this happening?
EDIT: After investigating a little bit, it seems that Hibernate is calling this method by itself sometimes when flushing session. Several times in some cases, for different entities, all in the same transaction. This can cause deadlocking because each call to update_table01() locks specific table01 column row with FOR UPDATE lock. With some improper call ordering, it can create a circular wait. After I made this entity non-updatable (i.e. marked all columns with update=false), everything works as it should. Now, I am really surprised with this Hibernate behaviour, because table01 entities in RAM were not attached to any of sessions which were responsible for later transactions. And yet, Hibernate flushed these entities to database, and I don't know why.
As for the locks, I've identified two more stored procedures of mine that insert/update to some other table which references table01 (one of them changes the FK column). These will request a ShareLock on the appropriate FK row in table01, and will, therefore, conflict with update_table01(). So these three stored procedures will wait for each other to complete. This alone cannot create a circular wait, but it becomes possible if you add a couple of Hibernate-caused calls to update_table01() after calls to these stored procedures.

A:

Firstly, the exclusive lock you see in:
ExclusiveLock on tuple (8,72) of relation 16890 of database 16751

This should hopefully be your "table01" - try:
SELECT * FROM pg_class WHERE oid = 16890;

Secondly, yes you have processes 23495 and 23481 blocking each other. PostgreSQL detects this after waiting 1 second and cancels 23495. Then, a few lines further down 23481 goes through after 1000.361ms.
To test this, you'll want two terminals open, each running psql. That way you can control the pauses in each. Issue a BEGIN in each and try running the update in both terminals. Take a look at the pg_locks view to see what's going on.
None of my experimenting has been able to reproduce this, and I can't see how it can.
The ShareLock you see is probably the one preventing changes to the table while the UPDATE occurs. You wouldn't want someone dropping the column you are trying to update.
Naturally, two share-locks can't conflict so there must be something else at work.
What does strike me from your log extract is that you have a number of other simple updates that are all sat there for what seems like a long time for such a simple update.
It's possible that the deadlock detector was mistaken - your server was just under extreme load and there was no conflict between your two transactions. If your deadlock_timeout setting was a bit longer this might never have happened.

