From 2e3947da159b8a2f9657fd8c1a5a1f366f83ba85 Mon Sep 17 00:00:00 2001 From: Peter Geoghegan Date: Sun, 21 Nov 2021 21:48:33 -0800 Subject: [PATCH v2] Unify VACUUM VERBOSE and log_autovacuum_min_duration. Author: Peter Geoghegan Discussion: https://postgr.es/m/CAH2-WzmW4Me7_qR4X4ka7pxP-jGmn7=Npma_-Z-9Y1eD0MQRLw@mail.gmail.com --- src/include/commands/vacuum.h | 6 +- src/backend/access/heap/vacuumlazy.c | 240 ++++++++++----------------- src/backend/commands/vacuum.c | 2 +- 3 files changed, 88 insertions(+), 160 deletions(-) diff --git a/src/include/commands/vacuum.h b/src/include/commands/vacuum.h index 4cfd52eaf..d1e804f47 100644 --- a/src/include/commands/vacuum.h +++ b/src/include/commands/vacuum.h @@ -177,7 +177,7 @@ typedef struct VacAttrStats /* flag bits for VacuumParams->options */ #define VACOPT_VACUUM 0x01 /* do VACUUM */ #define VACOPT_ANALYZE 0x02 /* do ANALYZE */ -#define VACOPT_VERBOSE 0x04 /* print progress info */ +#define VACOPT_VERBOSE 0x04 /* output instrumentation */ #define VACOPT_FREEZE 0x08 /* FREEZE option */ #define VACOPT_FULL 0x10 /* FULL (non-concurrent) vacuum */ #define VACOPT_SKIP_LOCKED 0x20 /* skip if cannot get lock */ @@ -217,8 +217,8 @@ typedef struct VacuumParams * whole table */ bool is_wraparound; /* force a for-wraparound vacuum */ int log_min_duration; /* minimum execution threshold in ms at - * which verbose logs are activated, -1 - * to use default */ + * which verbose output is logged, -1 to + * use default */ VacOptValue index_cleanup; /* Do index vacuum and cleanup */ VacOptValue truncate; /* Truncate empty pages at the end */ diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index db6becfed..754f373d3 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -180,7 +180,6 @@ typedef struct LVShared * the lazy vacuum. */ Oid relid; - int elevel; /* * Fields for both index vacuum and cleanup. @@ -333,7 +332,7 @@ typedef struct LVRelState /* Error reporting state */ char *relnamespace; char *relname; - char *indname; + char *indname; /* Current index name */ BlockNumber blkno; /* used only for heap operations */ OffsetNumber offnum; /* used only for heap operations */ VacErrPhase phase; @@ -393,9 +392,6 @@ typedef struct LVSavedErrInfo VacErrPhase phase; } LVSavedErrInfo; -/* elevel controls whole VACUUM's verbosity */ -static int elevel = -1; - /* non-export function prototypes */ static void lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, @@ -472,6 +468,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, BufferAccessStrategy bstrategy) { LVRelState *vacrel; + bool verbose, + instrument; PGRUsage ru0; TimestampTz starttime = 0; WalUsage walusage_start = pgWalUsage; @@ -497,8 +495,10 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, TransactionId FreezeLimit; MultiXactId MultiXactCutoff; - /* measure elapsed time iff autovacuum logging requires it */ - if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0) + verbose = (params->options & VACOPT_VERBOSE) != 0; + instrument = (verbose || (IsAutoVacuumWorkerProcess() && + params->log_min_duration >= 0)); + if (instrument) { pg_rusage_init(&ru0); starttime = GetCurrentTimestamp(); @@ -509,11 +509,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, } } - if (params->options & VACOPT_VERBOSE) - elevel = INFO; - else - elevel = DEBUG2; - pgstat_progress_start_command(PROGRESS_COMMAND_VACUUM, RelationGetRelid(rel)); @@ -538,14 +533,56 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, if (params->options & VACOPT_DISABLE_PAGE_SKIPPING) aggressive = true; + /* + * Setup error traceback support for ereport(). The idea is to set up an + * error context callback to display additional information on any error + * during a vacuum. During different phases of vacuum, we update the + * state so that the error context callback always display current + * information. Copy the names of relations into local memory now, too. + * It isn't always safe to assume that we can get the name of each rel. + * It's convenient for code in lazy_scan_heap to always use these temp + * copies. + * + * Note that the index vacuum and heap vacuum phases may be called + * multiple times in the middle of the heap scan phase. So the old phase + * information is restored at the end of those phases. + */ vacrel = (LVRelState *) palloc0(sizeof(LVRelState)); + vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel)); + vacrel->relname = pstrdup(RelationGetRelationName(rel)); + vacrel->indname = NULL; + vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN; + errcallback.callback = vacuum_error_callback; + errcallback.arg = vacrel; + errcallback.previous = error_context_stack; + error_context_stack = &errcallback; + if (verbose) + { + /* VACUUM VERBOSE initial INFO message, before we start real work */ + Assert(!IsAutoVacuumWorkerProcess()); + if (aggressive) + ereport(INFO, + (errmsg("aggressively vacuuming \"%s.%s.%s\"", + get_database_name(MyDatabaseId), + vacrel->relnamespace, vacrel->relname))); + else + ereport(INFO, + (errmsg("vacuuming \"%s.%s.%s\"", + get_database_name(MyDatabaseId), + vacrel->relnamespace, vacrel->relname))); + } /* Set up high level stuff about rel */ vacrel->rel = rel; vac_open_indexes(vacrel->rel, RowExclusiveLock, &vacrel->nindexes, &vacrel->indrels); - vacrel->failsafe_active = false; - vacrel->consider_bypass_optimization = true; + if (instrument && vacrel->nindexes > 0) + { + /* Couldn't copy index names earlier, so do that now instead */ + indnames = palloc(sizeof(char *) * vacrel->nindexes); + for (int i = 0; i < vacrel->nindexes; i++) + indnames[i] = pstrdup(RelationGetRelationName(vacrel->indrels[i])); + } /* * The index_cleanup param either disables index vacuuming and cleanup or @@ -559,6 +596,8 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, Assert(params->index_cleanup != VACOPTVALUE_UNSPECIFIED); Assert(params->truncate != VACOPTVALUE_UNSPECIFIED && params->truncate != VACOPTVALUE_AUTO); + vacrel->failsafe_active = false; + vacrel->consider_bypass_optimization = true; vacrel->do_index_vacuuming = true; vacrel->do_index_cleanup = true; vacrel->do_rel_truncate = (params->truncate != VACOPTVALUE_DISABLED); @@ -589,37 +628,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->FreezeLimit = FreezeLimit; vacrel->MultiXactCutoff = MultiXactCutoff; - vacrel->relnamespace = get_namespace_name(RelationGetNamespace(rel)); - vacrel->relname = pstrdup(RelationGetRelationName(rel)); - vacrel->indname = NULL; - vacrel->phase = VACUUM_ERRCB_PHASE_UNKNOWN; - - /* Save index names iff autovacuum logging requires it */ - if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0 && - vacrel->nindexes > 0) - { - indnames = palloc(sizeof(char *) * vacrel->nindexes); - for (int i = 0; i < vacrel->nindexes; i++) - indnames[i] = - pstrdup(RelationGetRelationName(vacrel->indrels[i])); - } - - /* - * Setup error traceback support for ereport(). The idea is to set up an - * error context callback to display additional information on any error - * during a vacuum. During different phases of vacuum (heap scan, heap - * vacuum, index vacuum, index clean up, heap truncate), we update the - * error context callback to display appropriate information. - * - * Note that the index vacuum and heap vacuum phases may be called - * multiple times in the middle of the heap scan phase. So the old phase - * information is restored at the end of those phases. - */ - errcallback.callback = vacuum_error_callback; - errcallback.arg = vacrel; - errcallback.previous = error_context_stack; - error_context_stack = &errcallback; - /* * Call lazy_scan_heap to perform all required heap pruning, index * vacuuming, and heap vacuuming (plus related processing) @@ -650,11 +658,6 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, */ if (should_attempt_truncation(vacrel)) { - /* - * Update error traceback information. This is the last phase during - * which we add context information to errors, so we don't need to - * revert to the previous phase. - */ update_vacuum_error_info(vacrel, NULL, VACUUM_ERRCB_PHASE_TRUNCATE, vacrel->nonempty_pages, InvalidOffsetNumber); @@ -717,12 +720,11 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, vacrel->new_dead_tuples); pgstat_progress_end_command(); - /* and log the action if appropriate */ - if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0) + if (instrument) { TimestampTz endtime = GetCurrentTimestamp(); - if (params->log_min_duration == 0 || + if (verbose || params->log_min_duration == 0 || TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) { @@ -745,12 +747,17 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, (secs + usecs / 1000000.0); } - /* - * 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); - if (params->is_wraparound) + if (verbose) + { + /* + * Aggressiveness already reported earlier, in dedicated + * VACUUM VERBOSE ereport + */ + Assert(!params->is_wraparound); + msgfmt = _("finished vacuuming \"%s.%s.%s\": index scans: %d\n"); + } + else if (params->is_wraparound) { /* * While it's possible for a VACUUM to be both is_wraparound @@ -849,7 +856,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, (unsigned long long) walusage.wal_bytes); appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0)); - ereport(LOG, + ereport(verbose ? INFO : LOG, (errmsg_internal("%s", buf.data))); pfree(buf.data); } @@ -861,7 +868,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, if (vacrel->indstats[i]) pfree(vacrel->indstats[i]); - if (indnames && indnames[i]) + if (instrument) pfree(indnames[i]); } } @@ -911,10 +918,8 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive) next_unskippable_block, next_failsafe_block, next_fsm_block_to_vacuum; - PGRUsage ru0; Buffer vmbuffer = InvalidBuffer; bool skipping_blocks; - StringInfoData buf; const int initprog_index[] = { PROGRESS_VACUUM_PHASE, PROGRESS_VACUUM_TOTAL_HEAP_BLKS, @@ -923,19 +928,6 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive) int64 initprog_val[3]; GlobalVisState *vistest; - pg_rusage_init(&ru0); - - if (aggressive) - ereport(elevel, - (errmsg("aggressively vacuuming \"%s.%s\"", - vacrel->relnamespace, - vacrel->relname))); - else - ereport(elevel, - (errmsg("vacuuming \"%s.%s\"", - vacrel->relnamespace, - vacrel->relname))); - nblocks = RelationGetNumberOfBlocks(vacrel->rel); next_unskippable_block = 0; next_failsafe_block = 0; @@ -1628,49 +1620,15 @@ lazy_scan_heap(LVRelState *vacrel, VacuumParams *params, bool aggressive) /* * When the table has no indexes (i.e. in the one-pass strategy case), - * make log report that lazy_vacuum_heap_rel would've made had there been - * indexes. (As in the two-pass strategy case, only make this report when - * there were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.) + * produce debug output that lazy_vacuum_heap_rel would've made had there + * been indexes. (As in the two-pass strategy case, only do so when there + * were LP_DEAD line pointers vacuumed in lazy_vacuum_heap_page.) */ if (vacrel->nindexes == 0 && vacrel->lpdead_item_pages > 0) - ereport(elevel, + ereport(DEBUG2, (errmsg("table \"%s\": removed %lld dead item identifiers in %u pages", vacrel->relname, (long long) vacrel->lpdead_items, vacrel->lpdead_item_pages))); - - /* - * Make a log report summarizing pruning and freezing. - * - * The autovacuum specific logging in heap_vacuum_rel summarizes an entire - * VACUUM operation, whereas each VACUUM VERBOSE log report generally - * summarizes a single round of index/heap vacuuming (or rel truncation). - * It wouldn't make sense to report on pruning or freezing while following - * that convention, though. You can think of this log report as a summary - * of our first pass over the heap. - */ - initStringInfo(&buf); - appendStringInfo(&buf, - _("%lld dead row versions cannot be removed yet, oldest xmin: %u\n"), - (long long) vacrel->new_dead_tuples, vacrel->OldestXmin); - appendStringInfo(&buf, ngettext("Skipped %u page due to buffer pins, ", - "Skipped %u pages due to buffer pins, ", - vacrel->pinskipped_pages), - vacrel->pinskipped_pages); - appendStringInfo(&buf, ngettext("%u frozen page.\n", - "%u frozen pages.\n", - vacrel->frozenskipped_pages), - vacrel->frozenskipped_pages); - appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0)); - - ereport(elevel, - (errmsg("table \"%s.%s\": found %lld removable, %lld nonremovable row versions in %u out of %u pages", - vacrel->relnamespace, - vacrel->relname, - (long long) vacrel->tuples_deleted, - (long long) vacrel->num_tuples, vacrel->scanned_pages, - nblocks), - errdetail_internal("%s", buf.data))); - pfree(buf.data); } /* @@ -2162,11 +2120,6 @@ lazy_vacuum(LVRelState *vacrel) * calls.) */ vacrel->do_index_vacuuming = false; - ereport(elevel, - (errmsg("table \"%s\": index scan bypassed: %u pages from table (%.2f%% of total) have %lld dead item identifiers", - vacrel->relname, vacrel->lpdead_item_pages, - 100.0 * vacrel->lpdead_item_pages / vacrel->rel_pages, - (long long) vacrel->lpdead_items))); } else if (lazy_vacuum_all_indexes(vacrel)) { @@ -2309,7 +2262,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel) { int index; BlockNumber vacuumed_pages; - PGRUsage ru0; Buffer vmbuffer = InvalidBuffer; LVSavedErrInfo saved_err_info; @@ -2326,7 +2278,6 @@ lazy_vacuum_heap_rel(LVRelState *vacrel) VACUUM_ERRCB_PHASE_VACUUM_HEAP, InvalidBlockNumber, InvalidOffsetNumber); - pg_rusage_init(&ru0); vacuumed_pages = 0; index = 0; @@ -2373,10 +2324,9 @@ lazy_vacuum_heap_rel(LVRelState *vacrel) (index == vacrel->lpdead_items && vacuumed_pages == vacrel->lpdead_item_pages)); - ereport(elevel, + ereport(DEBUG2, (errmsg("table \"%s\": removed %lld dead item identifiers in %u pages", - vacrel->relname, (long long) index, vacuumed_pages), - errdetail_internal("%s", pg_rusage_show(&ru0)))); + vacrel->relname, (long long) index, vacuumed_pages))); /* Revert to the previous phase information for error traceback */ restore_vacuum_error_info(vacrel, &saved_err_info); @@ -2744,13 +2694,13 @@ parallel_vacuum_process_all_indexes(LVRelState *vacrel, bool vacuum) } if (vacuum) - 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), lps->pcxt->nworkers_launched, nworkers))); else - 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), @@ -3019,16 +2969,12 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat, double reltuples, LVRelState *vacrel) { IndexVacuumInfo ivinfo; - PGRUsage ru0; LVSavedErrInfo saved_err_info; - pg_rusage_init(&ru0); - ivinfo.index = indrel; ivinfo.analyze_only = false; ivinfo.report_progress = false; ivinfo.estimated_count = true; - ivinfo.message_level = elevel; ivinfo.num_heap_tuples = reltuples; ivinfo.strategy = vacrel->bstrategy; @@ -3048,10 +2994,9 @@ lazy_vacuum_one_index(Relation indrel, IndexBulkDeleteResult *istat, istat = index_bulk_delete(&ivinfo, istat, lazy_tid_reaped, (void *) vacrel->dead_items); - ereport(elevel, + ereport(DEBUG2, (errmsg("scanned index \"%s\" to remove %d row versions", - vacrel->indname, vacrel->dead_items->num_items), - errdetail_internal("%s", pg_rusage_show(&ru0)))); + vacrel->indname, vacrel->dead_items->num_items))); /* Revert to the previous phase information for error traceback */ restore_vacuum_error_info(vacrel, &saved_err_info); @@ -3076,16 +3021,12 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat, LVRelState *vacrel) { IndexVacuumInfo ivinfo; - PGRUsage ru0; LVSavedErrInfo saved_err_info; - pg_rusage_init(&ru0); - ivinfo.index = indrel; ivinfo.analyze_only = false; ivinfo.report_progress = false; ivinfo.estimated_count = estimated_count; - ivinfo.message_level = elevel; ivinfo.num_heap_tuples = reltuples; ivinfo.strategy = vacrel->bstrategy; @@ -3105,21 +3046,17 @@ lazy_cleanup_one_index(Relation indrel, IndexBulkDeleteResult *istat, istat = index_vacuum_cleanup(&ivinfo, istat); if (istat) - { - ereport(elevel, + ereport(DEBUG2, (errmsg("index \"%s\" now contains %.0f row versions in %u pages", RelationGetRelationName(indrel), istat->num_index_tuples, istat->num_pages), errdetail("%.0f index row versions were removed.\n" "%u index pages were newly deleted.\n" - "%u index pages are currently deleted, of which %u are currently reusable.\n" - "%s.", + "%u index pages are currently deleted, of which %u are currently reusable.\n", istat->tuples_removed, istat->pages_newly_deleted, - istat->pages_deleted, istat->pages_free, - pg_rusage_show(&ru0)))); - } + istat->pages_deleted, istat->pages_free))); /* Revert to the previous phase information for error traceback */ restore_vacuum_error_info(vacrel, &saved_err_info); @@ -3188,10 +3125,6 @@ lazy_truncate_heap(LVRelState *vacrel) */ do { - PGRUsage ru0; - - pg_rusage_init(&ru0); - /* * We need full exclusive lock on the relation in order to do * truncation. If we can't get it, give up rather than waiting --- we @@ -3219,7 +3152,7 @@ lazy_truncate_heap(LVRelState *vacrel) * We failed to establish the lock in the specified number of * retries. This means we give up truncating. */ - ereport(elevel, + ereport(DEBUG2, (errmsg("\"%s\": stopping truncate due to conflicting lock request", vacrel->relname))); return; @@ -3289,12 +3222,10 @@ lazy_truncate_heap(LVRelState *vacrel) vacrel->pages_removed += orig_rel_pages - new_rel_pages; vacrel->rel_pages = new_rel_pages; - ereport(elevel, + ereport(DEBUG2, (errmsg("table \"%s\": truncated %u to %u pages", vacrel->relname, - orig_rel_pages, new_rel_pages), - errdetail_internal("%s", - pg_rusage_show(&ru0)))); + orig_rel_pages, new_rel_pages))); orig_rel_pages = new_rel_pages; } while (new_rel_pages > vacrel->nonempty_pages && lock_waiter_detected); } @@ -3353,7 +3284,7 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected) { if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock)) { - ereport(elevel, + ereport(DEBUG2, (errmsg("table \"%s\": suspending truncate due to conflicting lock request", vacrel->relname))); @@ -3997,7 +3928,6 @@ parallel_vacuum_begin(LVRelState *vacrel, int nrequested) shared = (LVShared *) shm_toc_allocate(pcxt->toc, est_shared_len); MemSet(shared, 0, est_shared_len); shared->relid = RelationGetRelid(vacrel->rel); - shared->elevel = elevel; shared->maintenance_work_mem_worker = (nindexes_mwm > 0) ? maintenance_work_mem / Min(parallel_workers, nindexes_mwm) : @@ -4154,8 +4084,6 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc) lvshared = (LVShared *) shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_SHARED, false); - elevel = lvshared->elevel; - elog(DEBUG1, "starting parallel vacuum worker"); /* Set debug_query_string for individual workers */ diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c index 5c4bc15b4..47d8ab733 100644 --- a/src/backend/commands/vacuum.c +++ b/src/backend/commands/vacuum.c @@ -261,7 +261,7 @@ ExecVacuum(ParseState *pstate, VacuumStmt *vacstmt, bool isTopLevel) /* user-invoked vacuum is never "for wraparound" */ params.is_wraparound = false; - /* user-invoked vacuum never uses this parameter */ + /* user-invoked vacuum uses VACOPT_VERBOSE instead of log_min_duration */ params.log_min_duration = -1; /* Now go through the common routine */ -- 2.30.2