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 1t673L-00AjKW-Ps for pgsql-general@arkaria.postgresql.org; Wed, 30 Oct 2024 11:39:56 +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 1t673K-0085zQ-3t for pgsql-general@arkaria.postgresql.org; Wed, 30 Oct 2024 11:39:54 +0000 Received: from makus.postgresql.org ([2001:4800:3e1:1::229]) by malur.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (Exim 4.94.2) (envelope-from ) id 1t673J-0085z3-Ea for pgsql-general@lists.postgresql.org; Wed, 30 Oct 2024 11:39:54 +0000 Received: from mail-ej1-x643.google.com ([2a00:1450:4864:20::643]) by makus.postgresql.org with esmtps (TLS1.3) tls TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (Exim 4.94.2) (envelope-from ) id 1t673C-003c8N-HF for pgsql-general@lists.postgresql.org; Wed, 30 Oct 2024 11:39:52 +0000 Received: by mail-ej1-x643.google.com with SMTP id a640c23a62f3a-a9acafdb745so147011166b.0 for ; Wed, 30 Oct 2024 04:39:46 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20230601; t=1730288384; x=1730893184; darn=lists.postgresql.org; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:from:to:cc:subject:date:message-id:reply-to; bh=nPRiCmFU12GmzDW/VUW0+JNgOmX7DNcMvNtAjzI0cOE=; b=lDOkUW97+IhwBPPEvZcm7FST5NhG7uufP3JmuCEbndhIaduEG/WtqxNM0amh4m6uaa xKuZoePGBCpTc39jD7+BlQwTSngncO9RvpFt2tIkz8YIMEdeF8fCyy2+dweNqlkZS0ut xrzsRkGWKyLvTxzl7mxYPsLNVGyAmRThjKdBu5JJrpt6G1duhlnxstfNc8OoxdAISy45 Br0bIAKZ7fNLtg3v17d8EUgqSgIa+vSAczNbaBh3Dq0yJ8l4BACedbdu6WiZf/cuL5jx OX35Vu34lGTBDzb3qeG1y5OCBxKLg+MkyNYS3yTjD2otZzDeVQkrDdj4XxSJ+Lv+x9wC kn3w== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20230601; t=1730288384; x=1730893184; h=cc:to:subject:message-id:date:from:in-reply-to:references :mime-version:x-gm-message-state:from:to:cc:subject:date:message-id :reply-to; bh=nPRiCmFU12GmzDW/VUW0+JNgOmX7DNcMvNtAjzI0cOE=; b=ROTtFTN+9IjZ/jSxaSIA0NaDM4NgTl8yIIROpP3BWJEU82AsJQqBEHGadhlDaA1w9f 8M73YxbiO2a/loXZtz1ZAX4DcUWJHK0728zr1d9BR140krUPuuJnAyJ59dxbtFQ+DwiZ ghVJiAoL32/Es9XdZdA4gAv1hl/bSOPVENiDR/r8BpfwgR/c3B4SVxhTzb+6RbigdV+S z/P7LY0vwvQZpyRZ+IXPuv3VLvHoPyawspck2xD7i4BLZDK7BYL6GTriXSWjI2d+UIf2 08ams2szduEtaQ/oRsfU7WX0jkAdqB8pDi3a8D5uB96h/Xzwskpi2KjRS0u0H0f73LDW l4Nw== X-Gm-Message-State: AOJu0YzzIVUUK8eWYfC96N1JQvktTCywskVqw7NUL0RH9cyIKyA1ANZp YhC/MS2qmuKYMK7xHnHw5vnsTH9HAL05UZ8Sct0tQHKc9vJR0YAk4CkJr7I1rSrjg0HDjSkghvk vMSAJn7qLmFuy7Anid7pye1E+m13ur9B78zI= X-Google-Smtp-Source: AGHT+IH33IWxZ7jsfu8hnPZ45y7YZ/Leai2M7VBFicrXc1ZCt12/r29QEI1x99+9yTjr6lKHgWzoPeHyS4L36kcgxps= X-Received: by 2002:a17:907:7d9e:b0:a9a:1af0:ee1a with SMTP id a640c23a62f3a-a9e2b32ec9fmr550691466b.6.1730288383733; Wed, 30 Oct 2024 04:39:43 -0700 (PDT) MIME-Version: 1.0 References: In-Reply-To: From: Vijaykumar Jain Date: Wed, 30 Oct 2024 17:09:30 +0530 Message-ID: Subject: Re: Random memory related errors on live postgres 14.13 instance on Ubuntu 22.04 LTS To: Ian J Cottee Cc: pgsql-general@lists.postgresql.org Content-Type: multipart/alternative; boundary="00000000000078b3f40625b02892" List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Archived-At: Precedence: bulk --00000000000078b3f40625b02892 Content-Type: text/plain; charset="UTF-8" Content-Transfer-Encoding: quoted-printable On Wed, 30 Oct 2024 at 13:04, Ian J Cottee wrote: > Hello everyone, I=E2=80=99ve been using postgres for over 25 years now an= d never > had any major issues which were not caused by my own stupidity. In the la= st > 24 hours however I=E2=80=99ve had a number of issues on one client's serv= er which I > assume are a bug in postgres or a possible hardware issue (they are runni= ng > on a Linode) but I need some clarification and would welcome advice on ho= w > to proceed. I will also forward this mail to Linode support to ask them t= o > check for any memory issues they can detect. > > > > This particular Postgres is running on Ubuntu LTS 22.04 and has the > following version information: > > > > ``` > > PostgreSQL 14.13 (Ubuntu 14.13-0ubuntu0.22.04.1) on x86_64-pc-linux-gnu, > compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit > > ``` > > > The quick summary is that over a 24 hour period I had the following error= s > appear in the postgres logs at different times causing the system process= es > to restart: > > > - stuck spinlock detected > - free(): corrupted unsorted chunks > - double free or corruption (!prev) > - corrupted size vs. prev_size > - corrupted double-linked list > - *** stack smashing detected ***: terminated > - Segmentation fault > > > are you using the postgresql setup compiled from source ? listing the output of pg_config may give the details are there any extensions installed, can you list those extensions. if you have access to source packages , Getting a stack trace of a running PostgreSQL backend on Linux/BSD - PostgreSQL wiki can you generate a stacktrace from the process that is crashing or if it dumped a core, then backtrace from the core dump. will it be possible to share the actual logs both postgresql and kernel around the incident ... Do you have access to core dumps which these crashes may have generated ? i think ABRT / segmentation faults would generate one. do you collect stats of system. around the time of crash do you any abnormal usage of io or cpu or memory , along with locks held in postgresql setup etc. > Here=E2=80=99s the more detailed breakdown. > > > > On Monday evening this week, the following event occurred on the server > > > > ``` > > 2024-10-28 18:12:47.145 GMT [575437] xxx@xxx PANIC: stuck spinlock > detected at LWLockWaitListLock, > ./build/../src/backend/storage/lmgr/lwlock.c:913 > ``` > > > I think a backtrace here would help what part of call stack led to this. this alone does not look like any bug. > Followed by: > > > > ``` > > 2024-10-28 18:12:47.249 GMT [1880289] LOG: terminating any other active > server processes > > 2024-10-28 18:12:47.284 GMT [1880289] LOG: all server processes > terminated; reinitializing > > ``` > > And eventually > > > ``` > > 2024-10-28 18:12:48.474 GMT [575566] xxx@xxx FATAL: the database system > is in recovery mode > > 2024-10-28 18:12:48.476 GMT [575550] LOG: database system was not properl= y > shut down; automatic recovery in progress > > 2024-10-28 18:12:48.487 GMT [575550] LOG: redo starts at DD/405E83A8 > > 2024-10-28 18:12:48.487 GMT [575550] LOG: invalid record length at > DD/405EF818: wanted 24, got 0 > > 2024-10-28 18:12:48.487 GMT [575550] LOG: redo done at DD/405EF7E0 system > usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s > > 2024-10-28 18:12:48.515 GMT [1880289] LOG: database system is ready to > accept connections > > ``` > > This wasn=E2=80=99t noticed by myself or any users as they tend to all be= finished > by 17:30. However later, > > > > ``` > > 2024-10-28 20:27:15.258 GMT [611459] xxx@xxx LOG: unexpected EOF on > client connection with an open transaction > > 2024-10-28 21:01:05.934 GMT [620373] xxx@xxxx LOG: unexpected EOF on > client connection with an open transaction > > free(): corrupted unsorted chunks > it all seems like memory corruption or some leak ... valgrind ? to get more details if leak ... > 2024-10-28 21:15:02.203 GMT [1880289] LOG: server process (PID 623803) wa= s > terminated by signal 6: Aborted > > 2024-10-28 21:15:02.204 GMT [1880289] LOG: terminating any other active > server processes > > ``` > > > > This time it could not recover and I didn=E2=80=99t notice until early th= e next > morning whilst doing some routine checks. > > > > ``` > > 2024-10-28 21:15:03.643 GMT [623807] LOG: database system was not properl= y > shut down; automatic recovery in progress > > 2024-10-28 21:15:03.655 GMT [623807] LOG: redo starts at DD/47366740 > > 2024-10-28 21:15:03.663 GMT [623807] LOG: invalid record length at > DD/475452A0: wanted 24, got 0 > > 2024-10-28 21:15:03.663 GMT [623807] LOG: redo done at DD/47545268 system > usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s > > 2024-10-28 21:15:03.682 GMT [623829] xxx@xxx FATAL: the database system > is in recovery mode > > double free or corruption (!prev) > > 2024-10-28 21:15:03.832 GMT [1880289] LOG: startup process (PID 623807) > was terminated by signal 6: Aborted > > 2024-10-28 21:15:03.832 GMT [1880289] LOG: aborting startup due to startu= p > process failure > > 2024-10-28 21:15:03.835 GMT [1880289] LOG: database system is shut down > > ``` > > > > When I noticed in the morning it was able to start without an issue. From > googling it appeared to be a memory issue and I wondered if the problem w= as > sorted now the server process had stopped completely and restarted. The > problem was not sorted although all the above errors were recovered from > automatically without any input from myself or the client=E2=80=99s notic= ing. > > > > ``` > > corrupted size vs. prev_size > > 2024-10-29 09:55:24.417 GMT [894747] LOG: background worker "parallel > worker" (PID 947642) was terminated by signal 6: Aborted > > ``` > > > > ``` > > corrupted double-linked list > > 2024-10-29 13:14:28.322 GMT [894747] LOG: background worker "parallel > worker" (PID 1019071) was terminated by signal 6: Aborted > > ``` > > > > ``` > > *** stack smashing detected ***: terminated > > 2024-10-28 15:24:30.331 GMT [1880289] LOG: background worker "parallel > worker" (PID 528630) was terminated by signal 6: A\ borted > > ``` > > > > ``` > > 2024-10-28 15:40:26.617 GMT [1880289] LOG: background worker "parallel > worker" (PID 533515) was terminated by signal 11: \ > > Segmentation fault > > 2024-10-28 15:40:26.617 GMT [1880289] DETAIL: Failed process was running: > SELECT "formula_line".id FROM "formul\ > > ``` > > idk why it crashed with sigabrt instead of sigkill if it was indeed a memory leak and not a bug ... so not sure memory overcommiting can be of use here ... how much is the concurrency at peak and with what work mem .... any theory of excessive work mem and too many concurrent processes holding some locks for long ... it should not crash even if that is the case, but just asking ... lastly.... is it possible to memcheck run on the machine just to ensure no memory scares ... if this is running on a vm, or bare metal ,,,, any hardware errors around that time ? most likely it looks like a h/w issue, we used to see things like this on bare metals .... which only happened occasionally and then frequently till we moved away from that setup. also, does it happen only when the optimiser picks a plan involving parallel workers for a query? If you set max_parallel_workers_per_gather to 0, to not parallelize anything , do you still see the issue ? Just insights, if not useful, pls ignore. > Best regards > > > Ian Cottee > > > > > > > > > > > > > > > --=20 Thanks, Vijay Open to work Resume - Vijaykumar Jain --00000000000078b3f40625b02892 Content-Type: text/html; charset="UTF-8" Content-Transfer-Encoding: quoted-printable


