Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commit94d13d4

Browse files
committed
Improve logging of auto-vacuum and auto-analyze
When logging auto-vacuum and auto-analyze activity, include the I/Otiming if track_io_timing is enabled. Also, for auto-analyze, add theread rate and the dirty rate, similar to how that information hashistorically been logged for auto-vacuum.Stephen Frost and Jakub WartakReviewed-By: Heikki Linnakangas, Tomas VondraDiscussion:https://www.postgresql.org/message-id/VI1PR0701MB69603A433348EDCF783C6ECBF6EF0%40VI1PR0701MB6960.eurprd07.prod.outlook.com
1 parent1ea3963 commit94d13d4

File tree

3 files changed

+116
-10
lines changed

3 files changed

+116
-10
lines changed

‎doc/src/sgml/config.sgml‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -7457,9 +7457,11 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv;
74577457
I/O timing information is
74587458
displayed in <link linkend="monitoring-pg-stat-database-view">
74597459
<structname>pg_stat_database</structname></link>, in the output of
7460-
<xref linkend="sql-explain"/> when the <literal>BUFFERS</literal> option is
7461-
used, and by <xref linkend="pgstatstatements"/>. Only superusers can
7462-
change this setting.
7460+
<xref linkend="sql-explain"/> when the <literal>BUFFERS</literal> option
7461+
is used, by autovacuum for auto-vacuums and auto-analyzes, when
7462+
<xref linkend="guc-log-autovacuum-min-duration"/> is set and by
7463+
<xref linkend="pgstatstatements"/>. Only superusers can change this
7464+
setting.
74637465
</para>
74647466
</listitem>
74657467
</varlistentry>

‎src/backend/access/heap/vacuumlazy.c‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -441,6 +441,8 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
441441
TransactionIdnew_frozen_xid;
442442
MultiXactIdnew_min_multi;
443443
ErrorContextCallbackerrcallback;
444+
PgStat_Counterstartreadtime=0;
445+
PgStat_Counterstartwritetime=0;
444446

445447
Assert(params!=NULL);
446448
Assert(params->index_cleanup!=VACOPT_TERNARY_DEFAULT);
@@ -455,6 +457,11 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
455457
{
456458
pg_rusage_init(&ru0);
457459
starttime=GetCurrentTimestamp();
460+
if (track_io_timing)
461+
{
462+
startreadtime=pgStatBlockReadTime;
463+
startwritetime=pgStatBlockWriteTime;
464+
}
458465
}
459466

