Skip vacuum log report code in lazy_scan_heap() if possible
Hi,
When recently debugging a vacuum-related issue, I noticed that there
is some log-report processing/formatting code at the end of
lazy_scan_heap() that, unless the vacuum VERBOSE option is specified,
typically results in no log output (as the log-level is then DEBUG2).
I think it is worth skipping this code if ultimately nothing is going
to be logged (and I found that even for a tiny database, a VACUUM may
execute this code hundreds of times).
I have attached a simple patch for this.
Regards,
Greg Nancarrow
Fujitsu Australia
Attachments:
v1-0001-Skip-vacuum-log-report-processing-in-lazy_scan_heap-if-possible.patchapplication/octet-stream; name=v1-0001-Skip-vacuum-log-report-processing-in-lazy_scan_heap-if-possible.patchDownload
From c434b4d6235cffdee8b913c431d6ea6622ea2964 Mon Sep 17 00:00:00 2001
From: Greg Nancarrow <gregn4422@gmail.com>
Date: Fri, 29 Oct 2021 19:46:25 +1100
Subject: [PATCH] Skip vacuum log report processing in lazy_scan_heap() if the
log output is suppressed anyway due to the vacuum log-level.
---
src/backend/access/heap/vacuumlazy.c | 7 +++++++
1 file changed, 7 insertions(+)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 05221cc1d6..f7fe3ed436 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1626,6 +1626,13 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive)
if (vacrel->nindexes > 0 && vacrel->do_index_cleanup)
update_index_statistics(vacrel);
+ /*
+ * Skip log report processing if the log output is going to be
+ * suppressed anyway due to the log level.
+ */
+ if (!message_level_is_interesting(elevel))
+ return;
+
/*
* When the table has no indexes (i.e. in the one-pass strategy case),
* make log report that lazy_vacuum_heap_rel would've made had there been
--
2.27.0
On 10/29/21, 3:54 AM, "Greg Nancarrow" <gregn4422@gmail.com> wrote:
When recently debugging a vacuum-related issue, I noticed that there
is some log-report processing/formatting code at the end of
lazy_scan_heap() that, unless the vacuum VERBOSE option is specified,
typically results in no log output (as the log-level is then DEBUG2).
I think it is worth skipping this code if ultimately nothing is going
to be logged (and I found that even for a tiny database, a VACUUM may
execute this code hundreds of times).
I have attached a simple patch for this.
I think this logging only happens once per table, so I'm not sure it's
really worth it to short-circuit here. If it was per-page, IMO there
would be a much stronger case for it. That being said, I don't think
the proposed patch would hurt anything.
Nathan
On 10/29/21, 10:49 AM, "Bossart, Nathan" <bossartn@amazon.com> wrote:
On 10/29/21, 3:54 AM, "Greg Nancarrow" <gregn4422@gmail.com> wrote:
When recently debugging a vacuum-related issue, I noticed that there
is some log-report processing/formatting code at the end of
lazy_scan_heap() that, unless the vacuum VERBOSE option is specified,
typically results in no log output (as the log-level is then DEBUG2).
I think it is worth skipping this code if ultimately nothing is going
to be logged (and I found that even for a tiny database, a VACUUM may
execute this code hundreds of times).
I have attached a simple patch for this.I think this logging only happens once per table, so I'm not sure it's
really worth it to short-circuit here. If it was per-page, IMO there
would be a much stronger case for it. That being said, I don't think
the proposed patch would hurt anything.
Since I have no further comments, I went ahead and marked this once as
ready-for-committer.
Nathan
On Thu, Dec 02, 2021 at 10:22:25PM +0000, Bossart, Nathan wrote:
Since I have no further comments, I went ahead and marked this once as
ready-for-committer.
Well, as you say, lazy_scan_heap() is only run once per relation, so
that's not a hot code path. Looking at the callers of
message_level_is_interesting(), we apply that also in areas where a
lot of unnecessary work would be involved, like the drop of object
dependencies or ProcSleep() (I recall that there were profiles where
standby replies in walsender.c could show up). And based on the
amount of unnecessary work done at the end of lazy_scan_heap(), I'd
say that this is worth skipping, so let's do it.
There is always the argument that one may blindly add some logic at
the end of lazy_scan_heap(), causing it to be skipped depending on the
configuration, but that's unlikely going to happen after the activity
is logged, so I am fine to apply what you have here. Let's wait a bit
to see if others have any objections, first.
--
Michael
Hi,
On 2021-12-03 09:53:22 +0900, Michael Paquier wrote:
On Thu, Dec 02, 2021 at 10:22:25PM +0000, Bossart, Nathan wrote:
Since I have no further comments, I went ahead and marked this once as
ready-for-committer.Well, as you say, lazy_scan_heap() is only run once per relation, so
that's not a hot code path.
Yea, it seems like a premature optimization.
Looking at the callers of
message_level_is_interesting(), we apply that also in areas where a
lot of unnecessary work would be involved, like the drop of object
dependencies or ProcSleep() (I recall that there were profiles where
standby replies in walsender.c could show up). And based on the
amount of unnecessary work done at the end of lazy_scan_heap(), I'd
say that this is worth skipping, so let's do it.
I think this mostly reduces the coverage of the relevant code without any
measurable speed gain. -0.5 from here.
Greetings,
Andres Freund
If my patch to unite vacuum verbose and the autovacuum logging gets in,
then this issue also goes away.
Peter Geoghegan
(Sent from my phone)
On 12/3/21, 7:40 AM, "Peter Geoghegan" <pg@bowt.ie> wrote:
If my patch to unite vacuum verbose and the autovacuum logging gets
in, then this issue also goes away.
Perhaps this patch should be marked Rejected in favor of that one,
then.
Nathan