released savepoint blocking further statements

From: Miklós Fazekas <mfazekas(at)szemafor(dot)com>
To: pgsql-bugs(at)postgresql(dot)org
Subject: released savepoint blocking further statements
Date: 2016-04-07 08:26:15
Message-ID: CAAMmcSSMdrL5uhsgdy=TLedj=48PKY8RHMGisNgffjEo9XVxNA@mail.gmail.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

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

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message emmanuel.reynard 2016-04-07 10:28:20 BUG #14072: char() and application of locale collation
Previous Message Noah Misch 2016-04-07 02:41:25 Re: BUG #14050: "could not reserve shared memory region" in postgresql log