On = Wed, 30 Oct 2024 at 13:04, Ian J Cottee <ian@cottee.org> wrote:

Hello everyone, I=E2=80=99ve been using postgres for over 25 years now and never had any major issues which were not caused by my own stupidit= y. In the last 24 hours however I=E2=80=99ve had a number of issues on one cli= ent's server which I assume are a bug in postgres or a possible hardware issue (they are running on a L= inode) but I need some clarification and would welcome advice on how to proceed. I will also = forward this mail to Linode support to ask them to check for any memory iss= ues they can detect.=C2=A0

=C2=A0

This particular Postgres is running on Ubuntu LTS 22.04 and has the following version information:

=C2=A0

```

PostgreSQL 14.13 (Ubuntu 14.13-0ubuntu0.22.04.1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit

```


The quick summary is = that over a 24 hour period I had the following errors appear in the postgres logs at different times causing the system processes to restart:

  • stuck spinlock detected=C2=A0
  • free(): corrupted unsorted chunks=C2= =A0
  • double free or corruption (!prev)
  • corrupted size vs. pr= ev_size=C2=A0
  • corrupted double-linked list=C2=A0
  • *** stack = smashing detected ***: terminated=C2=A0
  • Segmentation fault=C2=A0

=C2=A0


are you using the postgresql setup compiled from source ?=C2=A0
= listing the output of pg_config may give the details=C2=A0

