From 5635e88f7438371c22aef117648d29c0472a0e89 Mon Sep 17 00:00:00 2001 From: Anthonin Bonnefoy Date: Mon, 27 May 2024 09:51:12 +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. buffer miss is renamed into buffer read to be consistent with pgBufferUsage naming in both vacuum and 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 | 13 ++++++------- src/backend/commands/analyze.c | 28 +++++++++++++++++++++------- 2 files changed, 27 insertions(+), 14 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 8145ea8fc3..66e86c1d08 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; @@ -609,7 +608,7 @@ heap_vacuum_rel(Relation rel, VacuumParams *params, double read_rate = 0, write_rate = 0; - 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)); @@ -738,17 +737,17 @@ 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 * (bufferusage.shared_blks_read + bufferusage.local_blks_read) / - (1024 * 1024) / (secs_dur + usecs_dur / 1000000.0); + (1024 * 1024) / (delay_in_ms / 1000.0); write_rate = (double) BLCKSZ * (bufferusage.shared_blks_dirtied + bufferusage.local_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); appendStringInfo(&buf, - _("buffer usage: %lld hits, %lld misses, %lld dirtied\n"), + _("buffer usage: %lld hits, %lld reads, %lld dirtied\n"), (long long) (bufferusage.shared_blks_hit + bufferusage.local_blks_hit), (long long) (bufferusage.shared_blks_read + bufferusage.local_blks_read), (long long) (bufferusage.shared_blks_dirtied + bufferusage.local_blks_dirtied)); diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index cab5792525..14d30af644 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) { @@ -718,15 +724,16 @@ 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; StringInfoData buf; @@ -738,6 +745,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); /* * We do not expect an analyze to take > 25 days and it simplifies @@ -775,7 +784,7 @@ do_analyze_rel(Relation onerel, VacuumParams *params, */ initStringInfo(&buf); - appendStringInfo(&buf, _("automatic analyze of table \"%s.%s.%s\"\n"), + appendStringInfo(&buf, _("analyze of table \"%s.%s.%s\"\n"), get_database_name(MyDatabaseId), get_namespace_name(RelationGetNamespace(onerel)), RelationGetRelationName(onerel)); @@ -789,13 +798,18 @@ do_analyze_rel(Relation onerel, VacuumParams *params, } appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"), read_rate, write_rate); - appendStringInfo(&buf, _("buffer usage: %lld hits, %lld misses, %lld dirtied\n"), + appendStringInfo(&buf, _("buffer usage: %lld hits, %lld reads, %lld dirtied\n"), (long long) (bufferusage.shared_blks_hit + bufferusage.local_blks_hit), (long long) (bufferusage.shared_blks_read + bufferusage.local_blks_read), (long long) (bufferusage.shared_blks_dirtied + bufferusage.local_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)