Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sICtl-00DtS4-B4 for pgsql-admin@arkaria.postgresql.org; Fri, 14 Jun 2024 19:47:45 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.94.2) (envelope-from ) id 1sICtj-0059Pc-03 for pgsql-admin@arkaria.postgresql.org; Fri, 14 Jun 2024 19:47:43 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1sICti-0059PT-Hn for pgsql-admin@lists.postgresql.org; Fri, 14 Jun 2024 19:47:43 +0000 Received: from mail-qk1-x730.google.com ([2607:f8b0:4864:20::730]) by magus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1sICtc-001gAD-Hh for pgsql-admin@lists.postgresql.org; Fri, 14 Jun 2024 19:47:42 +0000 Received: by mail-qk1-x730.google.com with SMTP id af79cd13be357-7955841fddaso219738785a.1 for ; Fri, 14 Jun 2024 12:47:36 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=aweber.com; s=2018090500; t=1718394455; x=1718999255; darn=lists.postgresql.org; h=references:to:cc:in-reply-to:date:subject:mime-version:message-id :from:from:to:cc:subject:date:message-id:reply-to; bh=Hf4kcMDX8n6SMPglmbn0x4EGTPBuv14qQw/ON5dFVrQ=; b=CcKMMqr1KmVv3iaXlvvktA3CLU7ni1qp55woRBXovz2ozKRFREAGBpQPzgcvMAaL/W gSrAnR80vohn/h6bfIwLRHjKUkf4X6sdIDByKgduImAb6TJg6h1ff71So1984Bjfaa68 IMxJPuOrJeCuOJL1GTRVl4xiNCONIsjMjatTD1Fly1kObJKKpIf+A8aALOSCGHtF9CGw BJ3aeweJWoBk1fp4Stmhg94J9nucqLsUAsf+xdKFdbnsMGr4qYnFl5m+Xg03mes/KdhX Z9bXS7FAXKzODqFyo1Im8TZ1mLjSvbKla7l7T4BRWJXwVYsbYY/V14yMl6iuBQ8LKfPI KeHw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1718394455; x=1718999255; h=references:to:cc:in-reply-to:date:subject:mime-version:message-id :from:x-gm-message-state:from:to:cc:subject:date:message-id:reply-to; bh=Hf4kcMDX8n6SMPglmbn0x4EGTPBuv14qQw/ON5dFVrQ=; b=tswfYUagf5t8b7ou8iNLL0F+fBOOl8HqIWF2gBEj9YO5oLBax8QChpShMu3aXZ59Mc KVy1JjHywrrdWPUAXbS1KW99FqsCI3JtQf+lXZXhlwPTilvbqzpHLm442/H4DazA8xOP MbB2wzn6+JS1eyt1EXrDpcL+MLUFPn/vgHIwa2tjgEHd7jo/T4miD3StznVXWRVifbum cgs0hiK+FO8zq78gaDhPEyjxMQC8GT/11dlUnw5NmhvdGzkVeRARghRMr1f+Kv8mHlbN KV12l2BiGmTQck9PFLc4BDqbF9w9dmTgu0ZtSeTWocBm3Wd72mHN6QWqPANBwEN775xa XOlQ== X-Gm-Message-State: AOJu0YwOZmdAO2sI450Y0g8pG2DwDZ70h72yGbSUvwzGwUhjkQb2Uvc4 gXyvi4Bdmt8a1uW4pQ24TheKQbekSxxceiz1JjzgrmnZwWShrvSiP0D91ZBOoIw= X-Google-Smtp-Source: AGHT+IEqD8jB7DZRDff3wa6lm4aIPSD4WBlnXQHi6swowhnyqlfL+lWrTY+sLIQr+iOsVRLrqycpsA== X-Received: by 2002:a05:620a:2492:b0:795:be11:c626 with SMTP id af79cd13be357-79810177b06mr1133268285a.26.1718394454842; Fri, 14 Jun 2024 12:47:34 -0700 (PDT) Received: from smtpclient.apple ([172.59.218.20]) by smtp.gmail.com with ESMTPSA id af79cd13be357-798abc03844sm175062385a.75.2024.06.14.12.47.33 (version=TLS1_2 cipher=ECDHE-ECDSA-AES128-GCM-SHA256 bits=128/128); Fri, 14 Jun 2024 12:47:34 -0700 (PDT) From: Chris Hoover Message-Id: <290BB1BE-4F67-4CE5-84B3-67DA8B43DAFA@aweber.com> Content-Type: multipart/alternative; boundary="Apple-Mail=_4A3C716A-023C-4DA2-8294-C12B29920AC5" Mime-Version: 1.0 (Mac OS X Mail 16.0 \(3774.500.171.1.1\)) Subject: Re: Outage caused by query in IPC:MessageQueueReceive wait???? Date: Fri, 14 Jun 2024 15:47:22 -0400 In-Reply-To: Cc: pgsql-admin@lists.postgresql.org To: Paul Barrett References: <33F68D47-1D2D-4DB8-B753-BE83A3FA653E@aweber.com> <464C0807-4299-42B4-81E8-AC8D016C3AC7@aweber.com> X-Mailer: Apple Mail (2.3774.500.171.1.1) List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --Apple-Mail=_4A3C716A-023C-4DA2-8294-C12B29920AC5 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Unfortunately I don=E2=80=99t. I do snapshot pg_locks and = pg_stat_statements every minute (along with several other catalogs). I = was able to back trace to this single query in a transaction causing = issue: ``` snapped_at | 2024-06-14 10:00:00.024303-04 pid | 13900 ... backend_start | 2024-06-14 09:59:09.604535-04 xact_start | 2024-06-14 09:59:50.026618-04 query_start | 2024-06-14 09:59:50.881825-04 state_change | 2024-06-14 09:59:50.881826-04 wait_event_type | IPC wait_event | MessageQueueReceive state | active backend_xid | 2334413815 backend_xmin | 2334413815 ... ``` Here are the minute by minute log showing the query stuck for 16 = minutes: ``` select snapped_at, pid, wait_event_type, wait_event from = pg_stat_activity_snapshot_table where snapped_at >=3D '2024-06-14 09:50' = and snapped_at < '2024-06-14 10:20' and pid =3D 13900 order by = snapped_at ; snapped_at | pid | wait_event_type | = wait_event = -------------------------------+-------+-----------------+----------------= ----- 2024-06-14 10:00:00.024303-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:01:00.013122-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:02:00.011187-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:03:00.010872-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:04:00.013126-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:05:00.019508-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:06:00.010661-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:07:00.011247-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:08:00.010288-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:09:00.011029-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:10:00.021545-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:11:00.011503-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:12:00.010562-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:13:00.011171-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:14:00.01087-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:15:00.01752-04 | 13900 | IPC | = MessageQueueReceive 2024-06-14 10:16:00.010518-04 | 13900 | IPC | = MessageQueueReceive (17 rows) ``` Thanks, Chris Hoover Senior DBA AWeber.com Cell: (803) 528-2269 Email: chrish@aweber.com > On Jun 14, 2024, at 2:27=E2=80=AFPM, Paul Barrett = wrote: >=20 > Hi Chris, > Do you have log_lock_waits enabled? If yes, check the Postgres log to = see what process was causing the block/lock. I hope this helps. >=20 > Thanks, > Paul B >=20 > On Fri, Jun 14, 2024 at 2:19=E2=80=AFPM Chris Hoover = > wrote: >> Yes, it appeared to be in a transaction. The = pg_stat_activity.xact_start was before the query_start. Unfortunately, = I don=E2=80=99t have the other queries. (I snapshot pg_stat_activity = every minute, so it missed any prior queries to the blocker). >>=20 >> Thanks, >>=20 >>=20 >> Chris Hoover >> Senior DBA >> AWeber.com >> Cell: (803) 528-2269 >> Email: chrish@aweber.com >>=20 >>=20 >>=20 >>> On Jun 14, 2024, at 2:16=E2=80=AFPM, Ozgur Kulu > wrote: >>>=20 >>> Hi chris,=20 >>>=20 >>> Is this query in transaction block ?=20 >>>=20 >>> 14 Haz 2024 Cum 20:03 tarihinde Chris Hoover > =C5=9Funu yazd=C4=B1: >>>> Forgot to mention, this is on PG 16.1 >>>>=20 >>>> Thanks, >>>>=20 >>>>=20 >>>> Chris Hoover >>>> Senior DBA >>>> AWeber.com >>>> Cell: (803) 528-2269 >>>> Email: chrish@aweber.com >>>>=20 >>>>=20 >>>>=20 >>>>> On Jun 14, 2024, at 12:52=E2=80=AFPM, Chris Hoover = > wrote: >>>>>=20 >>>>> All, >>>>>=20 >>>>> We had an outage today that appears to have been caused by a query = in "IPC:MessageQueueReceive=E2=80=9D wait state blocking another query = from completing a truncate. =20 >>>>>=20 >>>>> Is there anyway to figure out what exactly it was waiting on other = than an IPC message? I=E2=80=99m trying to get to the true root cause = of our outage. >>>>>=20 >>>>> Thanks, >>>>>=20 >>>>>=20 >>>>> Chris Hoover >>>>> Senior DBA >>>>> AWeber.com >>>>> Cell: (803) 528-2269 >>>>> Email: chrish@aweber.com >>>>>=20 >>>>>=20 >>>>>=20 >>>>=20 >>=20 --Apple-Mail=_4A3C716A-023C-4DA2-8294-C12B29920AC5 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 Unfortunately = I don=E2=80=99t.  I do snapshot pg_locks and pg_stat_statements = every minute (along with several other catalogs).  I was able to = back trace to this single query in a transaction causing = issue:

```
snapped_at     =   | 2024-06-14 10:00:00.024303-04
pid     =                 | = 13900
...
backend_start    | 2024-06-14 = 09:59:09.604535-04
xact_start         =   | 2024-06-14 09:59:50.026618-04
query_start   =      | 2024-06-14 = 09:59:50.881825-04
state_change       | = 2024-06-14 09:59:50.881826-04
wait_event_type   | = IPC
wait_event           | = MessageQueueReceive
state           =          | active
backend_xid   =      | 2334413815
backend_xmin     | = 2334413815
...
```

Here are = the minute by minute log showing the query stuck for 16 = minutes:
```
select snapped_at, pid, = wait_event_type, wait_event from pg_stat_activity_snapshot_table where = snapped_at >=3D '2024-06-14 09:50' and snapped_at < '2024-06-14 = 10:20' and pid =3D 13900 order by = snapped_at
;
          = snapped_at           |  pid  | = wait_event_type |     = wait_event
-------------------------------+-------+-------------= ----+---------------------
 2024-06-14 10:00:00.024303-04 = | 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:01:00.013122-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:02:00.011187-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:03:00.010872-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:04:00.013126-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:05:00.019508-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:06:00.010661-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:07:00.011247-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:08:00.010288-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:09:00.011029-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:10:00.021545-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:11:00.011503-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:12:00.010562-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:13:00.011171-04 | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:14:00.01087-04  | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:15:00.01752-04  | = 13900 | IPC             | = MessageQueueReceive
 2024-06-14 10:16:00.010518-04 | = 13900 | IPC             | = MessageQueueReceive
(17 = rows)
```

