From cea4a55edc18d7ea1f6b89b87ad7d5dfd056a7bd 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 | 26 ++++++++++++++++++++------ 2 files changed, 25 insertions(+), 12 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index cd5d5fc319..af3f603b36 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 258627d3db..c4575365b8 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; @@ -741,6 +748,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; @@ -785,7 +794,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)); @@ -803,9 +812,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)