error "can only drop stats once" brings down database

Floris Van Nee <florisvannee@Optiver.com> writes:

Hi,
On a database we have we've recently seen a fatal error occur twice. The error happened on two different physical replicas (of the same cluster) during a WAL redo action in the recovery process. They're running Postgres 15.5.

Occurrence 1:
2024-02-01 06:55:54.476 CET,,,70290,,65a29b60.11292,6,,2024-01-13 15:17:04 CET,1/0,0,FATAL,XX000,"can only drop stats once",,,,,"WAL redo at A7BD1/D6F9B6C0 for Transaction/COMMIT: 2024-02-01 06:55:54.395851+01; ...

Hmm. This must be coming from pgstat_drop_entry_internal.
I suspect the correct fix is in pgstat_drop_entry, along
the lines of

-	if (shent)
+	if (shent && !shent->dropped)

but it's not clear to me how the already-dropped case ought to affect
the function's bool result. Also, how are we getting into a
concurrent-drop situation in recovery?

regards, tom lane

Floris Van Nee <florisvannee@Optiver.com> writes:

Hi,
On a database we have we've recently seen a fatal error occur twice. The

error happened on two different physical replicas (of the same cluster)
during a WAL redo action in the recovery process. They're running Postgres
15.5.

Occurrence 1:
2024-02-01 06:55:54.476 CET,,,70290,,65a29b60.11292,6,,2024-01-13 15:17:04

CET,1/0,0,FATAL,XX000,"can only drop stats once",,,,,"WAL redo at
A7BD1/D6F9B6C0 for Transaction/COMMIT: 2024-02-01 06:55:54.395851+01;
...

Hmm. This must be coming from pgstat_drop_entry_internal.
I suspect the correct fix is in pgstat_drop_entry, along the lines of

-	if (shent)
+	if (shent && !shent->dropped)

but it's not clear to me how the already-dropped case ought to affect the
function's bool result. Also, how are we getting into a concurrent-drop
situation in recovery?

Anyone has further thoughts on this? This still happens occasionally.

-Floris

Floris Van Nee <florisvannee@Optiver.com> writes:

Hmm. This must be coming from pgstat_drop_entry_internal.
I suspect the correct fix is in pgstat_drop_entry, along the lines of

-	if (shent)
+	if (shent && !shent->dropped)

but it's not clear to me how the already-dropped case ought to affect the
function's bool result. Also, how are we getting into a concurrent-drop
situation in recovery?

Anyone has further thoughts on this? This still happens occasionally.

I was expecting Andres to comment on it eventually. I don't know
that code well enough to want to modify it on my own authority,
especially not just before a release.

One thing that would be safe enough and perhaps useful is to
modify the "can only drop stats once" message to provide a
little more detail, like the hash key of the problematic
entry. That might help us understand what's triggering this.
The OIDs would be opaque perhaps, but the PgStat_Kind value
seems useful to know.

regards, tom lane

Hello Floris,

03.05.2024 21:10, Floris Van Nee wrote:

Floris Van Nee <florisvannee@Optiver.com> writes:

Hi,
On a database we have we've recently seen a fatal error occur twice. The

error happened on two different physical replicas (of the same cluster)
during a WAL redo action in the recovery process. They're running Postgres
15.5.

Occurrence 1:
2024-02-01 06:55:54.476 CET,,,70290,,65a29b60.11292,6,,2024-01-13 15:17:04

CET,1/0,0,FATAL,XX000,"can only drop stats once",,,,,"WAL redo at
A7BD1/D6F9B6C0 for Transaction/COMMIT: 2024-02-01 06:55:54.395851+01;
...

Hmm. This must be coming from pgstat_drop_entry_internal.
I suspect the correct fix is in pgstat_drop_entry, along the lines of

-	if (shent)
+	if (shent && !shent->dropped)

but it's not clear to me how the already-dropped case ought to affect the
function's bool result. Also, how are we getting into a concurrent-drop
situation in recovery?

Anyone has further thoughts on this? This still happens occasionally.

Please take a look at bug #17947 (maybe you encounter the same?):
/messages/by-id/17947-b9554521ad963c9c@postgresql.org

Best regards,
Alexander

Hi,

On 2024-05-03 18:10:05 +0000, Floris Van Nee wrote:

Floris Van Nee <florisvannee@Optiver.com> writes:

Hi,
On a database we have we've recently seen a fatal error occur twice. The

