pg.ddx.io pgsql-hackers@postgresql.org mailing list archive
help / color / mirror / Atom feedRe: vacuum verbose detail logs are unclear; log at *start* of each stage; show allvisible/frozen/hintbits
9+ messages / 5 participants
[nested] [flat]
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage; show allvisible/frozen/hintbits
@ 2020-01-13 00:45 Justin Pryzby <pryzby@telsasoft.com>
0 siblings, 1 reply; 9+ messages in thread
From: Justin Pryzby @ 2020-01-13 00:45 UTC (permalink / raw)
To: Jeff Janes <jeff.janes@gmail.com>; +Cc: pgsql-hackers
On Sun, Dec 29, 2019 at 01:15:24PM -0500, Jeff Janes wrote:
> On Fri, Dec 20, 2019 at 12:11 PM Justin Pryzby <pryzby@telsasoft.com> wrote:
>
> > This is a usability complaint. If one knows enough about vacuum and/or
> > logging, I'm sure there's no issue.
>
> > | 11 DEBUG: "t": found 999 removable, 999 nonremovable row versions in 9 out of 9 pages
>
> I agree the mixture of pre-action and after-action reporting is rather
> confusing sometimes. I'm more concerned about what the user sees in their
> terminal, though, rather than the server's log file.
Sorry, I ran vacuum (not verbose) with client_min_messages=debug, which was confusing.
> Also, the above quoted line is confusing. It makes it sound like it found
> removable items, but didn't actually remove them. I think that that is
> taking grammatical parallelism too far. How about something like:
>
> DEBUG: "t": removed 999 row versions, found 999 nonremovable row versions in 9 out of 9 pages
Since da4ed8bf, lazy_vacuum_heap() actually says: "removed %d [row versions] in
%d pages". Strangely, the "found .. removable, .. nonremovable" in
lazy_scan_heap() is also from da4ed8bf. Should we change them to match ?
> Also, I'd appreciate a report on how many hint-bits were set
> and how many pages were marked all-visible and/or frozen.
Possibly should fork this part to a different thread, but..
hint bits are being set by heap_prune_chain():
|#0 HeapTupleSatisfiesVacuum (htup=htup@entry=0x7fffabfcccc0, OldestXmin=OldestXmin@entry=536, buffer=buffer@entry=167) at heapam_visibility.c:1245
|#1 0x00007fb6eb3eb848 in heap_prune_chain (prstate=0x7fffabfccf30, OldestXmin=536, rootoffnum=1, buffer=167, relation=0x7fb6eb1e6858) at pruneheap.c:488
|#2 heap_page_prune (relation=relation@entry=0x7fb6eb1e6858, buffer=buffer@entry=167, OldestXmin=536, report_stats=report_stats@entry=false, latestRemovedXid=latestRemovedXid@entry=0x7fb6ed84a13c) at pruneheap.c:223
|#3 0x00007fb6eb3f02a2 in lazy_scan_heap (aggressive=false, nindexes=0, Irel=0x0, vacrelstats=0x7fb6ed84a0c0, params=0x7fffabfcdfd0, onerel=0x7fb6eb1e6858) at vacuumlazy.c:970
|#4 heap_vacuum_rel (onerel=0x7fb6eb1e6858, params=0x7fffabfcdfd0, bstrategy=<optimized out>) at vacuumlazy.c:302
In the attached, I moved heap_page_prune to avoid a second loop over items.
Then, initdb crashed until I avoided calling heap_prepare_freeze_tuple() for
HEAPTUPLE_DEAD. I'm not sure that's ok or maybe if it's exposing an issue.
I'm also not sure if t_infomask!=oldt_infomask is the right test.
One of my usability complaints was that the DETAIL includes newlines, which
makes it not apparent that it's detail, or that it's associated with the
preceding INFO. Should those all be separate DETAIL messages (currently, only
the first errdetail is used, but maybe they should be catted together
usefully). Should errdetail do something with newlines, like change them to
\n\t for output to the client (but not logfile). Should vacuum itself do
something (but probably no change to logfiles).
I remembered that log_statement_stats looks like this:
2020-01-01 11:28:33.758 CST [3916] LOG: EXECUTOR STATISTICS
2020-01-01 11:28:33.758 CST [3916] DETAIL: ! system usage stats:
! 0.050185 s user, 0.000217 s system, 0.050555 s elapsed
! [2.292346 s user, 0.215656 s system total]
[...]
It calls errdetail_internal("%s", str.data), same as vaccum, but the multi-line
detail messages are written like this:
|appendStringInfo(&str, "!\t...")
|...
|ereport(LOG,
| (errmsg_internal("%s", title),
| errdetail_internal("%s", str.data)));
Since they can run multiple times, including rusage, and there's not currently
any message shown before their action, I propose that lazy_vacuum_index/heap
should write VACUUM VERBOSE logs at DEBUG level. Or otherwise show a log
before starting each action, at least those for which it logs completion.
I'm not sure why this one doesn't use get ngettext() ? Missed at a8d585c0 ?
|appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
Or why this one uses _/gettext() ? (580ddcec suggests that I'm missing
something?).
|appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
Anyway, now it looks like this:
postgres=# VACUUM VERBOSE t;
INFO: vacuuming "pg_temp_3.t"
INFO: "t": removed 1998 row versions in 5 pages
INFO: "t": removed 1998, found 999 nonremovable row versions in 9 out of 9 pages
DETAIL: ! 0 dead row versions cannot be removed yet, oldest xmin: 4505
! There were 0 unused item identifiers.
! Skipped 0 pages due to buffer pins, 0 frozen pages.
! 0 pages are entirely empty.
! Marked 9 pages all visible, 4 pages frozen.
! Wrote 1998 hint bits.
! CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s.
VACUUM
Thanks for your input.
Justin
Attachments:
[text/x-diff] v1-0001-Rename-buf-to-avoid-shadowing-buf-of-another-type.patch (2.7K, ../../20200113004542.GA26045@telsasoft.com/2-v1-0001-Rename-buf-to-avoid-shadowing-buf-of-another-type.patch)
download | inline diff:
From d27f2cb5262ec3d3511de44ec7c15d1b1235e5ee Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 27 Nov 2019 20:07:10 -0600
Subject: [PATCH v1 1/6] Rename buf to avoid shadowing buf of another type
---
src/backend/access/heap/vacuumlazy.c | 20 ++++++++++----------
1 file changed, 10 insertions(+), 10 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 5a48b66..1338963 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -609,7 +609,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
BlockNumber next_unskippable_block;
bool skipping_blocks;
xl_heap_freeze_tuple *frozen;
- StringInfoData buf;
+ StringInfoData sbuf;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1443,33 +1443,33 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* This is pretty messy, but we split it up so that we can skip emitting
* individual parts of the message when not applicable.
*/
- initStringInfo(&buf);
- appendStringInfo(&buf,
+ initStringInfo(&sbuf);
+ appendStringInfo(&sbuf,
_("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
nkeep, OldestXmin);
- appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+ appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
nunused);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+ appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
"Skipped %u pages due to buffer pins, ",
vacrelstats->pinskipped_pages),
vacrelstats->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
+ appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
"%u frozen pages.\n",
vacrelstats->frozenskipped_pages),
vacrelstats->frozenskipped_pages);
- appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+ appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
"%u pages are entirely empty.\n",
empty_pages),
empty_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+ appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
ereport(elevel,
(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
RelationGetRelationName(onerel),
tups_vacuumed, num_tuples,
vacrelstats->scanned_pages, nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
+ errdetail_internal("%s", sbuf.data)));
+ pfree(sbuf.data);
}
/*
--
2.7.4
[text/x-diff] v1-0002-vacuumlazy-typos-in-comments.patch (1.4K, ../../20200113004542.GA26045@telsasoft.com/3-v1-0002-vacuumlazy-typos-in-comments.patch)
download | inline diff:
From bb92c8a6220000789e2fc9c852172624d5f9f773 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 13:38:49 -0600
Subject: [PATCH v1 2/6] vacuumlazy: typos in comments
---
src/backend/access/heap/vacuumlazy.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 1338963..532698d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1279,7 +1279,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
/*
* It should never be the case that the visibility map page is set
* while the page-level bit is clear, but the reverse is allowed
- * (if checksums are not enabled). Regardless, set the both bits
+ * (if checksums are not enabled). Regardless, set both bits
* so that we get back in sync.
*
* NB: If the heap page is all-visible but the VM bit is not set,
@@ -1335,7 +1335,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
}
/*
- * If the all-visible page is turned out to be all-frozen but not
+ * If the all-visible page turned out to be all-frozen but not
* marked, we should so mark it. Note that all_frozen is only valid
* if all_visible is true, so we must check both.
*/
--
2.7.4
[text/x-diff] v1-0003-Indent-VACUUM-VERBOSE-multi-line-errdetail-messag.patch (3.7K, ../../20200113004542.GA26045@telsasoft.com/4-v1-0003-Indent-VACUUM-VERBOSE-multi-line-errdetail-messag.patch)
download | inline diff:
From 2e11bd7284727fd4ec05cc2a5c57c6b379752e15 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 1 Jan 2020 17:35:35 -0600
Subject: [PATCH v1 3/6] Indent VACUUM VERBOSE multi-line errdetail messages..
I borrowed the format from ShowUsage.
---
src/backend/access/heap/vacuumlazy.c | 38 +++++++++++++++++++++++-------------
1 file changed, 24 insertions(+), 14 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 532698d..c8d5538 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -591,7 +591,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
BlockNumber nblocks,
blkno;
HeapTupleData tuple;
- char *relname;
+ char *relname,
+ *msgprefix;
TransactionId relfrozenxid = onerel->rd_rel->relfrozenxid;
TransactionId relminmxid = onerel->rd_rel->relminmxid;
BlockNumber empty_pages,
@@ -1440,28 +1441,37 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
tups_vacuumed, vacuumed_pages)));
/*
+ * Indent multi-line DETAIL if being sent to client (verbose)
+ * We don't know if it's sent to the client (client_min_messages);
+ * Also, that affects output to the logfile, too; assume that it's more
+ * important to format messages requested by the client than to make
+ * verbose logs pretty when also sent to the logfile.
+ */
+ msgprefix = elevel==INFO ? "!\t" : "";
+
+ /*
* This is pretty messy, but we split it up so that we can skip emitting
* individual parts of the message when not applicable.
*/
initStringInfo(&sbuf);
appendStringInfo(&sbuf,
- _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+ _("! %.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
nkeep, OldestXmin);
- appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
- nunused);
- appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
- "Skipped %u pages due to buffer pins, ",
+ appendStringInfo(&sbuf, _("%sThere were %.0f unused item identifiers.\n"),
+ msgprefix, nunused);
+ appendStringInfo(&sbuf, ngettext("%sSkipped %u page due to buffer pins, ",
+ "%sSkipped %u pages due to buffer pins, ",
vacrelstats->pinskipped_pages),
- vacrelstats->pinskipped_pages);
+ msgprefix, vacrelstats->pinskipped_pages);
appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
"%u frozen pages.\n",
vacrelstats->frozenskipped_pages),
vacrelstats->frozenskipped_pages);
- appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
- "%u pages are entirely empty.\n",
+ appendStringInfo(&sbuf, ngettext("%s%u page is entirely empty.\n",
+ "%s%u pages are entirely empty.\n",
empty_pages),
- empty_pages);
- appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
+ msgprefix, empty_pages);
+ appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
ereport(elevel,
(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
@@ -1828,9 +1838,9 @@ lazy_cleanup_index(Relation indrel,
RelationGetRelationName(indrel),
stats->num_index_tuples,
stats->num_pages),
- errdetail("%.0f index row versions were removed.\n"
- "%u index pages have been deleted, %u are currently reusable.\n"
- "%s.",
+ errdetail("! %.0f index row versions were removed.\n"
+ "!\t%u index pages have been deleted, %u are currently reusable.\n"
+ "!\t%s.",
stats->tuples_removed,
stats->pages_deleted, stats->pages_free,
pg_rusage_show(&ru0))));
--
2.7.4
[text/x-diff] v1-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch (3.9K, ../../20200113004542.GA26045@telsasoft.com/5-v1-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch)
download | inline diff:
From 10d3c94e9e38c29086627631564c9e6d4d620ca2 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v1 4/6] reduce to DEBUG status logged from vacuum_heap/index..
..since they can run multiple times, which is both excessively noisy, and
confusing, due to showing multiple, multi-line messages with rusage.
Also output (at DEBUG) a message indicating the action to be taken, before
starting it. To avoid outputting a message about completion of one step, and
taking a long time before outputting anything about the next/current step.
I'm taking as a guiding principle to elog whenever calling
pgstat_progress_update_param.
---
src/backend/access/heap/vacuumlazy.c | 20 +++++++++++++++-----
1 file changed, 15 insertions(+), 5 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index c8d5538..08ad6b5 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -326,6 +326,7 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
/* Report that we are now doing final cleanup */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_FINAL_CLEANUP);
+ elog(DEBUG1, "cleaning up");
/*
* Update statistics in pg_class.
@@ -1429,8 +1430,11 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
/* Do post-vacuum cleanup and statistics update for each index */
if (vacrelstats->useindex)
{
- for (i = 0; i < nindexes; i++)
+ for (i = 0; i < nindexes; i++) {
+ ereport(DEBUG1, (errmsg("cleaning up index \"%s\"",
+ RelationGetRelationName(Irel[i]))));
lazy_cleanup_index(Irel[i], indstats[i], vacrelstats);
+ }
}
/* If no indexes, make log report that lazy_vacuum_heap would've made */
@@ -1503,8 +1507,11 @@ lazy_vacuum_all_indexes(Relation onerel, LVRelStats *vacrelstats,
PROGRESS_VACUUM_PHASE_VACUUM_INDEX);
/* Remove index entries */
- for (i = 0; i < nindexes; i++)
+ for (i = 0; i < nindexes; i++) {
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming index",
+ RelationGetRelationName(Irel[i]))));
lazy_vacuum_index(Irel[i], &indstats[i], vacrelstats);
+ }
/* Increase and report the number of index scans */
vacrelstats->num_index_scans++;
@@ -1538,6 +1545,8 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
/* Report that we are now vacuuming the heap */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming heap",
+ RelationGetRelationName(onerel))));
/* Setup error traceback support for ereport() */
errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
@@ -1589,7 +1598,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
vmbuffer = InvalidBuffer;
}
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg("\"%s\": removed %d row versions in %d pages",
RelationGetRelationName(onerel),
tupindex, npages),
@@ -1780,7 +1789,7 @@ lazy_vacuum_index(Relation indrel,
*stats = index_bulk_delete(&ivinfo, *stats,
lazy_tid_reaped, (void *) vacrelstats);
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg("scanned index \"%s\" to remove %d row versions",
RelationGetRelationName(indrel),
vacrelstats->num_dead_tuples),
@@ -1833,7 +1842,7 @@ lazy_cleanup_index(Relation indrel,
InvalidMultiXactId,
false);
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg("index \"%s\" now contains %.0f row versions in %u pages",
RelationGetRelationName(indrel),
stats->num_index_tuples,
@@ -1901,6 +1910,7 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
/* Report that we are now truncating */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_TRUNCATE);
+ elog(DEBUG1, "truncating heap");
/*
* Loop until no more truncating can be done.
--
2.7.4
[text/x-diff] v1-0005-Report-number-of-pages_allvisible-frozen.patch (4.4K, ../../20200113004542.GA26045@telsasoft.com/6-v1-0005-Report-number-of-pages_allvisible-frozen.patch)
download | inline diff:
From aec813b2fe066093ce7355f22b7396dd13b8e11b Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 14:56:02 -0600
Subject: [PATCH v1 5/6] Report number of pages_allvisible/frozen..
..as requested by Jeff Janes
---
src/backend/access/heap/vacuumlazy.c | 37 ++++++++++++++++++++++++++++++------
1 file changed, 31 insertions(+), 6 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 08ad6b5..b739d49 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -125,7 +125,9 @@ typedef struct LVRelStats
double new_rel_tuples; /* new estimated total # of tuples */
double new_live_tuples; /* new estimated total # of live tuples */
double new_dead_tuples; /* new estimated total # of dead tuples */
- BlockNumber pages_removed;
+ BlockNumber pages_removed; /* Due to truncation */
+ BlockNumber pages_frozen;
+ BlockNumber pages_allvisible;
double tuples_deleted;
BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
/* List of TIDs of tuples we intend to delete */
@@ -427,11 +429,13 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
get_namespace_name(RelationGetNamespace(onerel)),
RelationGetRelationName(onerel),
vacrelstats->num_index_scans);
- appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen\n"),
+ appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen, %u marked all visible, %u marked frozen\n"),
vacrelstats->pages_removed,
vacrelstats->rel_pages,
vacrelstats->pinskipped_pages,
- vacrelstats->frozenskipped_pages);
+ vacrelstats->frozenskipped_pages,
+ vacrelstats->pages_allvisible,
+ vacrelstats->pages_frozen);
appendStringInfo(&buf,
_("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
vacrelstats->tuples_deleted,
@@ -647,6 +651,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
vacrelstats->scanned_pages = 0;
vacrelstats->tupcount_pages = 0;
vacrelstats->nonempty_pages = 0;
+ vacrelstats->pages_frozen = 0;
+ vacrelstats->pages_allvisible = 0;
+
vacrelstats->latestRemovedXid = InvalidTransactionId;
lazy_space_alloc(vacrelstats, nblocks);
@@ -944,6 +951,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
visibilitymap_set(onerel, blkno, buf, InvalidXLogRecPtr,
vmbuffer, InvalidTransactionId,
VISIBILITYMAP_ALL_VISIBLE | VISIBILITYMAP_ALL_FROZEN);
+ vacrelstats->pages_allvisible++;
+ vacrelstats->pages_frozen++;
END_CRIT_SECTION();
}
@@ -1275,8 +1284,12 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
{
uint8 flags = VISIBILITYMAP_ALL_VISIBLE;
- if (all_frozen)
+ if (all_frozen) {
flags |= VISIBILITYMAP_ALL_FROZEN;
+ vacrelstats->pages_frozen++;
+ }
+
+ vacrelstats->pages_allvisible++;
/*
* It should never be the case that the visibility map page is set
@@ -1475,6 +1488,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
"%s%u pages are entirely empty.\n",
empty_pages),
msgprefix, empty_pages);
+ appendStringInfo(&sbuf, ngettext("%sMarked %u page all visible, ",
+ "%sMarked %u pages all visible, ",
+ vacrelstats->pages_allvisible),
+ msgprefix, vacrelstats->pages_allvisible);
+ appendStringInfo(&sbuf, ngettext("%u page frozen.\n",
+ "%u pages frozen.\n",
+ vacrelstats->pages_frozen),
+ vacrelstats->pages_frozen);
appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
ereport(elevel,
@@ -1692,10 +1713,14 @@ lazy_vacuum_page(Relation onerel, BlockNumber blkno, Buffer buffer,
uint8 flags = 0;
/* Set the VM all-frozen bit to flag, if needed */
- if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0)
+ if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0) {
flags |= VISIBILITYMAP_ALL_VISIBLE;
- if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen)
+ vacrelstats->pages_allvisible++;
+ }
+ if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen) {
flags |= VISIBILITYMAP_ALL_FROZEN;
+ vacrelstats->pages_frozen++;
+ }
Assert(BufferIsValid(*vmbuffer));
if (flags != 0)
--
2.7.4
[text/x-diff] v1-0006-Report-number-of-hint-bits-written.patch (4.4K, ../../20200113004542.GA26045@telsasoft.com/7-v1-0006-Report-number-of-hint-bits-written.patch)
download | inline diff:
From 9902620947ae0ce100f58329929518b7e9ec9143 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 16:02:50 -0600
Subject: [PATCH v1 6/6] Report number of hint bits written..
..as requested by Jeff Janes
---
src/backend/access/heap/vacuumlazy.c | 38 ++++++++++++++++++++++++------------
1 file changed, 26 insertions(+), 12 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index b739d49..d08cac3 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -128,6 +128,7 @@ typedef struct LVRelStats
BlockNumber pages_removed; /* Due to truncation */
BlockNumber pages_frozen;
BlockNumber pages_allvisible;
+ double hintbit_tuples;
double tuples_deleted;
BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
/* List of TIDs of tuples we intend to delete */
@@ -437,11 +438,12 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
vacrelstats->pages_allvisible,
vacrelstats->pages_frozen);
appendStringInfo(&buf,
- _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
+ _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u, wrote %.0f hint bits\n"),
vacrelstats->tuples_deleted,
vacrelstats->new_rel_tuples,
vacrelstats->new_dead_tuples,
- OldestXmin);
+ OldestXmin,
+ vacrelstats->hintbit_tuples);
appendStringInfo(&buf,
_("buffer usage: %d hits, %d misses, %d dirtied\n"),
VacuumPageHit,
@@ -962,14 +964,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
}
/*
- * Prune all HOT-update chains in this page.
- *
- * We count tuples removed by the pruning step as removed by VACUUM.
- */
- tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
- &vacrelstats->latestRemovedXid);
-
- /*
* Now scan the page to collect vacuumable items and check for tuples
* requiring freezing.
*/
@@ -989,6 +983,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
offnum = OffsetNumberNext(offnum))
{
ItemId itemid;
+ HTSV_Result satisfies;
+ int oldmask;
itemid = PageGetItemId(page, offnum);
@@ -1040,7 +1036,11 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* cases impossible (e.g. in-progress insert from the same
* transaction).
*/
- switch (HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf))
+ oldmask = tuple.t_data->t_infomask;
+ satisfies = HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf);
+ if (oldmask != tuple.t_data->t_infomask)
+ vacrelstats->hintbit_tuples++;
+ switch (satisfies)
{
case HEAPTUPLE_DEAD:
@@ -1179,7 +1179,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* Each non-removable tuple must be checked to see if it needs
* freezing. Note we already have exclusive buffer lock.
*/
- if (heap_prepare_freeze_tuple(tuple.t_data,
+ // Avoid freezing HEAPTUPLE_DEAD, as required
+ if (satisfies!=HEAPTUPLE_DEAD &&
+ heap_prepare_freeze_tuple(tuple.t_data,
relfrozenxid, relminmxid,
FreezeLimit, MultiXactCutoff,
&frozen[nfrozen],
@@ -1192,6 +1194,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
} /* scan along page */
/*
+ * Prune all HOT-update chains in this page.
+ *
+ * We count tuples removed by the pruning step as removed by VACUUM.
+ */
+ tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
+ &vacrelstats->latestRemovedXid);
+
+ /*
* If we froze any tuples, mark the buffer dirty, and write a WAL
* record recording the changes. We must log the changes to be
* crash-safe against future truncation of CLOG.
@@ -1496,6 +1506,10 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
"%u pages frozen.\n",
vacrelstats->pages_frozen),
vacrelstats->pages_frozen);
+ appendStringInfo(&sbuf, ngettext("%sWrote %.0f hint bit.\n",
+ "%sWrote %.0f hint bits.\n",
+ vacrelstats->hintbit_tuples),
+ msgprefix, vacrelstats->hintbit_tuples);
appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
ereport(elevel,
--
2.7.4
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage; show allvisible/frozen/hintbits
@ 2020-01-21 13:49 Justin Pryzby <pryzby@telsasoft.com>
parent: Justin Pryzby <pryzby@telsasoft.com>
0 siblings, 1 reply; 9+ messages in thread
From: Justin Pryzby @ 2020-01-21 13:49 UTC (permalink / raw)
To: Jeff Janes <jeff.janes@gmail.com>; +Cc: pgsql-hackers
Rebased against 40d964ec997f64227bc0ff5e058dc4a5770a70a9
I added to March CF https://commitfest.postgresql.org/27/2425/
Attachments:
[text/x-diff] v2-0001-Rename-buf-to-avoid-shadowing-buf-of-another-type.patch (2.7K, ../../20200121134934.GY26045@telsasoft.com/2-v2-0001-Rename-buf-to-avoid-shadowing-buf-of-another-type.patch)
download | inline diff:
From 83407b81dfc1ed2dfaa6f115dc6c4a276efb07fc Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 27 Nov 2019 20:07:10 -0600
Subject: [PATCH v2 1/6] Rename buf to avoid shadowing buf of another type
---
src/backend/access/heap/vacuumlazy.c | 20 ++++++++++----------
1 file changed, 10 insertions(+), 10 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index f380437..5a66ba4 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -803,7 +803,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
BlockNumber next_unskippable_block;
bool skipping_blocks;
xl_heap_freeze_tuple *frozen;
- StringInfoData buf;
+ StringInfoData sbuf;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1677,33 +1677,33 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* This is pretty messy, but we split it up so that we can skip emitting
* individual parts of the message when not applicable.
*/
- initStringInfo(&buf);
- appendStringInfo(&buf,
+ initStringInfo(&sbuf);
+ appendStringInfo(&sbuf,
_("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
nkeep, OldestXmin);
- appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+ appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
nunused);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+ appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
"Skipped %u pages due to buffer pins, ",
vacrelstats->pinskipped_pages),
vacrelstats->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
+ appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
"%u frozen pages.\n",
vacrelstats->frozenskipped_pages),
vacrelstats->frozenskipped_pages);
- appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+ appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
"%u pages are entirely empty.\n",
empty_pages),
empty_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+ appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
ereport(elevel,
(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
RelationGetRelationName(onerel),
tups_vacuumed, num_tuples,
vacrelstats->scanned_pages, nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
+ errdetail_internal("%s", sbuf.data)));
+ pfree(sbuf.data);
}
/*
--
2.7.4
[text/x-diff] v2-0002-vacuumlazy-typos-in-comments.patch (1.4K, ../../20200121134934.GY26045@telsasoft.com/3-v2-0002-vacuumlazy-typos-in-comments.patch)
download | inline diff:
From ddfff05abecacf810612576f4d73d86e449d74fe Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 13:38:49 -0600
Subject: [PATCH v2 2/6] vacuumlazy: typos in comments
---
src/backend/access/heap/vacuumlazy.c | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 5a66ba4..cb83056 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1508,7 +1508,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
/*
* It should never be the case that the visibility map page is set
* while the page-level bit is clear, but the reverse is allowed
- * (if checksums are not enabled). Regardless, set the both bits
+ * (if checksums are not enabled). Regardless, set both bits
* so that we get back in sync.
*
* NB: If the heap page is all-visible but the VM bit is not set,
@@ -1564,7 +1564,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
}
/*
- * If the all-visible page is turned out to be all-frozen but not
+ * If the all-visible page turned out to be all-frozen but not
* marked, we should so mark it. Note that all_frozen is only valid
* if all_visible is true, so we must check both.
*/
--
2.7.4
[text/x-diff] v2-0003-Indent-VACUUM-VERBOSE-multi-line-errdetail-messag.patch (3.7K, ../../20200121134934.GY26045@telsasoft.com/4-v2-0003-Indent-VACUUM-VERBOSE-multi-line-errdetail-messag.patch)
download | inline diff:
From d77fb8fa723afcadcc4edd5ce08f4246556f65e0 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Wed, 1 Jan 2020 17:35:35 -0600
Subject: [PATCH v2 3/6] Indent VACUUM VERBOSE multi-line errdetail messages..
I borrowed the format from ShowUsage.
---
src/backend/access/heap/vacuumlazy.c | 38 +++++++++++++++++++++++-------------
1 file changed, 24 insertions(+), 14 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index cb83056..f45968c 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -785,7 +785,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
BlockNumber nblocks,
blkno;
HeapTupleData tuple;
- char *relname;
+ char *relname,
+ *msgprefix;
TransactionId relfrozenxid = onerel->rd_rel->relfrozenxid;
TransactionId relminmxid = onerel->rd_rel->relminmxid;
BlockNumber empty_pages,
@@ -1674,28 +1675,37 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
tups_vacuumed, vacuumed_pages)));
/*
+ * Indent multi-line DETAIL if being sent to client (verbose)
+ * We don't know if it's sent to the client (client_min_messages);
+ * Also, that affects output to the logfile, too; assume that it's more
+ * important to format messages requested by the client than to make
+ * verbose logs pretty when also sent to the logfile.
+ */
+ msgprefix = elevel==INFO ? "!\t" : "";
+
+ /*
* This is pretty messy, but we split it up so that we can skip emitting
* individual parts of the message when not applicable.
*/
initStringInfo(&sbuf);
appendStringInfo(&sbuf,
- _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+ _("! %.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
nkeep, OldestXmin);
- appendStringInfo(&sbuf, _("There were %.0f unused item identifiers.\n"),
- nunused);
- appendStringInfo(&sbuf, ngettext("Skipped %u page due to buffer pins, ",
- "Skipped %u pages due to buffer pins, ",
+ appendStringInfo(&sbuf, _("%sThere were %.0f unused item identifiers.\n"),
+ msgprefix, nunused);
+ appendStringInfo(&sbuf, ngettext("%sSkipped %u page due to buffer pins, ",
+ "%sSkipped %u pages due to buffer pins, ",
vacrelstats->pinskipped_pages),
- vacrelstats->pinskipped_pages);
+ msgprefix, vacrelstats->pinskipped_pages);
appendStringInfo(&sbuf, ngettext("%u frozen page.\n",
"%u frozen pages.\n",
vacrelstats->frozenskipped_pages),
vacrelstats->frozenskipped_pages);
- appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
- "%u pages are entirely empty.\n",
+ appendStringInfo(&sbuf, ngettext("%s%u page is entirely empty.\n",
+ "%s%u pages are entirely empty.\n",
empty_pages),
- empty_pages);
- appendStringInfo(&sbuf, _("%s."), pg_rusage_show(&ru0));
+ msgprefix, empty_pages);
+ appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
ereport(elevel,
(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
@@ -2404,9 +2414,9 @@ lazy_cleanup_index(Relation indrel,
RelationGetRelationName(indrel),
(*stats)->num_index_tuples,
(*stats)->num_pages),
- errdetail("%.0f index row versions were removed.\n"
- "%u index pages have been deleted, %u are currently reusable.\n"
- "%s.",
+ errdetail("! %.0f index row versions were removed.\n"
+ "!\t%u index pages have been deleted, %u are currently reusable.\n"
+ "!\t%s.",
(*stats)->tuples_removed,
(*stats)->pages_deleted, (*stats)->pages_free,
pg_rusage_show(&ru0))));
--
2.7.4
[text/x-diff] v2-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch (3.8K, ../../20200121134934.GY26045@telsasoft.com/5-v2-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch)
download | inline diff:
From 0a5f3ad741468c1c4bdbffb48b69f6610524e6d7 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v2 4/6] reduce to DEBUG status logged from vacuum_heap/index..
..since they can run multiple times, which is both excessively noisy, and
confusing, due to showing multiple, multi-line messages with rusage.
Also output (at DEBUG) a message indicating the action to be taken, before
starting it. To avoid outputting a message about completion of one step, and
taking a long time before outputting anything about the next/current step.
I'm taking as a guiding principle to elog whenever calling
pgstat_progress_update_param.
---
src/backend/access/heap/vacuumlazy.c | 20 +++++++++++++++-----
1 file changed, 15 insertions(+), 5 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index f45968c..2e1e8cc 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -506,6 +506,7 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
/* Report that we are now doing final cleanup */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_FINAL_CLEANUP);
+ elog(DEBUG1, "cleaning up");
/*
* Update statistics in pg_class.
@@ -1757,9 +1758,12 @@ lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
{
int idx;
- for (idx = 0; idx < nindexes; idx++)
+ for (idx = 0; idx < nindexes; idx++) {
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming index",
+ RelationGetRelationName(Irel[idx]))));
lazy_vacuum_index(Irel[idx], &stats[idx], vacrelstats->dead_tuples,
vacrelstats->old_live_tuples);
+ }
}
/* Increase and report the number of index scans */
@@ -1794,6 +1798,8 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
/* Report that we are now vacuuming the heap */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming heap",
+ RelationGetRelationName(onerel))));
/* Setup error traceback support for ereport() */
errcbarg.relnamespace = get_namespace_name(RelationGetNamespace(onerel));
@@ -1845,7 +1851,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
vmbuffer = InvalidBuffer;
}
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg("\"%s\": removed %d row versions in %d pages",
RelationGetRelationName(onerel),
tupindex, npages),
@@ -2323,10 +2329,13 @@ lazy_cleanup_all_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
}
else
{
- for (idx = 0; idx < nindexes; idx++)
+ for (idx = 0; idx < nindexes; idx++) {
+ ereport(DEBUG1, (errmsg("cleaning up index \"%s\"",
+ RelationGetRelationName(Irel[idx]))));
lazy_cleanup_index(Irel[idx], &stats[idx],
vacrelstats->new_rel_tuples,
vacrelstats->tupcount_pages < vacrelstats->rel_pages);
+ }
}
}
@@ -2366,7 +2375,7 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
else
msg = gettext_noop("scanned index \"%s\" to remove %d row versions");
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(msg,
RelationGetRelationName(indrel),
dead_tuples->num_tuples),
@@ -2409,7 +2418,7 @@ lazy_cleanup_index(Relation indrel,
else
msg = gettext_noop("index \"%s\" now contains %.0f row versions in %u pages");
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(msg,
RelationGetRelationName(indrel),
(*stats)->num_index_tuples,
@@ -2475,6 +2484,7 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
/* Report that we are now truncating */
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_TRUNCATE);
+ elog(DEBUG1, "truncating heap");
/*
* Loop until no more truncating can be done.
--
2.7.4
[text/x-diff] v2-0005-Report-number-of-pages_allvisible-frozen.patch (4.4K, ../../20200121134934.GY26045@telsasoft.com/6-v2-0005-Report-number-of-pages_allvisible-frozen.patch)
download | inline diff:
From 49a2dc5a4a95cb7ccce42326cdbf32a1feadc7dc Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 14:56:02 -0600
Subject: [PATCH v2 5/6] Report number of pages_allvisible/frozen..
..as requested by Jeff Janes
---
src/backend/access/heap/vacuumlazy.c | 37 ++++++++++++++++++++++++++++++------
1 file changed, 31 insertions(+), 6 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 2e1e8cc..49e214e 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -280,7 +280,9 @@ typedef struct LVRelStats
double new_rel_tuples; /* new estimated total # of tuples */
double new_live_tuples; /* new estimated total # of live tuples */
double new_dead_tuples; /* new estimated total # of dead tuples */
- BlockNumber pages_removed;
+ BlockNumber pages_removed; /* Due to truncation */
+ BlockNumber pages_frozen;
+ BlockNumber pages_allvisible;
double tuples_deleted;
BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
LVDeadTuples *dead_tuples;
@@ -607,11 +609,13 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
get_namespace_name(RelationGetNamespace(onerel)),
RelationGetRelationName(onerel),
vacrelstats->num_index_scans);
- appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen\n"),
+ appendStringInfo(&buf, _("pages: %u removed, %u remain, %u skipped due to pins, %u skipped frozen, %u marked all visible, %u marked frozen\n"),
vacrelstats->pages_removed,
vacrelstats->rel_pages,
vacrelstats->pinskipped_pages,
- vacrelstats->frozenskipped_pages);
+ vacrelstats->frozenskipped_pages,
+ vacrelstats->pages_allvisible,
+ vacrelstats->pages_frozen);
appendStringInfo(&buf,
_("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
vacrelstats->tuples_deleted,
@@ -841,6 +845,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
vacrelstats->scanned_pages = 0;
vacrelstats->tupcount_pages = 0;
vacrelstats->nonempty_pages = 0;
+ vacrelstats->pages_frozen = 0;
+ vacrelstats->pages_allvisible = 0;
+
vacrelstats->latestRemovedXid = InvalidTransactionId;
/*
@@ -1173,6 +1180,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
visibilitymap_set(onerel, blkno, buf, InvalidXLogRecPtr,
vmbuffer, InvalidTransactionId,
VISIBILITYMAP_ALL_VISIBLE | VISIBILITYMAP_ALL_FROZEN);
+ vacrelstats->pages_allvisible++;
+ vacrelstats->pages_frozen++;
END_CRIT_SECTION();
}
@@ -1504,8 +1513,12 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
{
uint8 flags = VISIBILITYMAP_ALL_VISIBLE;
- if (all_frozen)
+ if (all_frozen) {
flags |= VISIBILITYMAP_ALL_FROZEN;
+ vacrelstats->pages_frozen++;
+ }
+
+ vacrelstats->pages_allvisible++;
/*
* It should never be the case that the visibility map page is set
@@ -1706,6 +1719,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
"%s%u pages are entirely empty.\n",
empty_pages),
msgprefix, empty_pages);
+ appendStringInfo(&sbuf, ngettext("%sMarked %u page all visible, ",
+ "%sMarked %u pages all visible, ",
+ vacrelstats->pages_allvisible),
+ msgprefix, vacrelstats->pages_allvisible);
+ appendStringInfo(&sbuf, ngettext("%u page frozen.\n",
+ "%u pages frozen.\n",
+ vacrelstats->pages_frozen),
+ vacrelstats->pages_frozen);
appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
ereport(elevel,
@@ -1946,10 +1967,14 @@ lazy_vacuum_page(Relation onerel, BlockNumber blkno, Buffer buffer,
uint8 flags = 0;
/* Set the VM all-frozen bit to flag, if needed */
- if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0)
+ if ((vm_status & VISIBILITYMAP_ALL_VISIBLE) == 0) {
flags |= VISIBILITYMAP_ALL_VISIBLE;
- if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen)
+ vacrelstats->pages_allvisible++;
+ }
+ if ((vm_status & VISIBILITYMAP_ALL_FROZEN) == 0 && all_frozen) {
flags |= VISIBILITYMAP_ALL_FROZEN;
+ vacrelstats->pages_frozen++;
+ }
Assert(BufferIsValid(*vmbuffer));
if (flags != 0)
--
2.7.4
[text/x-diff] v2-0006-Report-number-of-hint-bits-written.patch (4.4K, ../../20200121134934.GY26045@telsasoft.com/7-v2-0006-Report-number-of-hint-bits-written.patch)
download | inline diff:
From 17b5f411873efa08ef31352d0e78379b4f7aaaa2 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 29 Dec 2019 16:02:50 -0600
Subject: [PATCH v2 6/6] Report number of hint bits written..
..as requested by Jeff Janes
---
src/backend/access/heap/vacuumlazy.c | 38 ++++++++++++++++++++++++------------
1 file changed, 26 insertions(+), 12 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 49e214e..3383807 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -283,6 +283,7 @@ typedef struct LVRelStats
BlockNumber pages_removed; /* Due to truncation */
BlockNumber pages_frozen;
BlockNumber pages_allvisible;
+ double hintbit_tuples;
double tuples_deleted;
BlockNumber nonempty_pages; /* actually, last nonempty page + 1 */
LVDeadTuples *dead_tuples;
@@ -617,11 +618,12 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
vacrelstats->pages_allvisible,
vacrelstats->pages_frozen);
appendStringInfo(&buf,
- _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u\n"),
+ _("tuples: %.0f removed, %.0f remain, %.0f are dead but not yet removable, oldest xmin: %u, wrote %.0f hint bits\n"),
vacrelstats->tuples_deleted,
vacrelstats->new_rel_tuples,
vacrelstats->new_dead_tuples,
- OldestXmin);
+ OldestXmin,
+ vacrelstats->hintbit_tuples);
appendStringInfo(&buf,
_("buffer usage: %d hits, %d misses, %d dirtied\n"),
VacuumPageHit,
@@ -1191,14 +1193,6 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
}
/*
- * Prune all HOT-update chains in this page.
- *
- * We count tuples removed by the pruning step as removed by VACUUM.
- */
- tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
- &vacrelstats->latestRemovedXid);
-
- /*
* Now scan the page to collect vacuumable items and check for tuples
* requiring freezing.
*/
@@ -1218,6 +1212,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
offnum = OffsetNumberNext(offnum))
{
ItemId itemid;
+ HTSV_Result satisfies;
+ int oldmask;
itemid = PageGetItemId(page, offnum);
@@ -1269,7 +1265,11 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* cases impossible (e.g. in-progress insert from the same
* transaction).
*/
- switch (HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf))
+ oldmask = tuple.t_data->t_infomask;
+ satisfies = HeapTupleSatisfiesVacuum(&tuple, OldestXmin, buf);
+ if (oldmask != tuple.t_data->t_infomask)
+ vacrelstats->hintbit_tuples++;
+ switch (satisfies)
{
case HEAPTUPLE_DEAD:
@@ -1408,7 +1408,9 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* Each non-removable tuple must be checked to see if it needs
* freezing. Note we already have exclusive buffer lock.
*/
- if (heap_prepare_freeze_tuple(tuple.t_data,
+ // Avoid freezing HEAPTUPLE_DEAD, as required
+ if (satisfies!=HEAPTUPLE_DEAD &&
+ heap_prepare_freeze_tuple(tuple.t_data,
relfrozenxid, relminmxid,
FreezeLimit, MultiXactCutoff,
&frozen[nfrozen],
@@ -1421,6 +1423,14 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
} /* scan along page */
/*
+ * Prune all HOT-update chains in this page.
+ *
+ * We count tuples removed by the pruning step as removed by VACUUM.
+ */
+ tups_vacuumed += heap_page_prune(onerel, buf, OldestXmin, false,
+ &vacrelstats->latestRemovedXid);
+
+ /*
* If we froze any tuples, mark the buffer dirty, and write a WAL
* record recording the changes. We must log the changes to be
* crash-safe against future truncation of CLOG.
@@ -1727,6 +1737,10 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
"%u pages frozen.\n",
vacrelstats->pages_frozen),
vacrelstats->pages_frozen);
+ appendStringInfo(&sbuf, ngettext("%sWrote %.0f hint bit.\n",
+ "%sWrote %.0f hint bits.\n",
+ vacrelstats->hintbit_tuples),
+ msgprefix, vacrelstats->hintbit_tuples);
appendStringInfo(&sbuf, _("%s%s."), msgprefix, pg_rusage_show(&ru0)); // why translate this ??
ereport(elevel,
--
2.7.4
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage; show allvisible/frozen/hintbits
@ 2020-01-22 05:34 Michael Paquier <michael@paquier.xyz>
parent: Justin Pryzby <pryzby@telsasoft.com>
0 siblings, 2 replies; 9+ messages in thread
From: Michael Paquier @ 2020-01-22 05:34 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; +Cc: Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers
On Tue, Jan 21, 2020 at 07:49:34AM -0600, Justin Pryzby wrote:
> Rebased against 40d964ec997f64227bc0ff5e058dc4a5770a70a9
> I added to March CF https://commitfest.postgresql.org/27/2425/
Please be careful with the sets of patches sent to a thread, just to
say that what you are sending is organized in a messy way, and that
this is not the only thread (I can see sometimes the same patches sent
to multiple threads for no actual reason). First, patches 0001 and
0002 have nothing to do with this thread. Patches 0003 and 0005 could
just be merged together, visibly with 0004 as well as they treat of
the same concepts, actually related to this thread. My point is that
it is harder to understand what you are trying to do, and that this is
inconsistent with the threads created.
From patch 0002:
- * If the all-visible page is turned out to be all-frozen but not
+ * If the all-visible page turned out to be all-frozen but not
* marked, we should so mark it. Note that all_frozen is only valid
* if all_visible is true, so we must check both.
Shouldn't the last part of the sentence be "we should mark it so"
instead of "we should so mark it"? I would rephrase the whole as
follows:
"If the all-visible page is all-frozen but not marked as such yet,
mark it as all-frozen."
From patch 0003:
/*
+ * Indent multi-line DETAIL if being sent to client (verbose)
+ * We don't know if it's sent to the client (client_min_messages);
+ * Also, that affects output to the logfile, too; assume that it's more
+ * important to format messages requested by the client than to make
+ * verbose logs pretty when also sent to the logfile.
+ */
+ msgprefix = elevel==INFO ? "!\t" : "";
Such stuff gets a -1 from me. This is not project-like, and you make
the translation of those messages much harder than they should be.
--
Michael
Attachments:
[application/pgp-signature] signature.asc (832B, ../../20200122053457.GG174860@paquier.xyz/2-signature.asc)
download
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage; show allvisible/frozen/hintbits
@ 2020-01-23 06:57 Michael Paquier <michael@paquier.xyz>
parent: Michael Paquier <michael@paquier.xyz>
1 sibling, 0 replies; 9+ messages in thread
From: Michael Paquier @ 2020-01-23 06:57 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; +Cc: Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers
On Wed, Jan 22, 2020 at 02:34:57PM +0900, Michael Paquier wrote:
> Shouldn't the last part of the sentence be "we should mark it so"
> instead of "we should so mark it"? I would rephrase the whole as
> follows:
> "If the all-visible page is all-frozen but not marked as such yet,
> mark it as all-frozen."
Applied this one to HEAD after chewing on it a bit.
--
Michael
Attachments:
[application/pgp-signature] signature.asc (832B, ../../20200123065756.GC1895@paquier.xyz/2-signature.asc)
download
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage
@ 2020-01-26 05:36 Justin Pryzby <pryzby@telsasoft.com>
parent: Michael Paquier <michael@paquier.xyz>
1 sibling, 2 replies; 9+ messages in thread
From: Justin Pryzby @ 2020-01-26 05:36 UTC (permalink / raw)
To: Michael Paquier <michael@paquier.xyz>; +Cc: Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers
On Wed, Jan 22, 2020 at 02:34:57PM +0900, Michael Paquier wrote:
> From patch 0003:
> /*
> + * Indent multi-line DETAIL if being sent to client (verbose)
> + * We don't know if it's sent to the client (client_min_messages);
> + * Also, that affects output to the logfile, too; assume that it's more
> + * important to format messages requested by the client than to make
> + * verbose logs pretty when also sent to the logfile.
> + */
> + msgprefix = elevel==INFO ? "!\t" : "";
> Such stuff gets a -1 from me. This is not project-like, and you make
> the translation of those messages much harder than they should be.
I don't see why its harder to translate ? Do you mean because it changes the
strings by adding %s ?
- appendStringInfo(&sbuf, ngettext("%u page is entirely empty.\n",
- "%u pages are entirely empty.\n",
+ appendStringInfo(&sbuf, ngettext("%s%u page is entirely empty.\n",
+ "%s%u pages are entirely empty.\n",
...
I did raise two questions regarding translation:
I'm not sure why this one doesn't use get ngettext() ? Seems to have been
missed at a8d585c0.
|appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
Or why this one does use _/gettext() ? (580ddcec suggests that I'm missing
something, but I just experimented, and it really seems to do nothing, since
"%s" shouldn't be translated).
|appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
Also, I realized it's possible to write different strings to the log vs the
client (with and without a prefix) by calling errdetail_internal() and
errdetail_log().
Here's a version rebased on top of f942dfb9, and making use of errdetail_log.
I'm not sure if it address your concern about translation, but it doesn't
change strings.
I think it's not needed or desirable to change what's written to the logfile,
since CSV logs have a separate "detail" field, and text logs are indented. The
server log is unchanged:
> 2020-01-25 23:08:40.451 CST [13971] INFO: "t": removed 0, found 160 nonremovable row versions in 1 out of 888 pages
> 2020-01-25 23:08:40.451 CST [13971] DETAIL: 0 dead row versions cannot be removed yet, oldest xmin: 781
> There were 0 unused item identifiers.
> Skipped 0 pages due to buffer pins, 444 frozen pages.
> 0 pages are entirely empty.
> CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s.
If VERBOSE, then the client log has ! prefixes, with the style borrowed from
ShowUsage:
> INFO: "t": removed 0, found 160 nonremovable row versions in 1 out of 888 pages
> DETAIL: ! 0 dead row versions cannot be removed yet, oldest xmin: 781
> ! There were 0 unused item identifiers.
> ! Skipped 0 pages due to buffer pins, 444 frozen pages.
> ! 0 pages are entirely empty.
> ! CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.01 s.
I mentioned before that maybe the client's messages with newlines should be
indented similarly to how the they're done in the text logfile. I looked,
that's append_with_tabs() in elog.c. So that's a different possible
implementation, which would apply to any message with newlines (or possibly
just DETAIL).
I'll also fork the allvisible/frozen/hintbits patches to a separate thread.
Thanks,
Justin
Attachments:
[text/x-diff] v3-0001-Remove-gettext-erronously-readded-at-580ddce.patch (955B, ../../20200126053629.GO13621@telsasoft.com/2-v3-0001-Remove-gettext-erronously-readded-at-580ddce.patch)
download | inline diff:
From a3d0b41435655615ab13f808ec7c30e53e596e50 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 25 Jan 2020 21:25:37 -0600
Subject: [PATCH v3 1/4] Remove gettext erronously readded at 580ddce
---
src/backend/access/heap/vacuumlazy.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8ce5011..8e8ea9d 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1690,7 +1690,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
"%u pages are entirely empty.\n",
empty_pages),
empty_pages);
- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
+ appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
ereport(elevel,
(errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
--
2.7.4
[text/x-diff] v3-0002-vacuum-verbose-use-ngettext-everywhere-possible.patch (1.4K, ../../20200126053629.GO13621@telsasoft.com/3-v3-0002-vacuum-verbose-use-ngettext-everywhere-possible.patch)
download | inline diff:
From 2db7c4e3482120b2a83cda74603f2454da7eaa03 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 25 Jan 2020 22:50:46 -0600
Subject: [PATCH v3 2/4] vacuum verbose: use ngettext() everywhere possible
---
src/backend/access/heap/vacuumlazy.c | 9 ++++++---
1 file changed, 6 insertions(+), 3 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 8e8ea9d..eb903d5 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -1673,10 +1673,13 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
* individual parts of the message when not applicable.
*/
initStringInfo(&buf);
- appendStringInfo(&buf,
- _("%.0f dead row versions cannot be removed yet, oldest xmin: %u\n"),
+ appendStringInfo(&buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
+ "%.0f dead row versions cannot be removed yet, oldest xmin: %u\n",
+ nkeep),
nkeep, OldestXmin);
- appendStringInfo(&buf, _("There were %.0f unused item identifiers.\n"),
+ appendStringInfo(&buf, ngettext("There was %.0f unused item identifier.\n",
+ "There were %.0f unused item identifiers.\n",
+ nunused),
nunused);
appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
"Skipped %u pages due to buffer pins, ",
--
2.7.4
[text/x-diff] v3-0003-vacuum-verbose-prefix-write-multi-line-output-to-.patch (4.8K, ../../20200126053629.GO13621@telsasoft.com/4-v3-0003-vacuum-verbose-prefix-write-multi-line-output-to-.patch)
download | inline diff:
From 3467bf485972065f73c25a8f1e66c7c4f0bd5d23 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 25 Jan 2020 21:47:05 -0600
Subject: [PATCH v3 3/4] vacuum verbose: prefix write multi-line output to
client..
..but do not change output to logfile, which isn't unclear.
I borrowed the format from ShowUsage.
TODO: lazy_cleanup_index
---
src/backend/access/heap/vacuumlazy.c | 58 ++++++++++++++++++++++++++----------
1 file changed, 43 insertions(+), 15 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index eb903d5..6f85af7 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -307,6 +307,7 @@ static BufferAccessStrategy vac_strategy;
static void lazy_scan_heap(Relation onerel, VacuumParams *params,
LVRelStats *vacrelstats, Relation *Irel, int nindexes,
bool aggressive);
+static void vacuum_msg(StringInfoData *buf, const char *prefix, LVRelStats *vacrelstats, double nkeep, double nunused, BlockNumber empty_pages, PGRUsage *ru0);
static void lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats);
static bool lazy_check_needs_freeze(Buffer buf, bool *hastup);
static void lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
@@ -717,7 +718,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
BlockNumber next_unskippable_block;
bool skipping_blocks;
xl_heap_freeze_tuple *frozen;
- StringInfoData buf;
+ StringInfoData logdetail,
+ clientdetail;
const int initprog_index[] = {
PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_TOTAL_HEAP_BLKS,
@@ -1668,40 +1670,66 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
RelationGetRelationName(onerel),
tups_vacuumed, vacuumed_pages)));
+ /* Write separate log messages to client (with prefix) and logfile (without prefix) */
+ vacuum_msg(&logdetail, "", vacrelstats, nkeep, nunused, empty_pages, &ru0);
+ vacuum_msg(&clientdetail, "! ", vacrelstats, nkeep, nunused, empty_pages, &ru0);
+
+ ereport(elevel,
+ (errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
+ RelationGetRelationName(onerel),
+ tups_vacuumed, num_tuples,
+ vacrelstats->scanned_pages, nblocks),
+ errdetail_log("%s", logdetail.data),
+ errdetail_internal("%s", clientdetail.data)));
+
+ pfree(logdetail.data);
+ pfree(clientdetail.data);
+}
+
+/* Populate buf with string to be freed by caller */
+static void
+vacuum_msg(StringInfoData *buf, const char *prefix, LVRelStats *vacrelstats, double nkeep, double nunused, BlockNumber empty_pages, PGRUsage *ru0)
+{
/*
* This is pretty messy, but we split it up so that we can skip emitting
* individual parts of the message when not applicable.
*/
- initStringInfo(&buf);
- appendStringInfo(&buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
+ initStringInfo(buf);
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("%.0f dead row version cannot be removed yet, oldest xmin: %u\n",
"%.0f dead row versions cannot be removed yet, oldest xmin: %u\n",
nkeep),
nkeep, OldestXmin);
- appendStringInfo(&buf, ngettext("There was %.0f unused item identifier.\n",
+
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("There was %.0f unused item identifier.\n",
"There were %.0f unused item identifiers.\n",
nunused),
nunused);
- appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ",
+
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("Skipped %u page due to buffer pins, ",
"Skipped %u pages due to buffer pins, ",
vacrelstats->pinskipped_pages),
vacrelstats->pinskipped_pages);
- appendStringInfo(&buf, ngettext("%u frozen page.\n",
+ appendStringInfo(buf, ngettext("%u frozen page.\n",
"%u frozen pages.\n",
vacrelstats->frozenskipped_pages),
vacrelstats->frozenskipped_pages);
- appendStringInfo(&buf, ngettext("%u page is entirely empty.\n",
+
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, ngettext("%u page is entirely empty.\n",
"%u pages are entirely empty.\n",
empty_pages),
empty_pages);
- appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
- ereport(elevel,
- (errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
- RelationGetRelationName(onerel),
- tups_vacuumed, num_tuples,
- vacrelstats->scanned_pages, nblocks),
- errdetail_internal("%s", buf.data)));
- pfree(buf.data);
+ if (prefix)
+ appendStringInfoString(buf, prefix);
+ appendStringInfo(buf, "%s.", pg_rusage_show(ru0));
}
/*
--
2.7.4
[text/x-diff] v3-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch (4.4K, ../../20200126053629.GO13621@telsasoft.com/5-v3-0004-reduce-to-DEBUG-status-logged-from-vacuum_heap-in.patch)
download | inline diff:
From 55fea31f5d3d99a94eba206ec5a75f94e1f43097 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sun, 15 Dec 2019 17:00:29 -0600
Subject: [PATCH v3 4/4] reduce to DEBUG status logged from vacuum_heap/index..
..since they can run multiple times, which is both excessively noisy, and
confusing, due to showing multiple, multi-line messages with rusage.
Also output (at DEBUG) a message indicating the action to be taken, before
starting it. To avoid outputting a message about completion of one step, and
taking a long time before outputting anything about the next/current step.
I'm taking as a guiding principle to elog whenever calling
pgstat_progress_update_param.
---
src/backend/access/heap/vacuumlazy.c | 24 +++++++++++++++++-------
1 file changed, 17 insertions(+), 7 deletions(-)
diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
index 6f85af7..95d999f 100644
--- a/src/backend/access/heap/vacuumlazy.c
+++ b/src/backend/access/heap/vacuumlazy.c
@@ -501,6 +501,7 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
lazy_truncate_heap(onerel, vacrelstats);
/* Report that we are now doing final cleanup */
+ elog(DEBUG1, "cleaning up");
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_FINAL_CLEANUP);
@@ -1773,9 +1774,12 @@ lazy_vacuum_all_indexes(Relation onerel, Relation *Irel,
{
int idx;
- for (idx = 0; idx < nindexes; idx++)
+ for (idx = 0; idx < nindexes; idx++) {
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming index",
+ RelationGetRelationName(Irel[idx]))));
lazy_vacuum_index(Irel[idx], &stats[idx], vacrelstats->dead_tuples,
vacrelstats->old_live_tuples);
+ }
}
/* Increase and report the number of index scans */
@@ -1805,6 +1809,8 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
Buffer vmbuffer = InvalidBuffer;
/* Report that we are now vacuuming the heap */
+ ereport(DEBUG1, (errmsg("\"%s\": vacuuming heap",
+ RelationGetRelationName(onerel))));
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_VACUUM_HEAP);
@@ -1848,7 +1854,7 @@ lazy_vacuum_heap(Relation onerel, LVRelStats *vacrelstats)
vmbuffer = InvalidBuffer;
}
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg("\"%s\": removed %d row versions in %d pages",
RelationGetRelationName(onerel),
tupindex, npages),
@@ -2093,13 +2099,13 @@ lazy_parallel_vacuum_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
}
if (lps->lvshared->for_cleanup)
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(ngettext("launched %d parallel vacuum worker for index cleanup (planned: %d)",
"launched %d parallel vacuum workers for index cleanup (planned: %d)",
lps->pcxt->nworkers_launched),
lps->pcxt->nworkers_launched, nworkers)));
else
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(ngettext("launched %d parallel vacuum worker for index vacuuming (planned: %d)",
"launched %d parallel vacuum workers for index vacuuming (planned: %d)",
lps->pcxt->nworkers_launched),
@@ -2326,10 +2332,13 @@ lazy_cleanup_all_indexes(Relation *Irel, IndexBulkDeleteResult **stats,
}
else
{
- for (idx = 0; idx < nindexes; idx++)
+ for (idx = 0; idx < nindexes; idx++) {
+ ereport(DEBUG1, (errmsg("cleaning up index \"%s\"",
+ RelationGetRelationName(Irel[idx]))));
lazy_cleanup_index(Irel[idx], &stats[idx],
vacrelstats->new_rel_tuples,
vacrelstats->tupcount_pages < vacrelstats->rel_pages);
+ }
}
}
@@ -2369,7 +2378,7 @@ lazy_vacuum_index(Relation indrel, IndexBulkDeleteResult **stats,
else
msg = gettext_noop("scanned index \"%s\" to remove %d row versions");
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(msg,
RelationGetRelationName(indrel),
dead_tuples->num_tuples),
@@ -2412,7 +2421,7 @@ lazy_cleanup_index(Relation indrel,
else
msg = gettext_noop("index \"%s\" now contains %.0f row versions in %u pages");
- ereport(elevel,
+ ereport(DEBUG1,
(errmsg(msg,
RelationGetRelationName(indrel),
(*stats)->num_index_tuples,
@@ -2476,6 +2485,7 @@ lazy_truncate_heap(Relation onerel, LVRelStats *vacrelstats)
pg_rusage_init(&ru0);
/* Report that we are now truncating */
+ elog(DEBUG1, "truncating heap");
pgstat_progress_update_param(PROGRESS_VACUUM_PHASE,
PROGRESS_VACUUM_PHASE_TRUNCATE);
--
2.7.4
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage
@ 2020-02-27 09:10 Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
parent: Justin Pryzby <pryzby@telsasoft.com>
1 sibling, 1 reply; 9+ messages in thread
From: Peter Eisentraut @ 2020-02-27 09:10 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; Michael Paquier <michael@paquier.xyz>; +Cc: Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers
On 2020-01-26 06:36, Justin Pryzby wrote:
> From a3d0b41435655615ab13f808ec7c30e53e596e50 Mon Sep 17 00:00:00 2001
> From: Justin Pryzby<pryzbyj@telsasoft.com>
> Date: Sat, 25 Jan 2020 21:25:37 -0600
> Subject: [PATCH v3 1/4] Remove gettext erronously readded at 580ddce
>
> ---
> src/backend/access/heap/vacuumlazy.c | 2 +-
> 1 file changed, 1 insertion(+), 1 deletion(-)
>
> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c
> index 8ce5011..8e8ea9d 100644
> --- a/src/backend/access/heap/vacuumlazy.c
> +++ b/src/backend/access/heap/vacuumlazy.c
> @@ -1690,7 +1690,7 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats,
> "%u pages are entirely empty.\n",
> empty_pages),
> empty_pages);
> - appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
> + appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
>
> ereport(elevel,
> (errmsg("\"%s\": found %.0f removable, %.0f nonremovable row versions in %u out of %u pages",
> -- 2.7.4
Why do you think it was erroneously added?
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage
@ 2020-02-29 19:59 Justin Pryzby <pryzby@telsasoft.com>
parent: Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
0 siblings, 0 replies; 9+ messages in thread
From: Justin Pryzby @ 2020-02-29 19:59 UTC (permalink / raw)
To: Peter Eisentraut <peter.eisentraut@2ndquadrant.com>; +Cc: Michael Paquier <michael@paquier.xyz>; Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers
On Thu, Feb 27, 2020 at 10:10:57AM +0100, Peter Eisentraut wrote:
> On 2020-01-26 06:36, Justin Pryzby wrote:
> >Subject: [PATCH v3 1/4] Remove gettext erronously readded at 580ddce
> >
> >- appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0));
> >+ appendStringInfo(&buf, "%s.", pg_rusage_show(&ru0));
>
> Why do you think it was erroneously added?
I was wrong.
It seemed useless to me to translate "%s.", but I see now that at least JA.PO
uses a different terminator than ".".
$ git grep -C3 'msgid "%s."$' '*.po' |grep msgstr
src/backend/po/de.po-msgstr "%s."
src/backend/po/es.po-msgstr "%s."
src/backend/po/fr.po-msgstr "%s."
src/backend/po/id.po-msgstr "%s."
src/backend/po/it.po-msgstr "%s."
src/backend/po/ja.po-msgstr "%s。"
BTW I only *happened* to see your message on the www interface. I didn't get
the original message. And the "Resend email" button didn't get it to me,
either..
--
Justin
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage
@ 2020-03-24 21:58 Tom Lane <tgl@sss.pgh.pa.us>
parent: Justin Pryzby <pryzby@telsasoft.com>
1 sibling, 1 reply; 9+ messages in thread
From: Tom Lane @ 2020-03-24 21:58 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; +Cc: Michael Paquier <michael@paquier.xyz>; Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers
Justin Pryzby <pryzby@telsasoft.com> writes:
> On Wed, Jan 22, 2020 at 02:34:57PM +0900, Michael Paquier wrote:
>> From patch 0003:
>> /*
>> + * Indent multi-line DETAIL if being sent to client (verbose)
>> + * We don't know if it's sent to the client (client_min_messages);
>> + * Also, that affects output to the logfile, too; assume that it's more
>> + * important to format messages requested by the client than to make
>> + * verbose logs pretty when also sent to the logfile.
>> + */
>> + msgprefix = elevel==INFO ? "!\t" : "";
>> Such stuff gets a -1 from me. This is not project-like, and you make
>> the translation of those messages much harder than they should be.
> I don't see why its harder to translate ?
The really fundamental problem with this is that you are trying to make
the server do what is properly the client's job, namely format messages
nicely. Please read the message style guidelines [1], particularly
the bit about "Formatting", which basically says "don't":
Formatting
Don't put any specific assumptions about formatting into the message
texts. Expect clients and the server log to wrap lines to fit their
own needs. In long messages, newline characters (\n) can be used to
indicate suggested paragraph breaks. Don't end a message with a
newline. Don't use tabs or other formatting characters. (In error
context displays, newlines are automatically added to separate levels
of context such as function calls.)
Rationale: Messages are not necessarily displayed on terminal-type
displays. In GUI displays or browsers these formatting instructions
are at best ignored.
regards, tom lane
[1] https://www.postgresql.org/docs/devel/error-style-guide.html
^ permalink raw reply [nested|flat] 9+ messages in thread
* Re: vacuum verbose detail logs are unclear; log at *start* of each stage
@ 2020-07-05 20:48 Daniel Gustafsson <daniel@yesql.se>
parent: Tom Lane <tgl@sss.pgh.pa.us>
0 siblings, 0 replies; 9+ messages in thread
From: Daniel Gustafsson @ 2020-07-05 20:48 UTC (permalink / raw)
To: Justin Pryzby <pryzby@telsasoft.com>; +Cc: Michael Paquier <michael@paquier.xyz>; Jeff Janes <jeff.janes@gmail.com>; pgsql-hackers; Tom Lane <tgl@sss.pgh.pa.us>
> On 24 Mar 2020, at 22:58, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> The really fundamental problem with this is that you are trying to make
> the server do what is properly the client's job, namely format messages
> nicely. Please read the message style guidelines [1], particularly
> the bit about "Formatting", which basically says "don't":
This thread has stalled since the last CF with Tom's raised issue unanswered,
and the patch no longer applies. I'm closing this as Returned with Feedback,
if there is an updated patchset then please re-open the entry.
cheers ./daniel
^ permalink raw reply [nested|flat] 9+ messages in thread
end of thread, other threads:[~2020-07-05 20:48 UTC | newest]
Thread overview: 9+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2020-01-13 00:45 Re: vacuum verbose detail logs are unclear; log at *start* of each stage; show allvisible/frozen/hintbits Justin Pryzby <pryzby@telsasoft.com>
2020-01-21 13:49 ` Justin Pryzby <pryzby@telsasoft.com>
2020-01-22 05:34 ` Michael Paquier <michael@paquier.xyz>
2020-01-23 06:57 ` Michael Paquier <michael@paquier.xyz>
2020-01-26 05:36 ` Re: vacuum verbose detail logs are unclear; log at *start* of each stage Justin Pryzby <pryzby@telsasoft.com>
2020-02-27 09:10 ` Re: vacuum verbose detail logs are unclear; log at *start* of each stage Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
2020-02-29 19:59 ` Re: vacuum verbose detail logs are unclear; log at *start* of each stage Justin Pryzby <pryzby@telsasoft.com>
2020-03-24 21:58 ` Re: vacuum verbose detail logs are unclear; log at *start* of each stage Tom Lane <tgl@sss.pgh.pa.us>
2020-07-05 20:48 ` Re: vacuum verbose detail logs are unclear; log at *start* of each stage Daniel Gustafsson <daniel@yesql.se>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox