From 23c046a0a60fea7f6cf3eb1197c4ba52b9ad74d5 Mon Sep 17 00:00:00 2001 From: Anthonin Bonnefoy Date: Mon, 8 Jul 2024 08:30:31 +0200 Subject: Output buffer and wal usage with verbose analyze Currently, buffer usage generated by analyze is only logged during autoanalyze. To make behaviour more consistent with VACUUM VERBOSE, this patch outputs buffer and wal usage of analyze on ANALYZE VERBOSE. The patch also changes delta time computation in VACUUM to use ms difference, to both simplify and make it more consistent with what's done in ANALYZE. --- src/backend/access/heap/vacuumlazy.c | 11 +++++----- src/backend/commands/analyze.c | 33 +++++++++++++++++++++++----- 2 files changed, 32 insertions(+), 12 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index d82aa3d4896..32cce88e260 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -599,8 +599,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) { - long secs_dur; - int usecs_dur; + long delay_in_ms; WalUsage walusage; BufferUsage bufferusage; StringInfoData buf; @@ -612,7 +611,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, int64 total_blks_read; int64 total_blks_dirtied; - TimestampDifference(starttime, endtime, &secs_dur, &usecs_dur); + delay_in_ms = TimestampDifferenceMilliseconds(starttime, endtime); memset(&walusage, 0, sizeof(WalUsage)); WalUsageAccumDiff(&walusage, &pgWalUsage, &startwalusage); memset(&bufferusage, 0, sizeof(BufferUsage)); @@ -748,12 +747,12 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, appendStringInfo(&buf, _("I/O timings: read: %.3f ms, write: %.3f ms\n"), read_ms, write_ms); } - if (secs_dur > 0 || usecs_dur > 0) + if (delay_in_ms > 0) { read_rate = (double) BLCKSZ * total_blks_read / - (1024 * 1024) / (secs_dur + usecs_dur / 1000000.0); + (1024 * 1024) / (delay_in_ms / 1000.0); write_rate = (double) BLCKSZ * total_blks_dirtied / - (1024 * 1024) / (secs_dur + usecs_dur / 1000000.0); + (1024 * 1024) / (delay_in_ms / 1000.0); } appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"), read_rate, write_rate); diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index d4377186d77..d492772aacb 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -288,7 +288,9 @@ do_analyze_rel(Relation onerel, VacuumParams *params, ind; Relation *Irel; int nindexes; - bool hasindex; + bool verbose, + instrument, + hasindex; VacAttrStats **vacattrstats; AnlIndexData *indexdata; int targrows, @@ -303,11 +305,15 @@ do_analyze_rel(Relation onerel, VacuumParams *params, Oid save_userid; int save_sec_context; int save_nestlevel; + WalUsage startwalusage = pgWalUsage; BufferUsage startbufferusage = pgBufferUsage; BufferUsage bufferusage; PgStat_Counter startreadtime = 0; PgStat_Counter startwritetime = 0; + verbose = (params->options & VACOPT_VERBOSE) != 0; + instrument = (verbose || (AmAutoVacuumWorkerProcess() && + params->log_min_duration >= 0)); if (inh) ereport(elevel, (errmsg("analyzing \"%s.%s\" inheritance tree", @@ -340,7 +346,7 @@ do_analyze_rel(Relation onerel, VacuumParams *params, RestrictSearchPath(); /* measure elapsed time iff autovacuum logging requires it */ - if (AmAutoVacuumWorkerProcess() && params->log_min_duration >= 0) + if (instrument) { if (track_io_timing) { @@ -723,17 +729,19 @@ do_analyze_rel(Relation onerel, VacuumParams *params, vac_close_indexes(nindexes, Irel, NoLock); /* Log the action if appropriate */ - if (AmAutoVacuumWorkerProcess() && 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)) { long delay_in_ms; + WalUsage walusage; double read_rate = 0; double write_rate = 0; + char *msgfmt; StringInfoData buf; int64 total_blks_hit; int64 total_blks_read; @@ -746,6 +754,8 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ memset(&bufferusage, 0, sizeof(BufferUsage)); BufferUsageAccumDiff(&bufferusage, &pgBufferUsage, &startbufferusage); + memset(&walusage, 0, sizeof(WalUsage)); + WalUsageAccumDiff(&walusage, &pgWalUsage, &startwalusage); total_blks_hit = bufferusage.shared_blks_hit + bufferusage.local_blks_hit; @@ -790,7 +800,13 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ initStringInfo(&buf); - appendStringInfo(&buf, _("automatic analyze of table \"%s.%s.%s\"\n"), + + if (AmAutoVacuumWorkerProcess()) + msgfmt = _("automatic analyze of table \"%s.%s.%s\"\n"); + else + msgfmt = _("analyze of table \"%s.%s.%s\"\n"); + + appendStringInfo(&buf, msgfmt, get_database_name(MyDatabaseId), get_namespace_name(RelationGetNamespace(onerel)), RelationGetRelationName(onerel)); @@ -808,9 +824,14 @@ do_analyze_rel(Relation onerel, VacuumParams *params, (long long) total_blks_hit, (long long) total_blks_read, (long long) total_blks_dirtied); + appendStringInfo(&buf, + _("WAL usage: %lld records, %lld full page images, %llu bytes\n"), + (long long) walusage.wal_records, + (long long) walusage.wal_fpi, + (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); -- 2.39.3 (Apple Git-146)