open-dsi
/
postgres
mirror of https://github.com/postgres/postgres
1
0
Fork 0
Code Issues Packages Projects Releases Wiki 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
pull/64/head
Stephen Frost 5 years ago
parent 1ea396362b
commit 94d13d474d
3 changed files with 116 additions and 10 deletions
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Show Stats Download Patch File Download Diff File
  1. 8
      doc/src/sgml/config.sgml
  2. 18
      src/backend/access/heap/vacuumlazy.c
  3. 100
      src/backend/commands/analyze.c

8
doc/src/sgml/config.sgml
Unescape View File

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

18
src/backend/access/heap/vacuumlazy.c
Unescape View File

@ -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"),

100
src/backend/commands/analyze.c
Unescape 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 */

Write Preview
Loading…
Cancel
Save