An issue I’ve been trying to understand recently is a bunch of ShareLock warnings in the log file.

LOG:  process 916 still waiting for ShareLock on transaction 378662803 after 1000.762 ms
STATEMENT:  update user_customers set last_changed=$1 where id=$20

And a bit later

LOG:  process 916 acquired ShareLock on transaction 378662803 after 1777.653 ms
STATEMENT:  update user_customers set last_changed=$1 where id=$20
LOG:  duration: 2030.106 ms  execute : update user_customers set last_changed=$1 where id=$20

The problem went away before I could run a query to find out what process was holding the lock, and I’ve never been able to catch it in the act. What can we tell from this logged information?

1. The type of lock that it was trying to grab was a Share lock.
2. The statement that is trying to grab a lock is an UPDATE.
3. The object being locked is a Transaction (not tuple).
4. There was only the one duration line, so whatever is holding the lock was quick (<1 sec).

A Share lock would mean the locking process is holding one of the following on the transaction:
• Row exclusive (update, delete, insert)
• Share update exclusive (vacuum, analyze)
• Share row exclusive (not used automatically by postgres processes)
• Exclusive (not used automatically by postgres processes)
• Access exclusive (alter, drop, truncate, reindex, cluster, vacuum full)

I know this particular database has no DDL running and the code does not perform any explicit locking so I can rule out the last 3, leaving Row Exclusive and Share Update Exclusive. I ruled out any autovacuum processing from blocking the updates in my previous post.

So that just leaves Row Exclusive as the possible cause of this blocking. However, remember that my lock is waiting on a transaction not a row. This indicates that some session has a Row Exclusive lock and an open transaction that my session needs to wait on. The only possible explanation (that I can come up with) is that this other session is locking the same row I am trying to update – which doesn’t make a whole lot of sense as the row is very user specific and multiple sessions updating a single user shouldn’t happen in this application.

The other confusing part is that this lock is being held for long enough to put a warning in the log file (>1 sec) and this update should run pretty much instantaneously. Also, the locking session ran fast as it didn’t display any DURATION line which is also set to a 1 sec threshold.

Enough guessing – I took my findings to the developers and together we eventually discovered a scheduled process that batch up requests to update these user rows, and it was possible for duplicate requests of the same rows to be run across multiple parallel sessions. The way it works indicated that many updates could be performed before it would commit, which can explain why my blocked update had to wait so long.

Timeline:

So only session 2 writes stuff to the log which is exactly what I was seeing.