released savepoint blocking further statements

I have PostgreSQL 9.5.2 on MacOSX 10.10.5 installed with homebrew, it did
happen with 9.4.1 too.
Our rails app seems to be stuck in pgsql command.
Debugger showed the pg client library is waiting for result from the server.

I've raised log levels in my pg and logs confirms that it's waiting on
psql[1.], when i execute the query from Log Monitoring Wiki the blocking
statement is RELEASE SAVEPOINT active_record_2_47 [2.], but that release
seems executed earlier fine according to logs [3.].

What else should i look into to troubleshoot the problem?

Regards
Miklós

[1.] Last statement locked:

LOG: 00000: execute <unnamed>: SELECT "position_types".* FROM
"position_types" WHERE "position_types"."id" = $1 LIMIT $2 FOR UPDATE
DETAIL: parameters: $1 = '1401', $2 = '1'
LOCATION: exec_execute_message, postgres.c:1963
LOG: 00000: process 79469 still waiting for ShareLock on transaction
8453886 after 1000.345 ms
DETAIL: Process holding the lock: 79440. Wait queue: 79469.
CONTEXT: while locking tuple (1,139) in relation "position_types"
LOCATION: ProcSleep, proc.c:1323
STATEMENT: SELECT "position_types".* FROM "position_types" WHERE
"position_types"."id" = $1 LIMIT $2 FOR UPDATE

[2.] I've tried to use the query Lock Monitoring wiki from to find out what
is blocking:

it shows that 79469 | RELEASE SAVEPOINT active_record_2_47 is the
current_statement_in_blocking_process.

https://wiki.postgresql.org/wiki/Lock_Monitoring

SELECT bl.pid AS blocked_pid,

a.usename AS blocked_user,
ka.query AS current_statement_in_blocking_process,
now() - ka.query_start AS blocking_duration,
kl.pid AS blocking_pid,
ka.usename AS blocking_user,
a.query AS blocked_statement,
now() - a.query_start AS blocked_duration
FROM pg_catalog.pg_locks bl
JOIN pg_catalog.pg_stat_activity a ON a.pid = bl.pid
JOIN pg_catalog.pg_locks kl ON kl.transactionid =
bl.transactionid AND kl.pid != bl.pid
JOIN pg_catalog.pg_stat_activity ka ON ka.pid = kl.pid
WHERE NOT bl.GRANTED;

blocked_pid | blocked_user | current_statement_in_blocking_process |
blocking_duration | blocking_pid | blocking_user |
blocked_statement
| blocked_duration

-------------+--------------+---------------------------------------+-------------------+--------------+---------------+-------------------------------------------------------------------------------------------------------+------------------

79469 | boga | RELEASE SAVEPOINT active_record_2_47 |
00:10:44.781475 | 79440 | boga | SELECT
"position_types".* FROM "position_types" WHERE "position_types"."id" = $1
LIMIT $2 FOR UPDATE | 00:08:39.344037

(1 row)

[3.] But according to pg logs that statement that RELEAS SAVEPOINT was
executed fine:

LOCATION: exec_execute_message, postgres.c:2034
LOG: 00000: statement: RELEASE SAVEPOINT active_record_2_47
LOCATION: exec_simple_query, postgres.c:946
LOG: 00000: duration: 0.038 ms

On Thu, Apr 7, 2016 at 1:26 AM, Miklós Fazekas <mfazekas(at)szemafor(dot)com> wrote:

> [2.] I've tried to use the query Lock Monitoring wiki from to find out what
> is blocking:
>
> it shows that 79469 | RELEASE SAVEPOINT active_record_2_47 is the
> current_statement_in_blocking_process.
>
> https://wiki.postgresql.org/wiki/Lock_Monitoring
>
> SELECT bl.pid AS blocked_pid,
>
> a.usename AS blocked_user,
> ka.query AS current_statement_in_blocking_process,
> now() - ka.query_start AS blocking_duration,
> kl.pid AS blocking_pid,
> ka.usename AS blocking_user,
> a.query AS blocked_statement,
> now() - a.query_start AS blocked_duration
> FROM pg_catalog.pg_locks bl
> JOIN pg_catalog.pg_stat_activity a ON a.pid = bl.pid
> JOIN pg_catalog.pg_locks kl ON kl.transactionid =
> bl.transactionid AND kl.pid != bl.pid
> JOIN pg_catalog.pg_stat_activity ka ON ka.pid = kl.pid
> WHERE NOT bl.GRANTED;

That is probably not the current statement in the blocking process.
It is likely that the blocking process is in the state "idle in
transaction", and the RELEASE SAVEPOINT is actually the most recent
statement, not the current statement.

I've updated the wiki to clarify that, but it could use some more polishing.

So your savepoint release has executed successfully, but the outer
transaction is still holding on to locks which block the other
process. You have to convince that outer transaction to either commit
or rollback.

Cheers,

Jeff

Jeff,

Thanks much for your help. There was an issue with rails 5 beta connection
pool where in some cases a connection with an open transaction returned to
pool.

Regards,
Miklós

On Fri, Apr 8, 2016 at 8:00 PM, Jeff Janes <jeff(dot)janes(at)gmail(dot)com> wrote:

> On Thu, Apr 7, 2016 at 1:26 AM, Miklós Fazekas <mfazekas(at)szemafor(dot)com>
> wrote:
>
>
> > [2.] I've tried to use the query Lock Monitoring wiki from to find out
> what
> > is blocking:
> >
> > it shows that 79469 | RELEASE SAVEPOINT active_record_2_47 is the
> > current_statement_in_blocking_process.
> >
> > https://wiki.postgresql.org/wiki/Lock_Monitoring
> >
> > SELECT bl.pid AS blocked_pid,
> >
> > a.usename AS blocked_user,
> > ka.query AS current_statement_in_blocking_process,
> > now() - ka.query_start AS blocking_duration,
> > kl.pid AS blocking_pid,
> > ka.usename AS blocking_user,
> > a.query AS blocked_statement,
> > now() - a.query_start AS blocked_duration
> > FROM pg_catalog.pg_locks bl
> > JOIN pg_catalog.pg_stat_activity a ON a.pid = bl.pid
> > JOIN pg_catalog.pg_locks kl ON kl.transactionid =
> > bl.transactionid AND kl.pid != bl.pid
> > JOIN pg_catalog.pg_stat_activity ka ON ka.pid = kl.pid
> > WHERE NOT bl.GRANTED;
>
>
> That is probably not the current statement in the blocking process.
> It is likely that the blocking process is in the state "idle in
> transaction", and the RELEASE SAVEPOINT is actually the most recent
> statement, not the current statement.
>
> I've updated the wiki to clarify that, but it could use some more
> polishing.
>
> So your savepoint release has executed successfully, but the outer
> transaction is still holding on to locks which block the other
> process. You have to convince that outer transaction to either commit
> or rollback.
>
> Cheers,
>
> Jeff
>