are there any extensions installed, can you list those extensions.=

if you have access to source packages ,=C2=A0
can you= generate a stacktrace=C2=A0from the process that is crashing or if it dump= ed a core, then backtrace from the core dump.

will= it be possible to share the actual logs both postgresql and kernel around = the incident ...=C2=A0

Do you have access to core = dumps which these crashes may have generated ? i think ABRT / segmentation = faults would generate one.

do you collect stats of= system. around the time of crash do you any abnormal usage of io or cpu or= memory , along with locks held in postgresql setup etc.



=C2=A0

Here=E2=80=99s the more detailed breakdown.=C2=A0

=C2=A0

On Monday evening this week, the following event occurred on t= he server

=C2=A0

```

2024-10-28 18:12:47.145 GMT [575437] xxx@xxx PANIC: stuck spinlock detected at LWLockWaitListLock, ./build/../src/backend/storage/lmgr/lwlock.c:913=C2=A0

```

=C2=A0

I think a backtrace here wou= ld help what part of call stack led to this. this alone does not look like = any bug.


=C2=A0

Followed by:

=C2=A0

```

2024-10-28 18:12:47.249 GMT [1880289] LOG: terminating any other active server processes

2024-10-28 18:12:47.284 GMT [1880289] LOG: all server processes terminated; reinitializing

```

