Re: Idle In Transaction

On Tue, 2010-07-13 at 17:38 -0400, Tom Lane wrote:
> Anthony Presley <anthony@resolution.com> writes:
> > Every so often (usually in the early morning), we are seeing an "<IDLE>
> > in transaction" show up.  This appears to lock / block other statements
> > from going through, though I'm not sure why.  If left unchecked, we end
> > up with all of our connections being overrun.
>
> Well, the idle transaction is evidently sitting on some lock that the
> UPDATE needs.  You didn't show the pg_locks columns that would tell
> exactly what lock it is though ...
>
> > Would a connection pooler cause (or amplify) any issues relating to
> > this?
>
> It shouldn't.  Any decent pooler will ensure that no transaction remains
> open when it transfers the connection to another client.
>
> > How can I track down the issue here?  I've been looking through
> > web app and database logs without much luck.
>
> Can you track the session connection (the port number) back to a client
> process?  If there's a pooler in the way you'll probably need to crank
> up its logging level to be able to make that association.  Once you've
> got that, you could attach to the client with a debugger and see what it
> thinks it's doing.
>
> The other line of attack I can think of is to turn on log_connections
> and log_statements and make sure log_line_prefix includes the PID.
> Then you can find the series of statements that were issued before
> the idle transaction went to sleep, and that hopefully is enough
> information to track down the client code.
>
>             regards, tom lane

Ok, I've written a script to find some of this information when an
<IDLE> in transaction has been hanging out too long, and then run some
SQL commands.  Since there's a lot there, I've added it to PasteBin:

  http://pastebin.com/TpfKd9Ya

In looking at it, it would appear that process 30367 has a
RowExclusiveLock on the forecast_timeblock table ... though the query
that is hung and waiting is on the employee table.

However, 8982 is blocked, waiting on 30637.  8982 is an insert into the
employee table.

forecast_timeblock has a foreign key to the employee table, ie:

Foreign-key constraints:
    "fk80bcf09c965efae7" FOREIGN KEY (employee_id) REFERENCES
employee(id)


I manually canceled the backend (8982), and tried running it again a few
minutes later.

And this was in the query log:

06:41:21 artemis postgres[8982]: [35-1] LOG:  process 8982 still waiting
for ShareLock on transaction 5153723 after 1000.797 ms

Any idea what gives?  I don't understand locks well enough to see what's
going on, but why would inserting into forecast_timeblock cause it to
block an insert into the employee table (which has no relation back to
forecast_timeblock).

Thanks!

By the way, we're running:

> select version();

version
------------------------------------------------------------------------------------------------------------------
PostgreSQL 8.4.2 on x86_64-redhat-linux-gnu, compiled by GCC gcc (GCC)
4.1.2 20071124 (Red Hat 4.1.2-42), 64-bit


--
Anthony