Thanks,


Chris = Hoover
Senior DBA
AWeber.com
Cell: (803) = 528-2269
Email: chrish@aweber.com



On Jun 14, 2024, at 2:27=E2=80=AFP= M, Paul Barrett <tinojam@gmail.com> wrote:

Hi Chris,
Do you have log_lock_waits enabled? If = yes, check the Postgres log to see what process was causing the = block/lock. I hope = this helps.

Thanks,
Paul = B

On Fri, Jun 14, 2024 at 2:19=E2=80=AFPM Chris = Hoover <chrish@aweber.com> = wrote:
Yes,  it appeared to be in = a transaction.  The pg_stat_activity.xact_start was before the = query_start.  Unfortunately, I don=E2=80=99t have the other = queries.  (I snapshot pg_stat_activity every minute, so it missed = any prior queries to the blocker).

Thanks,


Chris = Hoover
Senior DBA
AWeber.com
Cell: (803) = 528-2269



On Jun 14, 2024, at 2:16=E2=80=AFP= M, Ozgur Kulu <kuluozgur@gmail.com> wrote:

Hi chris, 

Is this query in transaction block = ? 

14 Haz 2024 Cum 20:03 tarihinde Chris Hoover <chrish@aweber.com> =C5=9Funu = yazd=C4=B1:
Forgot to mention, this is on PG = 16.1

Thanks,


Chris = Hoover
Senior DBA
AWeber.com
Cell: (803) = 528-2269



On Jun 14, 2024, at 12:52=E2=80=AF= PM, Chris Hoover <chrish@aweber.com> = wrote:

All,

We had an outage = today that appears to have been caused by a query in "IPC:MessageQueueRe= ceive=E2=80=9D wait state blocking another query from completing a = truncate.  

<= /span>
Is there = anyway to figure out what exactly it was waiting on other than an IPC = message?  I=E2=80=99m trying to get to the true root cause of our = outage.

Thanks,


Chris = Hoover
Senior DBA
AWeber.com
Cell: (803) = 528-2269


=



= --Apple-Mail=_4A3C716A-023C-4DA2-8294-C12B29920AC5--