Greetings, * Heikki Linnakangas (hlinn...@iki.fi) wrote: > On 13/01/2021 23:17, Stephen Frost wrote: > >Would be great to get a review / comments from others as to if there's > >any concerns. I'll admit that it seems reasonably straight-forward to > >me, but hey, I wrote most of it, so that's not really a fair > >assessment... ;) > > Look good overall. A few minor comments:
Thanks a lot for the review! > The patch consists of two part: add stats to the log for auto-analyze, and > implement prefetching. They seem like independent features, consider > splitting into two patches. Yeah, that's a good point. I had anticipated that there would be overlap but in the end there really wasn't. Done in the attached. > It's a bit weird that you get more stats in the log for > autovacuum/autoanalyze than you get with VACUUM/ANALYZE VERBOSE. Not really > this patch's fault though. Agreed. > This conflicts with the patch at https://commitfest.postgresql.org/31/2907/, > to refactor the table AM analyze API. That's OK, it's straightforward to > resolve regardless of which patch is committed first. Agreed. > > /* Outer loop over blocks to sample */ > > while (BlockSampler_HasMore(&bs)) > > { > >#ifdef USE_PREFETCH > > BlockNumber prefetch_targblock = InvalidBlockNumber; > >#endif > > BlockNumber targblock = BlockSampler_Next(&bs); > > > >#ifdef USE_PREFETCH > > > > /* > > * Make sure that every time the main BlockSampler is moved > > forward > > * that our prefetch BlockSampler also gets moved forward, so > > that we > > * always stay out ahead. > > */ > > if (BlockSampler_HasMore(&prefetch_bs)) > > prefetch_targblock = BlockSampler_Next(&prefetch_bs); > >#endif > > > > vacuum_delay_point(); > > > > if (!table_scan_analyze_next_block(scan, targblock, > > vac_strategy)) > > continue; > > > >#ifdef USE_PREFETCH > > > > /* > > * When pre-fetching, after we get a block, tell the kernel > > about the > > * next one we will want, if there's any left. > > */ > > if (effective_io_concurrency && prefetch_targblock != > > InvalidBlockNumber) > > PrefetchBuffer(scan->rs_rd, MAIN_FORKNUM, > > prefetch_targblock); > >#endif > > > > while (table_scan_analyze_next_tuple(scan, OldestXmin, > > &liverows, &deadrows, slot)) > > { > > ... > > } > > > > pgstat_progress_update_param(PROGRESS_ANALYZE_BLOCKS_DONE, > > > > ++blksdone); > > } > > If effective_io_concurrency == 0, this calls BlockSampler_Next(&prefetch_bs) > anyway, which is a waste of cycles. Good point, fixed. > If table_scan_analyze_next_block() returns false, we skip the > PrefetchBuffer() call. That seem wrong. Agreed, fixed. > Is there any potential harm from calling PrefetchBuffer() on a page that > table_scan_analyze_next_block() later deems as unsuitable for smapling and > returns false? That's theoretical at the moment, because > heapam_scan_analyze_next_block() always returns true. (The tableam ANALYZE > API refactor patch will make this moot, as it moves this logic into the > tableam's implementation, so the implementation can do whatever make sense > for the particular AM.) I can't see any potential harm and it seems pretty likely that if an heapam_scan_analyze_next_block()-equivilant were to decide that a block isn't appropriate to analyze it'd have to do so after reading that block anyway, making the prefetch still useful. Perhaps there'll be a case in the future where a given AM would know based on just the block number that it isn't useful to analyze, in which case it'd make sense to adjust the code to skip that block for both Prefetching and actually reading, but I don't think that would be too hard to do. Doesn't seem sensible to invent that in advance of actually having that case though- it's certainly not the case for heap AM today, at least, as you say. Unless there's anything else on this, I'll commit these sometime next week. Thanks again for the review! Stephen
From a65e4a9a7d666d7cfcbbc03c2cf50a2552888cab Mon Sep 17 00:00:00 2001 From: Stephen Frost <sfr...@snowman.net> Date: Fri, 5 Feb 2021 15:59:02 -0500 Subject: [PATCH 1/2] 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 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 5ef1c7ad3c..2da2f2e32a 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7411,9 +7411,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> diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index f3d2265fad..3a5e5a1ac2 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -440,6 +440,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); @@ -454,6 +456,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) @@ -674,6 +681,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 7295cf0215..0864cda80e 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(); } @@ -682,15 +693,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 */ -- 2.25.1 From 80c73fefad06df8ef241b7ab8c0e3a7468b83e4c Mon Sep 17 00:00:00 2001 From: Stephen Frost <sfr...@snowman.net> Date: Fri, 5 Feb 2021 16:05:07 -0500 Subject: [PATCH 2/2] Use pre-fetching for ANALYZE When we have posix_fadvise() available, we can improve the performance of an ANALYZE by quite a bit by using it to inform the kernel of the blocks that we're going to be asking for. Similar to bitmap index scans, the number of buffers pre-fetched is based off of the GUC effective_io_concurrency. Reviewed-By: Heikki Linnakangas Discussion: https://www.postgresql.org/message-id/VI1PR0701MB69603A433348EDCF783C6ECBF6EF0%40VI1PR0701MB6960.eurprd07.prod.outlook.com --- src/backend/commands/analyze.c | 73 +++++++++++++++++++++++++++++++++- 1 file changed, 71 insertions(+), 2 deletions(-) diff --git a/src/backend/commands/analyze.c b/src/backend/commands/analyze.c index 0864cda80e..4f31320c74 100644 --- a/src/backend/commands/analyze.c +++ b/src/backend/commands/analyze.c @@ -1117,6 +1117,7 @@ acquire_sample_rows(Relation onerel, int elevel, double liverows = 0; /* # live rows seen */ double deadrows = 0; /* # dead rows seen */ double rowstoskip = -1; /* -1 means not set yet */ + long randseed; /* Seed for block sampler(s) */ BlockNumber totalblocks; TransactionId OldestXmin; BlockSamplerData bs; @@ -1125,6 +1126,9 @@ acquire_sample_rows(Relation onerel, int elevel, TableScanDesc scan; BlockNumber nblocks; BlockNumber blksdone = 0; +#ifdef USE_PREFETCH + BlockSamplerData prefetch_bs; +#endif Assert(targrows > 0); @@ -1134,7 +1138,14 @@ acquire_sample_rows(Relation onerel, int elevel, OldestXmin = GetOldestNonRemovableTransactionId(onerel); /* Prepare for sampling block numbers */ - nblocks = BlockSampler_Init(&bs, totalblocks, targrows, random()); + randseed = random(); + nblocks = BlockSampler_Init(&bs, totalblocks, targrows, randseed); + +#ifdef USE_PREFETCH + /* Create another BlockSampler, using the same seed, for prefetching */ + if (effective_io_concurrency) + (void) BlockSampler_Init(&prefetch_bs, totalblocks, targrows, randseed); +#endif /* Report sampling block numbers */ pgstat_progress_update_param(PROGRESS_ANALYZE_BLOCKS_TOTAL, @@ -1146,14 +1157,72 @@ acquire_sample_rows(Relation onerel, int elevel, scan = table_beginscan_analyze(onerel); slot = table_slot_create(onerel, NULL); +#ifdef USE_PREFETCH + + /* + * If we are doing prefetching, then go ahead and tell the kernel about + * the first set of pages we are going to want. This also moves our + * iterator out ahead of the main one being used, where we will keep it so + * that we're always pre-fetching out effective_io_concurrency number of + * blocks ahead. + */ + if (effective_io_concurrency) + { + for (int i = 0; i < effective_io_concurrency; i++) + { + BlockNumber prefetch_block; + + if (!BlockSampler_HasMore(&prefetch_bs)) + break; + + prefetch_block = BlockSampler_Next(&prefetch_bs); + PrefetchBuffer(scan->rs_rd, MAIN_FORKNUM, prefetch_block); + } + } +#endif + /* Outer loop over blocks to sample */ while (BlockSampler_HasMore(&bs)) { + bool block_accepted; +#ifdef USE_PREFETCH + BlockNumber prefetch_targblock = InvalidBlockNumber; +#endif BlockNumber targblock = BlockSampler_Next(&bs); +#ifdef USE_PREFETCH + + /* + * Make sure that every time the main BlockSampler is moved forward + * that our prefetch BlockSampler also gets moved forward, so that we + * always stay out ahead. + */ + if (effective_io_concurrency && BlockSampler_HasMore(&prefetch_bs)) + prefetch_targblock = BlockSampler_Next(&prefetch_bs); +#endif + vacuum_delay_point(); - if (!table_scan_analyze_next_block(scan, targblock, vac_strategy)) + block_accepted = table_scan_analyze_next_block(scan, targblock, vac_strategy); + +#ifdef USE_PREFETCH + + /* + * When pre-fetching, after we get a block, tell the kernel about the + * next one we will want, if there's any left. + * + * We want to do this even if the table_scan_analyze_next_block() call + * above decides against analyzing the block it picked. + */ + if (effective_io_concurrency && prefetch_targblock != InvalidBlockNumber) + PrefetchBuffer(scan->rs_rd, MAIN_FORKNUM, prefetch_targblock); +#endif + + /* + * Don't analyze if table_scan_analyze_next_block() indicated this + * block is unsuitable for analyzing. + */ + if (!block_accepted) continue; while (table_scan_analyze_next_tuple(scan, OldestXmin, &liverows, &deadrows, slot)) -- 2.25.1
signature.asc
Description: PGP signature
