Thread

Reduce DEBUG level of catcache refreshing messages

Jelte Fennema-Nio <postgres@jeltef.nl> — 2025-05-30T12:33:27Z

When testing extensions using pgregress, it can be useful to introduce
some new DEBUG logs which are specific to the extension and change the
log level during part of the of the test.

There's a problem though: Often a "rehashing catalog cache ..." debug
message will also show up in those cases. It's not always possible to
predict when these messages show, and when they do their contents can
easily change if changes are made to an unrelated test or when run
against a different Postgres version. This change lowers the log level
of these messages to DEBUG5, so that they can be ignored while still
showing other (more predictable) DEBUG messages.

Re: Reduce DEBUG level of catcache refreshing messages

Fabrízio de Royes Mello <fabriziomello@gmail.com> — 2025-05-30T13:32:18Z

On Fri, May 30, 2025 at 9:33 AM Jelte Fennema-Nio <postgres@jeltef.nl>
wrote:

> When testing extensions using pgregress, it can be useful to introduce
> some new DEBUG logs which are specific to the extension and change the
> log level during part of the of the test.
>
> There's a problem though: Often a "rehashing catalog cache ..." debug
> message will also show up in those cases. It's not always possible to
> predict when these messages show, and when they do their contents can
> easily change if changes are made to an unrelated test or when run
> against a different Postgres version. This change lowers the log level
> of these messages to DEBUG5, so that they can be ignored while still
> showing other (more predictable) DEBUG messages.
>


This is a very good idea. In TimescaleDB we filter out such kind of output
in order to not end up with flaky test outputs.

The patch LGTM.

-- 
Fabrízio de Royes Mello

Re: Reduce DEBUG level of catcache refreshing messages

Tom Lane <tgl@sss.pgh.pa.us> — 2025-05-30T14:38:42Z

"Jelte Fennema-Nio" <postgres@jeltef.nl> writes:
> When testing extensions using pgregress, it can be useful to introduce
> some new DEBUG logs which are specific to the extension and change the
> log level during part of the of the test.

> There's a problem though: Often a "rehashing catalog cache ..." debug
> message will also show up in those cases. It's not always possible to
> predict when these messages show, and when they do their contents can
> easily change if changes are made to an unrelated test or when run
> against a different Postgres version. This change lowers the log level
> of these messages to DEBUG5, so that they can be ignored while still
> showing other (more predictable) DEBUG messages.

I don't have an opinion about the merits of this exact change, but
I wish somebody would go through all our DEBUGn messages and come up
with some coherent proposal for what the various levels should be
used for.  Right now I think those choices are purely idiosyncratic
and have been made differently in different patches.

Your usage example already suggests one possible rule:

* DEBUG1 is reserved for testing patches and should never be used
in permanent code.

Maybe that particular idea is not appropriate for some reason.
But if we could have *some* kind of explainable basis for
assigning DEBUGn levels, I think our lives would be better.

			regards, tom lane

Re: Reduce DEBUG level of catcache refreshing messages

Jelte Fennema-Nio <postgres@jeltef.nl> — 2025-05-30T22:38:32Z

On Fri, 30 May 2025 at 16:38, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> I don't have an opinion about the merits of this exact change, but
> I wish somebody would go through all our DEBUGn messages and come up
> with some coherent proposal for what the various levels should be
> used for.  Right now I think those choices are purely idiosyncratic
> and have been made differently in different patches.
>
> Your usage example already suggests one possible rule:
>
> * DEBUG1 is reserved for testing patches and should never be used
> in permanent code.
>
> Maybe that particular idea is not appropriate for some reason.
> But if we could have *some* kind of explainable basis for
> assigning DEBUGn levels, I think our lives would be better.

Agreed. I'll start with a concrete proposal then:

DEBUG1 is reserved for usage by extensions and for manually testing
patches. DEBUG1 should never be used in permanent code in core
Postgres.

DEBUG2 logs that can be triggered by queries should have content
that's fully dependent on these queries (and GUC configurations). So
no logs related to caches, that might or might not be instantiated
before already, nor logs that might fire based on a concurrent other
backend doing queries or autovacuum having run or not having run. For
background workers these requirements don't apply, there they can be
used as long as the message is deemed important enough to be shown
when a user configures log_min_messages=debug.

DEBUG3-5 logs are for any other debug logs that might be useful, at
varying levels of noise. DEBUG3 should fire at most once per query,
DEBUG4 usually less than 10, and DEBUG5 anything above.

Re: Reduce DEBUG level of catcache refreshing messages

Tom Lane <tgl@sss.pgh.pa.us> — 2025-05-30T22:58:09Z

Jelte Fennema-Nio <postgres@jeltef.nl> writes:
> On Fri, 30 May 2025 at 16:38, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> But if we could have *some* kind of explainable basis for
>> assigning DEBUGn levels, I think our lives would be better.

> Agreed. I'll start with a concrete proposal then:

> DEBUG1 is reserved for usage by extensions and for manually testing
> patches. DEBUG1 should never be used in permanent code in core
> Postgres.

+1

> DEBUG2 logs that can be triggered by queries should have content
> that's fully dependent on these queries (and GUC configurations). So
> no logs related to caches, that might or might not be instantiated
> before already, nor logs that might fire based on a concurrent other
> backend doing queries or autovacuum having run or not having run.

Yeah, I think stability is a useful expectation for DEBUG2, but we
still need some definition of the level's content.  I was thinking
perhaps that it should be used for high-level tracing of subsystem
actions; transaction start and stop being perhaps the most obvious
cases.  And we don't want it to be too verbose, either.

> DEBUG3-5 logs are for any other debug logs that might be useful, at
> varying levels of noise. DEBUG3 should fire at most once per query,
> DEBUG4 usually less than 10, and DEBUG5 anything above.

In a lot of cases it's going to be hard to be sure how chatty a given
log message will be in practice.  So while I'm on board with "more and
more noisy", I doubt how helpful the above guidelines will be.

One thing I was noticing while perusing some of the existing usages
is that some places use DEBUG5 for totally-expected-and-uninteresting
cases, for instance this example in guc.c:

void
check_GUC_name_for_parameter_acl(const char *name)
{
	/* OK if the GUC exists. */
	if (find_option(name, false, true, DEBUG5) != NULL)
		return;
	/* Otherwise, it'd better be a valid custom GUC name. */
	(void) assignable_custom_variable_name(name, false, ERROR);
}

We'd really prefer a NEVER log level there, I think, but we
don't have one.  Perhaps there's an argument for inventing one,
but the path of least resistance would be to define DEBUG5 as
being meant for cases that basically nobody wants to see ever.

That would leave us with only needing to define the contents
of levels 2-4, which is a small enough set that people might
be able to generally agree on which messages go where.
As a straw man:

DEBUG2: high-level tracing of actions.  Stability desired.

DEBUG3: "run of the mill" debug messages; this would be more
or less the default level.  Stability still a useful property.

DEBUG4: tracing of cache-flush-sensitive behavior and other
very noisy cases.

I'm not sure if this line of thought leads to wanting more
message levels than we have, but I don't think it'd be hard
to add more if that's the conclusion.

Other thoughts?  Are there constraints or use cases we've
not accounted for yet?

			regards, tom lane