460467
if (params->options&VACOPT_VERBOSE)
@@ -675,6 +682,17 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params,
675682
(long long)VacuumPageDirty);
676683
appendStringInfo(&buf,_("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
677684
read_rate,write_rate);
685+
if (track_io_timing)
686+
{
687+
appendStringInfoString(&buf,_("I/O Timings:"));
688+
if (pgStatBlockReadTime-startreadtime>0)
689+
appendStringInfo(&buf,_(" read=%.3f"),
690+
(double) (pgStatBlockReadTime-startreadtime) /1000);
691+
if (pgStatBlockWriteTime-startwritetime>0)
692+
appendStringInfo(&buf,_(" write=%.3f"),
693+
(double) (pgStatBlockWriteTime-startwritetime) /1000);
694+
appendStringInfoChar(&buf,'\n');
695+
}
678696
appendStringInfo(&buf,_("system usage: %s\n"),pg_rusage_show(&ru0));
679697
appendStringInfo(&buf,
680698
_("WAL usage: %ld records, %ld full page images, %llu bytes"),

‎src/backend/commands/analyze.c‎

Lines changed: 93 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -312,6 +312,11 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
312312
Oidsave_userid;
313313
intsave_sec_context;
314314
intsave_nestlevel;
315+
int64AnalyzePageHit=VacuumPageHit;
316+
int64AnalyzePageMiss=VacuumPageMiss;
317+
int64AnalyzePageDirty=VacuumPageDirty;
318+
PgStat_Counterstartreadtime=0;
319+
PgStat_Counterstartwritetime=0;
315320

316321
if (inh)
317322
ereport(elevel,
@@ -346,8 +351,14 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
346351
/* measure elapsed time iff autovacuum logging requires it */
347352
if (IsAutoVacuumWorkerProcess()&&params->log_min_duration >=0)
348353
{
354+
if (track_io_timing)
355+
{
356+
startreadtime=pgStatBlockReadTime;
357+
startwritetime=pgStatBlockWriteTime;
358+
}
359+
349360
pg_rusage_init(&ru0);
350-
if (params->log_min_duration>0)
361+
if (params->log_min_duration >=0)
351362
starttime=GetCurrentTimestamp();
352363
}
353364

@@ -692,15 +703,90 @@ do_analyze_rel(Relation onerel, VacuumParams *params,
692703
/* Log the action if appropriate */
693704
if (IsAutoVacuumWorkerProcess()&&params->log_min_duration >=0)
694705
{
706+
TimestampTzendtime=GetCurrentTimestamp();
707+
695708
if (params->log_min_duration==0||
696-
TimestampDifferenceExceeds(starttime,GetCurrentTimestamp(),
709+
TimestampDifferenceExceeds(starttime,endtime,
697710
params->log_min_duration))
711+
{
712+
longdelay_in_ms;
713+
doubleread_rate=0;
714+
doublewrite_rate=0;
715+
StringInfoDatabuf;
716+
717+
/*
718+
* Calculate the difference in the Page Hit/Miss/Dirty that
719+
* happened as part of the analyze by subtracting out the
720+
* pre-analyze values which we saved above.
721+
*/
722+
AnalyzePageHit=VacuumPageHit-AnalyzePageHit;
723+
AnalyzePageMiss=VacuumPageMiss-AnalyzePageMiss;
724+
AnalyzePageDirty=VacuumPageDirty-AnalyzePageDirty;
725+
726+
/*
727+
* We do not expect an analyze to take > 25 days and it simplifies
728+
* things a bit to use TimestampDifferenceMilliseconds.
729+
*/
730+
delay_in_ms=TimestampDifferenceMilliseconds(starttime,endtime);
731+
732+
/*
733+
* Note that we are reporting these read/write rates in the same
734+
* manner as VACUUM does, which means that while the 'average read
735+
* rate' here actually corresponds to page misses and resulting
736+
* reads which are also picked up by track_io_timing, if enabled,
737+
* the 'average write rate' is actually talking about the rate of
738+
* pages being dirtied, not being written out, so it's typical to
739+
* have a non-zero 'avg write rate' while I/O Timings only reports
740+
* reads.
741+
*
742+
* It's not clear that an ANALYZE will ever result in
743+
* FlushBuffer() being called, but we track and support reporting
744+
* on I/O write time in case that changes as it's practically free
745+
* to do so anyway.
746+
*/
747+
748+
if (delay_in_ms>0)
749+
{
750+
read_rate= (double)BLCKSZ*AnalyzePageMiss / (1024*1024) /
751+
(delay_in_ms /1000.0);
752+
write_rate= (double)BLCKSZ*AnalyzePageDirty / (1024*1024) /
753+
(delay_in_ms /1000.0);
754+
}
755+
756+
/*
757+
* We split this up so we don't emit empty I/O timing values when
758+
* track_io_timing isn't enabled.
759+
*/
760+
761+
initStringInfo(&buf);
762+
appendStringInfo(&buf,_("automatic analyze of table \"%s.%s.%s\"\n"),
763+
get_database_name(MyDatabaseId),
764+
get_namespace_name(RelationGetNamespace(onerel)),
765+
RelationGetRelationName(onerel));
766+
appendStringInfo(&buf,_("buffer usage: %lld hits, %lld misses, %lld dirtied\n"),
767+
(long long)AnalyzePageHit,
768+
(long long)AnalyzePageMiss,
769+
(long long)AnalyzePageDirty);
770+
appendStringInfo(&buf,_("avg read rate: %.3f MB/s, avg write rate: %.3f MB/s\n"),
771+
read_rate,write_rate);
772+
if (track_io_timing)
773+
{
774+
appendStringInfoString(&buf,_("I/O Timings:"));
775+
if (pgStatBlockReadTime-startreadtime>0)
776+
appendStringInfo(&buf,_(" read=%.3f"),
777+
(double) (pgStatBlockReadTime-startreadtime) /1000);
778+
if (pgStatBlockWriteTime-startwritetime>0)
779+
appendStringInfo(&buf,_(" write=%.3f"),
780+
(double) (pgStatBlockWriteTime-startwritetime) /1000);
781+
appendStringInfoChar(&buf,'\n');
782+
}
783+
appendStringInfo(&buf,_("system usage: %s"),pg_rusage_show(&ru0));
784+
698785
ereport(LOG,
699-
(errmsg("automatic analyze of table \"%s.%s.%s\" system usage: %s",
700-
get_database_name(MyDatabaseId),
701-
get_namespace_name(RelationGetNamespace(onerel)),
702-
RelationGetRelationName(onerel),
703-
pg_rusage_show(&ru0))));
786+
(errmsg_internal("%s",buf.data)));
787+
788+
pfree(buf.data);
789+
}
704790
}
705791

706792
/* Roll back any GUC changes executed by index functions */

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp