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
This commit is contained in:
parent
1ea396362b
commit
94d13d474d
|
@ -7457,9 +7457,11 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
|
|||
I/O timing information is
|
||||
displayed in <link linkend="monitoring-pg-stat-database-view">
|
||||
<structname>pg_stat_database</structname></link>, in the output of
|
||||
<xref linkend="sql-explain"/> when the <literal>BUFFERS</literal> option is
|
||||
used, and by <xref linkend="pgstatstatements"/>. Only superusers can
|
||||
change this setting.
|
||||
<xref linkend="sql-explain"/> when the <literal>BUFFERS</literal> option
|
||||
is used, by autovacuum for auto-vacuums and auto-analyzes, when
|
||||
<xref linkend="guc-log-autovacuum-min-duration"/> is set and by
|
||||
<xref linkend="pgstatstatements"/>. Only superusers can change this
|
||||
setting.
|
||||
</para>
|
||||
</listitem>
|
||||
</varlistentry>
|
||||
|
|
|
@ -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"),
|
||||
|
|
|
@ -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 */
|
||||
|
|
Loading…
Reference in New Issue