From 07b468eb32e4980eb006e5da07c9a610c28fc47f Mon Sep 17 00:00:00 2001 From: Shayon Mukherjee Date: Sat, 9 Aug 2025 10:43:47 -0400 Subject: [PATCH v1] Extend logging for VACUUM truncation suspensions with attempts and elapsed time This patch adds visibility into VACUUM truncation suspension behavior by logging attempt counts and elapsed time during verbose output. When VACUUM truncation is suspended due to lock conflicts, users now see - Individual suspension messages with attempt number and cumulative time - Summary statistics showing total suspensions and elapsed time Thus, giving users more visibility into the process --- src/backend/access/heap/vacuumlazy.c | 55 +++++++++++++++++++++++++--- 1 file changed, 49 insertions(+), 6 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 14036c27e8..4cfb31480e 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -458,7 +458,9 @@ static IndexBulkDeleteResult *lazy_cleanup_one_index(Relation indrel, static bool should_attempt_truncation(LVRelState *vacrel); static void lazy_truncate_heap(LVRelState *vacrel); static BlockNumber count_nondeletable_pages(LVRelState *vacrel, - bool *lock_waiter_detected); + bool *lock_waiter_detected, + int suspension_count, + instr_time *truncate_start_time); static void dead_items_alloc(LVRelState *vacrel, int nworkers); static void dead_items_add(LVRelState *vacrel, BlockNumber blkno, OffsetNumber *offsets, int num_offsets); @@ -3203,6 +3205,8 @@ lazy_truncate_heap(LVRelState *vacrel) BlockNumber new_rel_pages; bool lock_waiter_detected; int lock_retry; + int truncate_suspension_count = 0; + instr_time truncate_start_time; /* Report that we are now truncating */ pgstat_progress_update_param(PROGRESS_VACUUM_PHASE, @@ -3212,6 +3216,9 @@ lazy_truncate_heap(LVRelState *vacrel) update_vacuum_error_info(vacrel, NULL, VACUUM_ERRCB_PHASE_TRUNCATE, vacrel->nonempty_pages, InvalidOffsetNumber); + /* Record start time for truncation phase */ + INSTR_TIME_SET_CURRENT(truncate_start_time); + /* * Loop until no more truncating can be done. */ @@ -3282,7 +3289,7 @@ lazy_truncate_heap(LVRelState *vacrel) * other backends could have added tuples to these pages whilst we * were vacuuming. */ - new_rel_pages = count_nondeletable_pages(vacrel, &lock_waiter_detected); + new_rel_pages = count_nondeletable_pages(vacrel, &lock_waiter_detected, truncate_suspension_count, &truncate_start_time); vacrel->blkno = new_rel_pages; if (new_rel_pages >= orig_rel_pages) @@ -3292,6 +3299,10 @@ lazy_truncate_heap(LVRelState *vacrel) return; } + /* Count this suspension if lock waiters were detected */ + if (lock_waiter_detected) + truncate_suspension_count++; + /* * Okay to truncate. */ @@ -3320,6 +3331,23 @@ lazy_truncate_heap(LVRelState *vacrel) orig_rel_pages, new_rel_pages))); orig_rel_pages = new_rel_pages; } while (new_rel_pages > vacrel->nonempty_pages && lock_waiter_detected); + + /* Report truncation suspension statistics in verbose mode */ + if (vacrel->verbose && truncate_suspension_count > 0) + { + instr_time truncate_end_time; + instr_time truncate_elapsed; + + INSTR_TIME_SET_CURRENT(truncate_end_time); + truncate_elapsed = truncate_end_time; + INSTR_TIME_SUBTRACT(truncate_elapsed, truncate_start_time); + + ereport(INFO, + (errmsg("table \"%s\": truncation completed after %d suspension(s), total elapsed: %.3f s", + vacrel->relname, + truncate_suspension_count, + INSTR_TIME_GET_DOUBLE(truncate_elapsed)))); + } } /* @@ -3328,7 +3356,7 @@ lazy_truncate_heap(LVRelState *vacrel) * Returns number of nondeletable pages (last nonempty page + 1). */ static BlockNumber -count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected) +count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected, int suspension_count, instr_time *truncate_start_time) { BlockNumber blkno; BlockNumber prefetchedUntil; @@ -3376,9 +3404,24 @@ count_nondeletable_pages(LVRelState *vacrel, bool *lock_waiter_detected) { if (LockHasWaitersRelation(vacrel->rel, AccessExclusiveLock)) { - ereport(vacrel->verbose ? INFO : DEBUG2, - (errmsg("table \"%s\": suspending truncate due to conflicting lock request", - vacrel->relname))); + if (vacrel->verbose) + { + instr_time elapsed_so_far; + + elapsed_so_far = currenttime; + INSTR_TIME_SUBTRACT(elapsed_so_far, *truncate_start_time); + + ereport(INFO, + (errmsg("table \"%s\": suspending truncate due to conflicting lock request (attempt %d, elapsed: %.3f s)", + vacrel->relname, suspension_count + 1, + INSTR_TIME_GET_DOUBLE(elapsed_so_far)))); + } + else + { + ereport(DEBUG2, + (errmsg("table \"%s\": suspending truncate due to conflicting lock request", + vacrel->relname))); + } *lock_waiter_detected = true; return blkno; -- 2.39.5 (Apple Git-154)