Rebased against 40d964ec997f64227bc0ff5e058dc4a5770a70a9 I added to March CF https://commitfest.postgresql.org/27/2425/
>From 83407b81dfc1ed2dfaa6f115dc6c4a276efb07fc Mon Sep 17 00:00:00 2001 From: Justin Pryzby <pryz...@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
>From ddfff05abecacf810612576f4d73d86e449d74fe Mon Sep 17 00:00:00 2001 From: Justin Pryzby <pryz...@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
>From d77fb8fa723afcadcc4edd5ce08f4246556f65e0 Mon Sep 17 00:00:00 2001 From: Justin Pryzby <pryz...@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
>From 0a5f3ad741468c1c4bdbffb48b69f6610524e6d7 Mon Sep 17 00:00:00 2001 From: Justin Pryzby <pryz...@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
>From 49a2dc5a4a95cb7ccce42326cdbf32a1feadc7dc Mon Sep 17 00:00:00 2001 From: Justin Pryzby <pryz...@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
>From 17b5f411873efa08ef31352d0e78379b4f7aaaa2 Mon Sep 17 00:00:00 2001 From: Justin Pryzby <pryz...@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