error happened on two different physical replicas (of the same cluster)
during a WAL redo action in the recovery process. They're running Postgres
15.5.

Occurrence 1:
2024-02-01 06:55:54.476 CET,,,70290,,65a29b60.11292,6,,2024-01-13 15:17:04

CET,1/0,0,FATAL,XX000,"can only drop stats once",,,,,"WAL redo at
A7BD1/D6F9B6C0 for Transaction/COMMIT: 2024-02-01 06:55:54.395851+01;
...

Hmm. This must be coming from pgstat_drop_entry_internal.
I suspect the correct fix is in pgstat_drop_entry, along the lines of

-	if (shent)
+	if (shent && !shent->dropped)

but it's not clear to me how the already-dropped case ought to affect the
function's bool result.

I don't think that'd be quite right - just ignoring that we're confused about
tracking "stats object" liveliness seems likely to hide bugs.

Elsewhere in this thread you suggested adding more details about the error -
let's do that. Something like the attached might already be an improvement?

Also, how are we getting into a concurrent-drop situation in recovery?

I'd like to know how we get into the situation too. It's perhaps worth noting
that stats can be generated on a standby, albeit not by the replay
process. But locking should prevent active use of the stats entry when it's
being dropped...

Anyone has further thoughts on this? This still happens occasionally.

Do you have any more details about the workload leading to this issue? Is the
standby used for queries? Given the "high value" your oids/relfilenodes have,
I assume there are a lot of created/dropped/truncated relations?

Greetings,

Andres Freund

Hi,

On 2024-05-05 09:09:15 -0700, Andres Freund wrote:

Do you have any more details about the workload leading to this issue? Is the
standby used for queries? Given the "high value" your oids/relfilenodes have,
I assume there are a lot of created/dropped/truncated relations?

I suspect that the "high value" oids are related to the issue. I bet you're
running into OID wraparound for objects at a much higher frequency than most
users. I suspect the reason this causes problems is the problem I just found
and described here:
/messages/by-id/20240505183741.5tefii3razzefvtc@awork3.anarazel.de

Could you confirm that you have a) a lot of oid assignments b) your startup
process was running for a long time by the time of the crash?

The fact that we're not triggering "stats object garbage collection" for most
drops also explains why you're much more likely to see this on a standby than
on a primary. An a primary it's going to be rare to have a single backend live
long enough to observe an oid wraparound leading to one backend accessing
stats for the same object type with the same oid after that object previously
having been dropped. But most stats accesses on a standby are going to be by
the same process, the startup process. You'd still need some other accesses
to prevent the object from being dropped "immediately", but that could be due
to shorter lived processes.

Greetings,

Andres Freund

Could you confirm that you have a) a lot of oid assignments b) your startup
process was running for a long time by the time of the crash?

Thanks Andres. Both higher than average I guess, although it depends on what is considered 'a lot' and 'a long time'. The startup process was running for a few months. There are ~500k entries in pg_class, of which most are (Timescale) partitions. However, even with this number of items in pg_class I would't expect wraparound to happen frequently? These are not dropped/recreated. I've monitored "select count(*) from pg_class" for a while to see if it changes often, and while there are changes during the day (likely temporary tables being created), it also doesn't nearly happen at a frequency that will get us to a wraparound quickly.

Oids aren't just consumed by pg_class though. And I do see system oid growing quickly (when doing CREATE TABLE twice with a minute in between, then checking the oid difference of the table). I don't know how to investigate the cause of this. What would be the best way to check what could be consuming these oids so quickly?

-Floris

I suspect that the "high value" oids are related to the issue. I bet you're
running into OID wraparound for objects at a much higher frequency than
most users. I suspect the reason this causes problems is the problem I just
found and described here:

I definitely suspect oid wraparound has something to do with it. However, given what I found on the other thread ( /messages/by-id/17947-b9554521ad963c9c@postgresql.org ), I don't think the two have the exact same root cause. The other thread seems a clear case of 'forgot to call gc' when it should.

The fact that we're not triggering "stats object garbage collection" for most
drops also explains why you're much more likely to see this on a standby
than on a primary. An a primary it's going to be rare to have a single backend
live long enough to observe an oid wraparound leading to one backend
accessing stats for the same object type with the same oid after that object
previously having been dropped. But most stats accesses on a standby are
going to be by the same process, the startup process. You'd still need some
other accesses to prevent the object from being dropped "immediately", but
that could be due to shorter lived processes.

As mentioned on other thread, I do think garbage collection gets called as part of pgstat_execute_transactional_drops in recovery.

There's still the case of the "skip gc of entry if pending" though, however I struggle to understand how this can lead to such an error in the recovery process after wraparound. I'd expect the gc to happen relatively frequently (at least much more frequently than a wraparound) as tables get created/dropped quite frequently. Next to that, because the recovery process is the only one creating/dropping relations on standby, it should be impossible to get in a state where the recovery "local" stats cache has a non-gc'd entry that should be dropped? Because when dropping, at least it removes the local cache entry (even if it cannot remove the shared one). So later, when creating it again in pgstat_get_entry_ref, it should always hit the pgstat_reinit_entry path?

Would it make sense to at least commit your patch to enhance the error message a bit?

-Floris

On Sun, Jun 02, 2024 at 10:01:53PM +0000, Floris Van Nee wrote:

Would it make sense to at least commit your patch to enhance the
error message a bit?

FWIW, I am +1 for the improvement of this error message.

Note that there is a very similar proposal here:
/messages/by-id/ZkM30paAD8Cr/Bix@ip-10-97-1-34.eu-west-3.compute.internal

The only reason why I did not do one or the other yet is that this is
an improvement, hence I was waiting for v18 to open. If somebody
feels differently, feel free to proceed before that with the format
you like. Still I'd vote for the addition of the refcount to the
patch proposed on this thread, to provide more debugging info to the
information reported.
--
Michael

The only reason why I did not do one or the other yet is that this is an
improvement, hence I was waiting for v18 to open. If somebody feels
differently, feel free to proceed before that with the format you like. Still I'd
vote for the addition of the refcount to the patch proposed on this thread, to
provide more debugging info to the information reported.

This patch would help in getting more info about this specific issue if it reoccurs, but in that case it's only helpful if it's backpatched.
Agree the refcount addition makes sense.

-Floris

On Wed, Jun 05, 2024 at 10:31:04AM +0000, Floris Van Nee wrote:

This patch would help in getting more info about this specific issue
if it reoccurs, but in that case it's only helpful if it's
backpatched.
Agree the refcount addition makes sense.

Adding Bertrand in CC as he was similarly playing with this area.

What would both of you think about the attached. This is a mix of
what's been proposed on the two threads, with the addition of the
refcount.
--
Michael

Hi,

On Thu, Jun 06, 2024 at 01:44:26PM +0900, Michael Paquier wrote:

On Wed, Jun 05, 2024 at 10:31:04AM +0000, Floris Van Nee wrote:

This patch would help in getting more info about this specific issue
if it reoccurs, but in that case it's only helpful if it's
backpatched.
Agree the refcount addition makes sense.

Adding Bertrand in CC as he was similarly playing with this area.

What would both of you think about the attached. This is a mix of
what's been proposed on the two threads, with the addition of the
refcount.

I like the idea of adding refcount in the error message. OTOH I think it's more
appropriate to make use of errdetail_internal() as proposed in [1]/messages/by-id/ZkRsoOMrSrNI945i@ip-10-97-1-34.eu-west-3.compute.internal, but that's
a nit.

[1]: /messages/by-id/ZkRsoOMrSrNI945i@ip-10-97-1-34.eu-west-3.compute.internal

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

At Thu, 6 Jun 2024 06:05:11 +0000, Bertrand Drouvot <bertranddrouvot.pg@gmail.com> wrote in

What would both of you think about the attached. This is a mix of
what's been proposed on the two threads, with the addition of the
refcount.

I like the idea of adding refcount in the error message. OTOH I think it's more
appropriate to make use of errdetail_internal() as proposed in [1], but that's
a nit.

To me, this is something that is not expected to happen, but if it
does, we would want detailed information. In that sense, it might be
better not to hide it in the DETAILS field.

regards.

[1]: /messages/by-id/ZkRsoOMrSrNI945i@ip-10-97-1-34.eu-west-3.compute.internal

--
Kyotaro Horiguchi
NTT Open Source Software Center

On Fri, Jun 07, 2024 at 10:15:40AM +0900, Kyotaro Horiguchi wrote:

To me, this is something that is not expected to happen, but if it
does, we would want detailed information. In that sense, it might be
better not to hide it in the DETAILS field.

Same arguments here. A simple elog() makes easier to get to this
data.
--
Michael

On 2024-06-07 11:46:04 +0900, Michael Paquier wrote:

On Fri, Jun 07, 2024 at 10:15:40AM +0900, Kyotaro Horiguchi wrote:

To me, this is something that is not expected to happen, but if it
does, we would want detailed information. In that sense, it might be
better not to hide it in the DETAILS field.

Same arguments here. A simple elog() makes easier to get to this
data.

+1

Hi,

On Thu, Jun 06, 2024 at 08:12:58PM -0700, Andres Freund wrote:

On 2024-06-07 11:46:04 +0900, Michael Paquier wrote:

On Fri, Jun 07, 2024 at 10:15:40AM +0900, Kyotaro Horiguchi wrote:

To me, this is something that is not expected to happen, but if it
does, we would want detailed information. In that sense, it might be
better not to hide it in the DETAILS field.

Same arguments here. A simple elog() makes easier to get to this
data.

+1

That was a nit, so fine by me to move on with a simple elog().

Regards,

--
Bertrand Drouvot
PostgreSQL Contributors Team
RDS Open Source Databases
Amazon Web Services: https://aws.amazon.com

On Fri, Jun 07, 2024 at 09:32:13AM +0000, Bertrand Drouvot wrote:

That was a nit, so fine by me to move on with a simple elog().

Okay, I've just applied the elog() version down to 15 then. Now,
about the entry getting dropped twice..
--
Michael

Okay, I've just applied the elog() version down to 15 then. Now, about the
entry getting dropped twice..

Thanks Michael.

I've got an update about the bug. I managed to reproduce it locally after a lot of digging.

How to repro:
- Setup primary + replica
- Open a psql session on both
- On primary session: create table t (a int); select 't'::regclass::oid;
- On replica session: select * from t;
- On primary session: drop table t; vacuum pg_class; checkpoint;
- Gdb attach to the backend for your primary, set a breakpoint for
catalog.c:GetNewOidWithIndex, just before it calls GetNewObjectId()
- On primary session: create table t (a int);
- When it hits breakpoint, simulate oid wraparound by setting:
ShmemVariableCache->nextOid = <the output value of the select earlier>
This will make pg create the new table with the same oid as the previous one.
- On primary session: drop table t; -- this triggers the replica to go down

The reason it crashes on replica is that the recovery process is responsible for dropping
stats on commit, but it's not creating them on table creation. Thus, on the second create
table call, the old shared stats entry still exists (due to a backend still have a ref to it),
but it is never reinitialized by the logic in pgstat_reinit_entry(). On primary it's not possible
to reach this state, because heap_create() creates the stats entry immediately when the
table is created.

I wonder what's the best way to fix this though.
Should redo process call pgstat_create_relation somewhere, just like heap_create does?
Should we just ignore this 'drop stats twice' error on standby?

-Floris

On Sat, Jun 08, 2024 at 11:52:43AM +0000, Floris Van Nee wrote:

I've got an update about the bug. I managed to reproduce it locally
after a lot of digging.

How to repro:
- Setup primary + replica
- Open a psql session on both
- On primary session: create table t (a int); select 't'::regclass::oid;
- On replica session: select * from t;
- On primary session: drop table t; vacuum pg_class; checkpoint;
- Gdb attach to the backend for your primary, set a breakpoint for
catalog.c:GetNewOidWithIndex, just before it calls GetNewObjectId()
- On primary session: create table t (a int);
- When it hits breakpoint, simulate oid wraparound by setting:
ShmemVariableCache->nextOid = <the output value of the select earlier>
This will make pg create the new table with the same oid as the previous one.
- On primary session: drop table t; -- this triggers the replica to go down

Okay, this stuff makes the beginning of a week fun.

The reason it crashes on replica is that the recovery process is responsible for dropping
stats on commit, but it's not creating them on table creation. Thus, on the second create
table call, the old shared stats entry still exists (due to a backend still have a ref to it),
but it is never reinitialized by the logic in pgstat_reinit_entry(). On primary it's not possible
to reach this state, because heap_create() creates the stats entry immediately when the
table is created.

I wonder what's the best way to fix this though.
Should redo process call pgstat_create_relation somewhere, just like heap_create does?
Should we just ignore this 'drop stats twice' error on standby?

Nah, ignoring the double-drop error does not seem right to me.
Wouldn't it make the most sense to ensure that the stats are dropped
on the standby instead on the first DROP replayed even if there are
still references to it hold, making sure that the stats entry with
this OID is gone before reusing it after wraparound?
--
Michael