database/postgres
1
0
Fork 0
mirror of https://github.com/postgres/postgres.git synced 2025-07-08 11:42:09 +03:00
Code Activity

Improve logging of auto-vacuum and auto-analyze

Browse Source 
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
This commit is contained in:
Stephen Frost
2021-03-16 14:46:48 -04:00
parent 1ea396362b
commit 94d13d474d
3 changed files with 116 additions and 10 deletions
Download Patch File Download Diff File Expand all files Collapse all files

100
src/backend/commands/analyze.c
View File

@ -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 */