Обсуждение: released savepoint blocking further statements

Поиск
Список
Период
Сортировка

released savepoint blocking further statements

От
Miklós Fazekas
Дата:
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



Re: released savepoint blocking further statements

От
Jeff Janes
Дата:
On Thu, Apr 7, 2016 at 1:26 AM, Mikl=C3=B3s Fazekas <mfazekas@szemafor.com>=
 wrote:


> [2.] I've tried to use the query Lock Monitoring wiki from to find out wh=
at
> 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 =3D bl.pid
>    JOIN pg_catalog.pg_locks         kl ON kl.transactionid =3D
> bl.transactionid AND kl.pid !=3D bl.pid
>    JOIN pg_catalog.pg_stat_activity ka ON ka.pid =3D 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

Re: released savepoint blocking further statements

От
Miklós Fazekas
Дата:
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.janes@gmail.com> wrote:
On Thu, Apr 7, 2016 at 1:26 AM, Miklós Fazekas <mfazekas@szemafor.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