From 94d13d474dc61800e8a17cc1959c55815b050ecd Mon Sep 17 00:00:00 2001 From: Stephen Frost Date: Tue, 16 Mar 2021 14:46:48 -0400 Subject: [PATCH] Improve logging of auto-vacuum and auto-analyze When logging auto-vacuum and auto-analyze activity, include the I/O timing if track_io_timing is enabled. Also, for auto-analyze, add the read rate and the dirty rate, similar to how that information has historically been logged for auto-vacuum. Stephen Frost and Jakub Wartak Reviewed-By: Heikki Linnakangas, Tomas Vondra Discussion: https://www.postgresql.org/message-id/VI1PR0701MB69603A433348EDCF783C6ECBF6EF0%40VI1PR0701MB6960.eurprd07.prod.outlook.com --- doc/src/sgml/config.sgml | 8 ++- src/backend/access/heap/vacuumlazy.c | 18 +++++ src/backend/commands/analyze.c | 100 +++++++++++++++++++++++++-- 3 files changed, 116 insertions(+), 10 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index a218d78bef..5e551b9f6d 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7457,9 +7457,11 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; I/O timing information is displayed in pg_stat_database, in the output of - when the BUFFERS option is - used, and by . Only superusers can - change this setting. + when the BUFFERS option + is used, by autovacuum for auto-vacuums and auto-analyzes, when + is set and by + . Only superusers can change this + setting. diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 366c122bd1..8341879d89 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -441,6 +441,8 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params, TransactionId new_frozen_xid; MultiXactId new_min_multi; ErrorContextCallback errcallback; + PgStat_Counter startreadtime = 0; + PgStat_Counter startwritetime = 0; Assert(params != NULL); Assert(params->index_cleanup != VACOPT_TERNARY_DEFAULT); @@ -455,6 +457,11 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params, { pg_rusage_init(&ru0); starttime = GetCurrentTimestamp(); + if (track_io_timing) + { + startreadtime = pgStatBlockReadTime; + startwritetime = pgStatBlockWriteTime; + } } if (params->options & VACOPT_VERBOSE) @@ -675,6 +682,17 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params, (long long) VacuumPageDirty); appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"), read_rate, write_rate); + if (track_io_timing) + { + appendStringInfoString(&buf, _("I/O Timings:")); + if (pgStatBlockReadTime - startreadtime > 0) + appendStringInfo(&buf, _(" read=%.3f"), + (double) (pgStatBlockReadTime - startreadtime) / 1000); + if (pgStatBlockWriteTime - startwritetime > 0) + appendStringInfo(&buf, _(" write=%.3f"), + (double) (pgStatBlockWriteTime - startwritetime) / 1000); + appendStringInfoChar(&buf, '\n'); + } appendStringInfo(&buf, _("system usage: %s\n"), pg_rusage_show(&ru0)); appendStringInfo(&buf, _("WAL usage: %ld records, %ld full page images, %llu bytes"), diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 3a9f358dd4..596bab2f10 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -312,6 +312,11 @@ do_analyze_rel(Relation onerel, VacuumParams *params, Oid save_userid; int save_sec_context; int save_nestlevel; + int64 AnalyzePageHit = VacuumPageHit; + int64 AnalyzePageMiss = VacuumPageMiss; + int64 AnalyzePageDirty = VacuumPageDirty; + PgStat_Counter startreadtime = 0; + PgStat_Counter startwritetime = 0; if (inh) ereport(elevel, @@ -346,8 +351,14 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* measure elapsed time iff autovacuum logging requires it */ if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0) { + if (track_io_timing) + { + startreadtime = pgStatBlockReadTime; + startwritetime = pgStatBlockWriteTime; + } + pg_rusage_init(&ru0); - if (params->log_min_duration > 0) + if (params->log_min_duration >= 0) starttime = GetCurrentTimestamp(); } @@ -692,15 +703,90 @@ do_analyze_rel(Relation onerel, VacuumParams *params, /* Log the action if appropriate */ if (IsAutoVacuumWorkerProcess() && params->log_min_duration >= 0) { + TimestampTz endtime = GetCurrentTimestamp(); + if (params->log_min_duration == 0 || - TimestampDifferenceExceeds(starttime, GetCurrentTimestamp(), + TimestampDifferenceExceeds(starttime, endtime, params->log_min_duration)) + { + long delay_in_ms; + double read_rate = 0; + double write_rate = 0; + StringInfoData buf; + + /* + * Calculate the difference in the Page Hit/Miss/Dirty that + * happened as part of the analyze by subtracting out the + * pre-analyze values which we saved above. + */ + AnalyzePageHit = VacuumPageHit - AnalyzePageHit; + AnalyzePageMiss = VacuumPageMiss - AnalyzePageMiss; + AnalyzePageDirty = VacuumPageDirty - AnalyzePageDirty; + + /* + * We do not expect an analyze to take > 25 days and it simplifies + * things a bit to use TimestampDifferenceMilliseconds. + */ + delay_in_ms = TimestampDifferenceMilliseconds(starttime, endtime); + + /* + * Note that we are reporting these read/write rates in the same + * manner as VACUUM does, which means that while the 'average read + * rate' here actually corresponds to page misses and resulting + * reads which are also picked up by track_io_timing, if enabled, + * the 'average write rate' is actually talking about the rate of + * pages being dirtied, not being written out, so it's typical to + * have a non-zero 'avg write rate' while I/O Timings only reports + * reads. + * + * It's not clear that an ANALYZE will ever result in + * FlushBuffer() being called, but we track and support reporting + * on I/O write time in case that changes as it's practically free + * to do so anyway. + */ + + if (delay_in_ms > 0) + { + read_rate = (double) BLCKSZ * AnalyzePageMiss / (1024 * 1024) / + (delay_in_ms / 1000.0); + write_rate = (double) BLCKSZ * AnalyzePageDirty / (1024 * 1024) / + (delay_in_ms / 1000.0); + } + + /* + * We split this up so we don't emit empty I/O timing values when + * track_io_timing isn't enabled. + */ + + initStringInfo(&buf); + appendStringInfo(&buf, _("automatic analyze of table \"%s.%s.%s\"\n"), + get_database_name(MyDatabaseId), + get_namespace_name(RelationGetNamespace(onerel)), + RelationGetRelationName(onerel)); + appendStringInfo(&buf, _("buffer usage: %lld hits, %lld misses, %lld dirtied\n"), + (long long) AnalyzePageHit, + (long long) AnalyzePageMiss, + (long long) AnalyzePageDirty); + appendStringInfo(&buf, _("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"), + read_rate, write_rate); + if (track_io_timing) + { + appendStringInfoString(&buf, _("I/O Timings:")); + if (pgStatBlockReadTime - startreadtime > 0) + appendStringInfo(&buf, _(" read=%.3f"), + (double) (pgStatBlockReadTime - startreadtime) / 1000); + if (pgStatBlockWriteTime - startwritetime > 0) + appendStringInfo(&buf, _(" write=%.3f"), + (double) (pgStatBlockWriteTime - startwritetime) / 1000); + appendStringInfoChar(&buf, '\n'); + } + appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0)); + ereport(LOG, - (errmsg("automatic analyze of table \"%s.%s.%s\" system usage: %s", - get_database_name(MyDatabaseId), - get_namespace_name(RelationGetNamespace(onerel)), - RelationGetRelationName(onerel), - pg_rusage_show(&ru0)))); + (errmsg_internal("%s", buf.data))); + + pfree(buf.data); + } } /* Roll back any GUC changes executed by index functions */