And eventually


```

2024-10-28 18:12:48.474 GMT [575566] xxx@xxx FATAL: the database system is in recovery mode

2024-10-28 18:12:48.476 GMT [575550] LOG: database system was not properly shut down; automatic recovery in progress

2024-10-28 18:12:48.487 GMT [575550] LOG: redo starts at DD/405E83A8

2024-10-28 18:12:48.487 GMT [575550] LOG: invalid record length at DD/405EF818: wanted 24, got 0

2024-10-28 18:12:48.487 GMT [575550] LOG: redo done at DD/405EF7E0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 = s

2024-10-28 18:12:48.515 GMT [1880289] LOG: database system is ready to accept connections

```

This wasn=E2=80=99t noticed by myself or any users as they ten= d to all be finished by 17:30.=C2=A0 However later,

=C2=A0

=C2=A0

```

2024-10-28 20:27:15.258 GMT [611459] xxx@xxx LOG: unexpected EOF on client connection with an open transaction

2024-10-28 21:01:05.934 GMT [620373] xxx@xxxx LOG: unexpected EOF on client connection with an open transaction

free(): corrupted unsorted chunks

<= br>
it all seems like memory corruption or some leak ... valgrind= ? to get more details if leak ...

=C2=A0

2024-10-28 21:15:02.203 GMT [1880289] LOG: server process (PID 623803) was terminated by signal 6: Aborted

2024-10-28 21:15:02.204 GMT [1880289] LOG: terminating any other active server processes

```

