Greetings, * Stephen Frost (sfr...@snowman.net) wrote: > * Tomas Vondra (tomas.von...@enterprisedb.com) wrote: > > Thanks. I'll do some testing/benchmarking once my machines are free, in > > a couple days perhaps. But as I said before, I don't expect this to > > behave very differently from other places that already do prefetching. > > Agreed, but would still be nice to see test results beyond just what > I've done.
Any chance you were able to run those tests..? > > FWIW I wonder if this should be tracked separately in the CF app, as > > it's very different from the original "add some logging" patch, which > > makes the CF entry rather misleading. > > I've gone ahead and updated the CF entry for this to hopefully make it > clearer for those interested in looking at it. I'll try to come back to > this in the next CF, ideally we'd at least get someone else to take a > look at the code beyond me. :) (Obviously, you looked at it some, but > wasn't really clear if you were alright with it or if you felt it needed > more review.) I've updated the patch to leverage Tom's introduction of TimestatmpDifferenceMilliseconds, which simplifies things a bit (and I don't think we need to worry about an analyze taking over 25 days...) and generally rebased this up to current HEAD. 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... ;) Thanks, Stephen
From 8ed687ee875943a0bc41daaf23f8d3c95f70c9b5 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 buffers 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 | 160 +++++++++++++++++++++++++-- 3 files changed, 175 insertions(+), 11 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 82864bbb24..8b069bc176 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -7409,9 +7409,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..ccef34af12 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 */ @@ -1031,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; @@ -1039,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); @@ -1048,7 +1138,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 +1156,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
