From d0f3c8dd28859bc4a48f0c5bc9cf81ecb7f93065 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 d82aa3d489..32cce88e26 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 d4377186d7..d492772aac 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)