=C2=A0

This time it could not recover and I didn=E2=80=99t notice unt= il early the next morning whilst doing some routine checks.

=C2=A0

```

2024-10-28 21:15:03.643 GMT [623807] LOG: database system was not properly shut down; automatic recovery in progress

2024-10-28 21:15:03.655 GMT [623807] LOG: redo starts at DD/47366740

2024-10-28 21:15:03.663 GMT [623807] LOG: invalid record length at DD/475452A0: wanted 24, got 0

2024-10-28 21:15:03.663 GMT [623807] LOG: redo done at DD/47545268 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 = s

2024-10-28 21:15:03.682 GMT [623829] xxx@xxx FATAL: the database system is in recovery mode

double free or corruption (!prev)

2024-10-28 21:15:03.832 GMT [1880289] LOG: startup process (PID 623807) was terminated by signal 6: Aborted

2024-10-28 21:15:03.832 GMT [1880289] LOG: aborting startup due to startup process failure

2024-10-28 21:15:03.835 GMT [1880289] LOG: database system is shut down

```

=C2=A0

When I noticed in the morning it was able to start without an issue. From googling it appeared to be a memory issue and I wondered if = the problem was sorted now the server process had stopped completely and restar= ted. The problem was not sorted although all the above errors were recovered fro= m automatically without any input from myself or the client=E2=80=99s noticin= g.

=C2=A0

```

corrupted size vs. prev_size

2024-10-29 09:55:24.417 GMT [894747] LOG: background worker "parallel worker" (PID 947642) was terminated by signal 6: Aborte= d

```

=C2=A0

```

corrupted double-linked list

2024-10-29 13:14:28.322 GMT [894747] LOG: background worker "parallel worker" (PID 1019071) was terminated by signal 6: Abort= ed

```

=C2=A0

```

*** stack smashing detected ***: terminated

2024-10-28 15:24:30.331 GMT [1880289] LOG: background worker "parallel worker" (PID 528630) was terminated by signal 6: A\ bor= ted

```

=C2=A0

```

2024-10-28 15:40:26.617 GMT [1880289] LOG: background worker "parallel worker" (PID 533515) was terminated by signal 11: \

Segmentation fault

2024-10-28 15:40:26.617 GMT [1880289] DETAIL: Failed process was running: SELECT "formula_line".id FROM "formul\

```

<= div>

idk why it=C2=A0crashed with sigabrt inst= ead of sigkill if it was indeed a memory leak and not a bug ... so not sure= memory overcommiting=C2=A0can be of use here ...

= how much is the concurrency at peak and with what work mem .... any theory = of excessive work mem and too many concurrent processes holding some locks = for long ...
it should not crash even if that is the case, but ju= st asking ...

lastly.... is it possible to memchec= k run on the machine just to ensure no memory scares ... if this is running= on a vm, or bare metal ,,,, any hardware errors around that time ?

most likely it looks like a h/w issue, we used to see thi= ngs like this on bare metals .... which only happened occasionally and then= frequently till we moved away from that setup.

al= so, does it happen only when the optimiser picks a plan involving parallel = workers=C2=A0 for a query?
If you set=C2=A0max_parallel_workers_per_gather to 0, to not paralle= lize=C2=A0anything , do you still see the issue ?
Just insights, if not useful, pls ignore.

=C2=A0



=C2=A0

Bes= t regards


Ian Cottee



=C2=A0

=C2=A0

=C2=A0

=C2=A0

=C2=A0

=C2=A0



--
Thanks,
Vijay

Open = to work
Resume -=C2=A0Vijaykumar Jain
--00000000000078b3f40625b02892--