From 9d3b50244357ef4c4e3b6e01f91de599077179c8 Mon Sep 17 00:00:00 2001 From: Alvaro Herrera Date: Fri, 25 Nov 2011 12:10:46 -0300 Subject: [PATCH] Improve logging of autovacuum I/O activity This adds some I/O stats to the logging of autovacuum (when the operation takes long enough that log_autovacuum_min_duration causes it to be logged), so that it is easier to tune. Notably, it adds buffer I/O counts (hits, misses, dirtied) and read and write rate. Authors: Greg Smith and Noah Misch --- src/backend/commands/vacuum.c | 3 +++ src/backend/commands/vacuumlazy.c | 32 +++++++++++++++++++++++++---- src/backend/storage/buffer/bufmgr.c | 20 +++++++++++++----- src/backend/utils/init/globals.c | 4 ++++ src/include/miscadmin.h | 4 ++++ 5 files changed, 54 insertions(+), 9 deletions(-) diff --git a/src/backend/commands/vacuum.c b/src/backend/commands/vacuum.c index 89e190df956..5eec56950cc 100644 --- a/src/backend/commands/vacuum.c +++ b/src/backend/commands/vacuum.c @@ -214,6 +214,9 @@ vacuum(VacuumStmt *vacstmt, Oid relid, bool do_toast, VacuumCostActive = (VacuumCostDelay > 0); VacuumCostBalance = 0; + VacuumPageHit = 0; + VacuumPageMiss = 0; + VacuumPageDirty = 0; /* * Loop to process each selected relation. diff --git a/src/backend/commands/vacuumlazy.c b/src/backend/commands/vacuumlazy.c index 38deddc47c0..35472c50c1d 100644 --- a/src/backend/commands/vacuumlazy.c +++ b/src/backend/commands/vacuumlazy.c @@ -155,6 +155,10 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt, BlockNumber possibly_freeable; PGRUsage ru0; TimestampTz starttime = 0; + long secs; + int usecs; + double read_rate, + write_rate; bool scan_all; TransactionId freezeTableLimit; BlockNumber new_rel_pages; @@ -166,8 +170,7 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt, if (IsAutoVacuumWorkerProcess() && Log_autovacuum_min_duration >= 0) { pg_rusage_init(&ru0); - if (Log_autovacuum_min_duration > 0) - starttime = GetCurrentTimestamp(); + starttime = GetCurrentTimestamp(); } if (vacstmt->options & VACOPT_VERBOSE) @@ -262,13 +265,29 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt, /* and log the action if appropriate */ if (IsAutoVacuumWorkerProcess() && Log_autovacuum_min_duration >= 0) { + TimestampTz endtime = GetCurrentTimestamp(); + if (Log_autovacuum_min_duration == 0 || - TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(), + TimestampDifferenceExceeds(starttime, endtime, Log_autovacuum_min_duration)) + { + TimestampDifference(starttime, endtime, &secs, &usecs); + + read_rate = 0; + write_rate = 0; + if ((secs > 0) || (usecs > 0)) + { + read_rate = (double) BLCKSZ * VacuumPageMiss / (1024 * 1024) / + (secs + usecs / 1000000.0); + write_rate = (double) BLCKSZ * VacuumPageDirty / (1024 * 1024) / + (secs + usecs / 1000000.0); + } ereport(LOG, (errmsg("automatic vacuum of table \"%s.%s.%s\": index scans: %d\n" "pages: %d removed, %d remain\n" "tuples: %.0f removed, %.0f remain\n" + "buffer usage: %d hits, %d misses, %d dirtied\n" + "avg read rate: %.3f MiB/s, avg write rate: %.3f MiB/s\n" "system usage: %s", get_database_name(MyDatabaseId), get_namespace_name(RelationGetNamespace(onerel)), @@ -277,8 +296,13 @@ lazy_vacuum_rel(Relation onerel, VacuumStmt *vacstmt, vacrelstats->pages_removed, vacrelstats->rel_pages, vacrelstats->tuples_deleted, - new_rel_tuples, + vacrelstats->new_rel_tuples, + VacuumPageHit, + VacuumPageMiss, + VacuumPageDirty, + read_rate,write_rate, pg_rusage_show(&ru0)))); + } } } diff --git a/src/backend/storage/buffer/bufmgr.c b/src/backend/storage/buffer/bufmgr.c index 2342506d679..71fe8c665ec 100644 --- a/src/backend/storage/buffer/bufmgr.c +++ b/src/backend/storage/buffer/bufmgr.c @@ -340,6 +340,7 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum, { /* Just need to update stats before we exit */ *hit = true; + VacuumPageHit++; if (VacuumCostActive) VacuumCostBalance += VacuumCostPageHit; @@ -471,6 +472,7 @@ ReadBuffer_common(SMgrRelation smgr, char relpersistence, ForkNumber forkNum, TerminateBufferIO(bufHdr, false, BM_VALID); } + VacuumPageMiss++; if (VacuumCostActive) VacuumCostBalance += VacuumCostPageMiss; @@ -972,10 +974,14 @@ MarkBufferDirty(Buffer buffer) Assert(bufHdr->refcount > 0); /* - * If the buffer was not dirty already, do vacuum cost accounting. + * If the buffer was not dirty already, do vacuum accounting. */ - if (!(bufHdr->flags & BM_DIRTY) && VacuumCostActive) - VacuumCostBalance += VacuumCostPageDirty; + if (!(bufHdr->flags & BM_DIRTY)) + { + VacuumPageDirty++; + if (VacuumCostActive) + VacuumCostBalance += VacuumCostPageDirty; + } bufHdr->flags |= (BM_DIRTY | BM_JUST_DIRTIED); @@ -2337,8 +2343,12 @@ SetBufferCommitInfoNeedsSave(Buffer buffer) { LockBufHdr(bufHdr); Assert(bufHdr->refcount > 0); - if (!(bufHdr->flags & BM_DIRTY) && VacuumCostActive) - VacuumCostBalance += VacuumCostPageDirty; + if (!(bufHdr->flags & BM_DIRTY)) + { + VacuumPageDirty++; + if (VacuumCostActive) + VacuumCostBalance += VacuumCostPageDirty; + } bufHdr->flags |= (BM_DIRTY | BM_JUST_DIRTIED); UnlockBufHdr(bufHdr); } diff --git a/src/backend/utils/init/globals.c b/src/backend/utils/init/globals.c index c4c41544a21..9ce64e67629 100644 --- a/src/backend/utils/init/globals.c +++ b/src/backend/utils/init/globals.c @@ -115,6 +115,10 @@ int VacuumCostPageDirty = 20; int VacuumCostLimit = 200; int VacuumCostDelay = 0; +int VacuumPageHit = 0; +int VacuumPageMiss = 0; +int VacuumPageDirty = 0; + int VacuumCostBalance = 0; /* working state for vacuum */ bool VacuumCostActive = false; diff --git a/src/include/miscadmin.h b/src/include/miscadmin.h index 9d194171a56..4ee08fead6f 100644 --- a/src/include/miscadmin.h +++ b/src/include/miscadmin.h @@ -230,6 +230,10 @@ extern int VacuumCostPageDirty; extern int VacuumCostLimit; extern int VacuumCostDelay; +extern int VacuumPageHit; +extern int VacuumPageMiss; +extern int VacuumPageDirty; + extern int VacuumCostBalance; extern bool VacuumCostActive; -- 2.39.5