Greetings, * Tomas Vondra (tomas.von...@2ndquadrant.com) wrote: > On 11/4/20 5:02 PM, Stephen Frost wrote: > >* Tomas Vondra (tomas.von...@2ndquadrant.com) wrote: > >>>If you highlight "738754560" in the output it appears to duplicate the > >>>syscalls issued until it preads() - in case of "738754560" offset it was > >>>asked for 3 times. Also I wouldn't imagine in wildest dreams that > >>>posix_fadvise(POSIX_FADV_WILLNEED) is such a cheap syscall. > >> > >>IMHO that'a a bug in the patch, which always tries to prefetch all > >>"future" blocks, including those that were already prefetched. It > >>probably needs to do something like bitmap heap scan where we track > >>what was already prefetched and only issue the new blocks. > > > >Updated patch attached which: > > > >- Starts out by pre-fetching the first effective_io_concurrency number > > of blocks we are going to want, hopefully making it so the kernel will > > trust our fadvise's over its own read-ahead, right from the start. > >- Makes sure the prefetch iterator is pushed forward whenever the > > regular interator is moved forward. > >- After each page read, issues a prefetch, similar to BitmapHeapScan, to > > hopefully avoiding having the prefetching get in the way of the > > regular i/o. > >- Added some comments, ran pgindent, added a commit message. > > Nice, that was quick ;-)
:) > >I do think we should also include patch that Jakub wrote previously > >which adds information about the read rate of ANALYZE. > > +1 Attached is an updated patch which updates the documentation and integrates Jakub's initial work on improving the logging around auto-analyze (and I made the logging in auto-vacuum more-or-less match it). > >I'll look at integrating that into this patch and then look at a new > >patch to do something similar for VACUUM in a bit. > > +1 I spent some time looking into this but it's a bit complicated.. For some sound reasons, VACUUM will avoid skipping through a table when there's only a few pages that it could skip (not skipping allows us to move forward the relfrozenxid). That said, perhaps we could start doing prefetching once we've decided that we're skipping. We'd need to think about if we have to worry about the VM changing between the pre-fetching and the time when we're actually going to ask for the page.. I don't *think* that's an issue because only VACUUM would be changing the pages to be all-frozen or all-visible, and so if we see a page that isn't one of those then we're going to want to visit that page and that's not going to change, and we probably don't need to care about a page that used to be all-frozen and now isn't during this run- but if the prefetch went ahead and got page 10, and now page 8 is not-all-frozen and the actual scan is at page 5, then maybe it wants page 8 next and that isn't what we pre-fetched... Anyhow, all-in-all, definitely more complicated and probably best considered and discussed independently. > >If you're doing further benchmarking of ANALYZE though, this would > >probably be the better patch to use. Certainly improved performance > >here quite a bit with effective_io_concurrency set to 16. > > Yeah. I'd expect this to be heavily dependent on hardware. Sure, I agree with that too. Thanks, Stephen
From 59ace10ce767b08d3a175322bcabed2fc9010054 Mon Sep 17 00:00:00 2001 From: Stephen Frost <sfr...@snowman.net> Date: Wed, 4 Nov 2020 10:46:23 -0500 Subject: [PATCH] Use pre-fetching for ANALYZE and improve AV logging 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 buffer pre-fetched is based off of the GUC effective_io_concurrency. Also, arrange to provide similar details for auto-analyze that we have for auto-vaccum, about the read rate, dirty rate, and add I/O timing (when track_io_timing is enabled) to both. Stephen Frost and Jakub Wartak 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 | 157 +++++++++++++++++++++++++-- 3 files changed, 172 insertions(+), 11 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index f043433e31..345a0305c6 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7358,9 +7358,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 2174fccb1e..f0c16ae797 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 8af12b5c6b..9eb181762f 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,87 @@ 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 secs; + int usecs; + 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; + + TimestampDifference(starttime, endtime, &secs, &usecs); + + /* + * 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 ((secs > 0) || (usecs > 0)) + { + read_rate = (double) BLCKSZ * AnalyzePageMiss / (1024 * 1024) / + (secs + usecs / 1000000.0); + write_rate = (double) BLCKSZ * AnalyzePageDirty / (1024 * 1024) / + (secs + usecs / 1000000.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 */ @@ -1031,6 +1114,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; @@ -1039,6 +1123,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); @@ -1048,7 +1135,13 @@ 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 */ + (void) BlockSampler_Init(&prefetch_bs, totalblocks, targrows, randseed); +#endif /* Report sampling block numbers */ pgstat_progress_update_param(PROGRESS_ANALYZE_BLOCKS_TOTAL, @@ -1060,16 +1153,64 @@ 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)) { +#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)) { /* -- 2.25.1
signature.asc
Description: PGP signature
