On Thu, Apr 02, 2020 at 06:40:51PM +0530, Amit Kapila wrote: > On Thu, Apr 2, 2020 at 6:18 PM Julien Rouhaud <rjuju...@gmail.com> wrote: > > > > =# select query, calls, wal_bytes, wal_records, wal_num_fpw from > > pg_stat_statements where query ilike '%create index%'; > > query | calls | wal_bytes | > > wal_records | wal_num_fpw > > ----------------------------------------------+-------+-----------+-------------+------------- > > create index t1_idx_parallel_0 ON t1(id) | 1 | 20389743 | > > 2762 | 2758 > > create index t1_idx_parallel_0_bis ON t1(id) | 1 | 20394391 | > > 2762 | 2758 > > create index t1_idx_parallel_0_ter ON t1(id) | 1 | 20395155 | > > 2762 | 2758 > > create index t1_idx_parallel_1 ON t1(id) | 1 | 20388335 | > > 2762 | 2758 > > create index t1_idx_parallel_2 ON t1(id) | 1 | 20389091 | > > 2762 | 2758 > > create index t1_idx_parallel_3 ON t1(id) | 1 | 20389847 | > > 2762 | 2758 > > create index t1_idx_parallel_4 ON t1(id) | 1 | 20390603 | > > 2762 | 2758 > > create index t1_idx_parallel_5 ON t1(id) | 1 | 20391359 | > > 2762 | 2758 > > create index t1_idx_parallel_6 ON t1(id) | 1 | 20392115 | > > 2762 | 2758 > > create index t1_idx_parallel_7 ON t1(id) | 1 | 20392871 | > > 2762 | 2758 > > create index t1_idx_parallel_8 ON t1(id) | 1 | 20393627 | > > 2762 | 2758 > > (11 rows) > > > > =# select relname, pg_relation_size(oid) from pg_class where relname like > > '%t1_id%'; > > relname | pg_relation_size > > -----------------------+------------------ > > t1_idx_parallel_0 | 22487040 > > t1_idx_parallel_0_bis | 22487040 > > t1_idx_parallel_0_ter | 22487040 > > t1_idx_parallel_2 | 22487040 > > t1_idx_parallel_1 | 22487040 > > t1_idx_parallel_4 | 22487040 > > t1_idx_parallel_3 | 22487040 > > t1_idx_parallel_5 | 22487040 > > t1_idx_parallel_6 | 22487040 > > t1_idx_parallel_7 | 22487040 > > t1_idx_parallel_8 | 22487040 > > (9 rows) > > > > > > So while the number of WAL records and full page images stay constant, we > > can > > see some small fluctuations in the total amount of generated WAL data, even > > for > > multiple execution of the sequential create index. I'm wondering if the > > fluctuations are due to some other internal details or if the WalUsage > > support > > is just completely broken (although I don't see any obvious issue ATM). > > > > I think we need to know the reason for this. Can you try with small > size indexes and see if the problem is reproducible? If it is, then it > will be easier to debug the same.
I did some quick testing using the attached shell script:
- one a 1k line base number of lines, scales 1 10 100 1000 (suffix _s)
- parallel workers from 0 to 8 (suffix _w)
- each index created twice (suffix _pa and _pb)
- with a vacuum;checkpoint;pg_switch_wal executed each time
I get the following results:
query | wal_bytes | wal_records |
wal_num_fpw
--------------------------------------------+-----------+-------------+-------------
CREATE INDEX t1_idx_s001_pa_w0 ON t1 (id) | 61871 | 22 |
18
CREATE INDEX t1_idx_s001_pa_w1 ON t1 (id) | 62394 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w2 ON t1 (id) | 63150 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w3 ON t1 (id) | 63906 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w4 ON t1 (id) | 64662 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w5 ON t1 (id) | 65418 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w6 ON t1 (id) | 65450 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w7 ON t1 (id) | 66206 | 21 |
18
CREATE INDEX t1_idx_s001_pa_w8 ON t1 (id) | 66962 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w0 ON t1 (id) | 67718 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w1 ON t1 (id) | 68474 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w2 ON t1 (id) | 68418 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w3 ON t1 (id) | 69174 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w4 ON t1 (id) | 69930 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w5 ON t1 (id) | 70686 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w6 ON t1 (id) | 71442 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w7 ON t1 (id) | 64922 | 21 |
18
CREATE INDEX t1_idx_s001_pb_w8 ON t1 (id) | 65682 | 21 |
18
CREATE INDEX t1_idx_s010_pa_w0 ON t1 (id) | 250460 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w1 ON t1 (id) | 251216 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w2 ON t1 (id) | 251972 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w3 ON t1 (id) | 252728 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w4 ON t1 (id) | 253484 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w5 ON t1 (id) | 254240 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w6 ON t1 (id) | 253552 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w7 ON t1 (id) | 254308 | 47 |
44
CREATE INDEX t1_idx_s010_pa_w8 ON t1 (id) | 255064 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w0 ON t1 (id) | 255820 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w1 ON t1 (id) | 256576 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w2 ON t1 (id) | 257332 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w3 ON t1 (id) | 258088 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w4 ON t1 (id) | 258844 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w5 ON t1 (id) | 259600 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w6 ON t1 (id) | 260356 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w7 ON t1 (id) | 260012 | 47 |
44
CREATE INDEX t1_idx_s010_pb_w8 ON t1 (id) | 260768 | 47 |
44
CREATE INDEX t1_idx_s1000_pa_w0 ON t1 (id) | 20400595 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w1 ON t1 (id) | 20401351 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w2 ON t1 (id) | 20402107 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w3 ON t1 (id) | 20402863 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w4 ON t1 (id) | 20403619 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w5 ON t1 (id) | 20404375 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w6 ON t1 (id) | 20403687 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w7 ON t1 (id) | 20404443 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pa_w8 ON t1 (id) | 20405199 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w0 ON t1 (id) | 20405955 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w1 ON t1 (id) | 20406711 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w2 ON t1 (id) | 20407467 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w3 ON t1 (id) | 20408223 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w4 ON t1 (id) | 20408979 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w5 ON t1 (id) | 20409735 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w6 ON t1 (id) | 20410491 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w7 ON t1 (id) | 20410147 | 2762 |
2759
CREATE INDEX t1_idx_s1000_pb_w8 ON t1 (id) | 20410903 | 2762 |
2759
CREATE INDEX t1_idx_s100_pa_w0 ON t1 (id) | 2082194 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w1 ON t1 (id) | 2082950 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w2 ON t1 (id) | 2083706 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w3 ON t1 (id) | 2084462 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w4 ON t1 (id) | 2085218 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w5 ON t1 (id) | 2085974 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w6 ON t1 (id) | 2085286 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w7 ON t1 (id) | 2086042 | 293 |
290
CREATE INDEX t1_idx_s100_pa_w8 ON t1 (id) | 2086798 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w0 ON t1 (id) | 2087554 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w1 ON t1 (id) | 2088310 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w2 ON t1 (id) | 2089066 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w3 ON t1 (id) | 2089822 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w4 ON t1 (id) | 2090578 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w5 ON t1 (id) | 2091334 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w6 ON t1 (id) | 2092090 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w7 ON t1 (id) | 2091746 | 293 |
290
CREATE INDEX t1_idx_s100_pb_w8 ON t1 (id) | 2092502 | 293 |
290
(72 rows)
The fluctuations exist for all scales, but doesn't seem to depend on the input
size.
Just to be sure I tried to measure the amount of WAL for various INSERT size
using roughly the same approach, and results are stable:
query | wal_bytes | wal_records
| wal_num_fpw
-----------------------------------------------------+-----------+-------------+-------------
INSERT INTO t_001_a SELECT generate_series($1, $2) | 59000 | 1000
| 0
INSERT INTO t_001_b SELECT generate_series($1, $2) | 59000 | 1000
| 0
INSERT INTO t_010_a SELECT generate_series($1, $2) | 590000 | 10000
| 0
INSERT INTO t_010_b SELECT generate_series($1, $2) | 590000 | 10000
| 0
INSERT INTO t_1000_a SELECT generate_series($1, $2) | 59000000 | 1000000
| 0
INSERT INTO t_1000_b SELECT generate_series($1, $2) | 59000000 | 1000000
| 0
INSERT INTO t_100_a SELECT generate_series($1, $2) | 5900000 | 100000
| 0
INSERT INTO t_100_b SELECT generate_series($1, $2) | 5900000 | 100000
| 0
(8 rows)
At this point I tend to think that this is somehow due to btbuild specific
behavior, or somewhere nearby.
> Few other minor comments
> ------------------------------------
> pg_stat_statements patch
> 1.
> +--
> +-- CRUD: INSERT SELECT UPDATE DELETE on test non-temp table to
> validate WAL generation metrics
> +--
>
> The word 'non-temp' in the above comment appears out of place. We
> don't need to specify it.
Fixed.
> 2.
> +-- SELECT usage data, check WAL usage is reported, wal_records equal
> rows count for INSERT/UPDATE/DELETE
> +SELECT query, calls, rows,
> +wal_bytes > 0 as wal_bytes_generated,
> +wal_records > 0 as wal_records_generated,
> +wal_records = rows as wal_records_as_rows
> +FROM pg_stat_statements ORDER BY query COLLATE "C";
>
> The comment doesn't seem to match what we are doing in the statement.
> I think we can simplify it to something like "check WAL is generated
> for above statements:
Done.
> 3.
> @@ -185,6 +185,9 @@ typedef struct Counters
> int64 local_blks_written; /* # of local disk blocks written */
> int64 temp_blks_read; /* # of temp blocks read */
> int64 temp_blks_written; /* # of temp blocks written */
> + uint64 wal_bytes; /* total amount of WAL bytes generated */
> + int64 wal_records; /* # of WAL records generated */
> + int64 wal_num_fpw; /* # of WAL full page image generated */
> double blk_read_time; /* time spent reading, in msec */
> double blk_write_time; /* time spent writing, in msec */
> double usage; /* usage factor */
>
> It is better to keep wal_bytes should be after wal_num_fpw as it is in
> the main patch. Also, consider changing at other places in this
> patch. I think we should add these new fields after blk_write_time or
> at the end after usage.
Done.
> 4.
> /* # of WAL full page image generated */
> Can we change it to "/* # of WAL full page image records generated */"?
>
> If you agree, then a similar comment exists in
> v11-0001-Add-infrastructure-to-track-WAL-usage, consider changing that
> as well.
Agreed, and fixed in both place.
> v11-0002-Add-option-to-report-WAL-usage-in-EXPLAIN-and-au
> 5.
> Specifically, include the
> + number of records, full page images and bytes generated.
>
> How about making the above slightly clear? "Specifically, include the
> number of records, number of full page image records and amount of WAL
> bytes generated.
Thanks, that's clearer. Done
>From 1ba0a76f3e071c239dd65fe06517ead816922957 Mon Sep 17 00:00:00 2001 From: Kirill Bychik <kirill.byc...@gmail.com> Date: Tue, 17 Mar 2020 14:41:50 +0100 Subject: [PATCH v13 1/4] Add infrastructure to track WAL usage. Author: Kirill Bychik, Julien Rouhaud Reviewed-by: Fuji Masao Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4zlxws_cza3...@mail.gmail.com --- src/backend/access/heap/vacuumlazy.c | 37 ++++++++++++----- src/backend/access/nbtree/nbtsort.c | 40 +++++++++++++++++++ src/backend/access/transam/xlog.c | 12 +++++- src/backend/access/transam/xloginsert.c | 13 ++++-- src/backend/executor/execParallel.c | 38 +++++++++++++----- src/backend/executor/instrument.c | 53 ++++++++++++++++++++++--- src/include/access/xlog.h | 3 +- src/include/executor/execParallel.h | 1 + src/include/executor/instrument.h | 18 ++++++++- src/tools/pgindent/typedefs.list | 1 + 10 files changed, 183 insertions(+), 33 deletions(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index 9f9596c718..cc7e8521a5 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -139,6 +139,7 @@ #define PARALLEL_VACUUM_KEY_DEAD_TUPLES 2 #define PARALLEL_VACUUM_KEY_QUERY_TEXT 3 #define PARALLEL_VACUUM_KEY_BUFFER_USAGE 4 +#define PARALLEL_VACUUM_KEY_WAL_USAGE 5 /* * Macro to check if we are in a parallel vacuum. If true, we are in the @@ -275,6 +276,9 @@ typedef struct LVParallelState /* Points to buffer usage area in DSM */ BufferUsage *buffer_usage; + /* Points to WAL usage area in DSM */ + WalUsage *wal_usage; + /* * The number of indexes that support parallel index bulk-deletion and * parallel index cleanup respectively. @@ -2143,8 +2147,8 @@ lazy_parallel_vacuum_indexes(Relation *Irel, IndexBulkDeleteResult **stats, vacrelstats->dead_tuples, nindexes, vacrelstats); /* - * Next, accumulate buffer usage. (This must wait for the workers to - * finish, or we might get incomplete data.) + * Next, accumulate buffer and WAL usage. (This must wait for the workers + * to finish, or we might get incomplete data.) */ if (nworkers > 0) { @@ -2154,7 +2158,7 @@ lazy_parallel_vacuum_indexes(Relation *Irel, IndexBulkDeleteResult **stats, WaitForParallelWorkersToFinish(lps->pcxt); for (i = 0; i < lps->pcxt->nworkers_launched; i++) - InstrAccumParallelQuery(&lps->buffer_usage[i]); + InstrAccumParallelQuery(&lps->buffer_usage[i], &lps->wal_usage[i]); } /* @@ -3171,6 +3175,7 @@ begin_parallel_vacuum(Oid relid, Relation *Irel, LVRelStats *vacrelstats, LVShared *shared; LVDeadTuples *dead_tuples; BufferUsage *buffer_usage; + WalUsage *wal_usage; bool *can_parallel_vacuum; long maxtuples; char *sharedquery; @@ -3255,15 +3260,19 @@ begin_parallel_vacuum(Oid relid, Relation *Irel, LVRelStats *vacrelstats, shm_toc_estimate_keys(&pcxt->estimator, 1); /* - * Estimate space for BufferUsage -- PARALLEL_VACUUM_KEY_BUFFER_USAGE. + * Estimate space for BufferUsage and WalUsage -- + * PARALLEL_VACUUM_KEY_BUFFER_USAGE and PARALLEL_VACUUM_KEY_WAL_USAGE. * * If there are no extensions loaded that care, we could skip this. We - * have no way of knowing whether anyone's looking at pgBufferUsage, so do - * it unconditionally. + * have no way of knowing whether anyone's looking at pgBufferUsage or + * pgWalUsage, so do it unconditionally. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(sizeof(BufferUsage), pcxt->nworkers)); shm_toc_estimate_keys(&pcxt->estimator, 1); + shm_toc_estimate_chunk(&pcxt->estimator, + mul_size(sizeof(WalUsage), pcxt->nworkers)); + shm_toc_estimate_keys(&pcxt->estimator, 1); /* Finally, estimate PARALLEL_VACUUM_KEY_QUERY_TEXT space */ querylen = strlen(debug_query_string); @@ -3299,11 +3308,18 @@ begin_parallel_vacuum(Oid relid, Relation *Irel, LVRelStats *vacrelstats, shm_toc_insert(pcxt->toc, PARALLEL_VACUUM_KEY_DEAD_TUPLES, dead_tuples); vacrelstats->dead_tuples = dead_tuples; - /* Allocate space for each worker's BufferUsage; no need to initialize */ + /* + * Allocate space for each worker's BufferUsage and WalUsage; no need to + * initialize + */ buffer_usage = shm_toc_allocate(pcxt->toc, mul_size(sizeof(BufferUsage), pcxt->nworkers)); shm_toc_insert(pcxt->toc, PARALLEL_VACUUM_KEY_BUFFER_USAGE, buffer_usage); lps->buffer_usage = buffer_usage; + wal_usage = shm_toc_allocate(pcxt->toc, + mul_size(sizeof(WalUsage), pcxt->nworkers)); + shm_toc_insert(pcxt->toc, PARALLEL_VACUUM_KEY_WAL_USAGE, wal_usage); + lps->wal_usage = wal_usage; /* Store query string for workers */ sharedquery = (char *) shm_toc_allocate(pcxt->toc, querylen + 1); @@ -3435,6 +3451,7 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc) LVShared *lvshared; LVDeadTuples *dead_tuples; BufferUsage *buffer_usage; + WalUsage *wal_usage; int nindexes; char *sharedquery; IndexBulkDeleteResult **stats; @@ -3511,9 +3528,11 @@ parallel_vacuum_main(dsm_segment *seg, shm_toc *toc) parallel_vacuum_index(indrels, stats, lvshared, dead_tuples, nindexes, &vacrelstats); - /* Report buffer usage during parallel execution */ + /* Report buffer/WAL usage during parallel execution */ buffer_usage = shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_BUFFER_USAGE, false); - InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber]); + wal_usage = shm_toc_lookup(toc, PARALLEL_VACUUM_KEY_WAL_USAGE, false); + InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber], + &wal_usage[ParallelWorkerNumber]); /* Pop the error context stack */ error_context_stack = errcallback.previous; diff --git a/src/backend/access/nbtree/nbtsort.c b/src/backend/access/nbtree/nbtsort.c index 3924945664..3f4cb7d39e 100644 --- a/src/backend/access/nbtree/nbtsort.c +++ b/src/backend/access/nbtree/nbtsort.c @@ -67,6 +67,7 @@ #include "access/xloginsert.h" #include "catalog/index.h" #include "commands/progress.h" +#include "executor/instrument.h" #include "miscadmin.h" #include "pgstat.h" #include "storage/smgr.h" @@ -81,6 +82,7 @@ #define PARALLEL_KEY_TUPLESORT UINT64CONST(0xA000000000000002) #define PARALLEL_KEY_TUPLESORT_SPOOL2 UINT64CONST(0xA000000000000003) #define PARALLEL_KEY_QUERY_TEXT UINT64CONST(0xA000000000000004) +#define PARALLEL_KEY_WAL_USAGE UINT64CONST(0xA000000000000005) /* * DISABLE_LEADER_PARTICIPATION disables the leader's participation in @@ -203,6 +205,7 @@ typedef struct BTLeader Sharedsort *sharedsort; Sharedsort *sharedsort2; Snapshot snapshot; + WalUsage *walusage; } BTLeader; /* @@ -1476,6 +1479,7 @@ _bt_begin_parallel(BTBuildState *buildstate, bool isconcurrent, int request) Sharedsort *sharedsort2; BTSpool *btspool = buildstate->spool; BTLeader *btleader = (BTLeader *) palloc0(sizeof(BTLeader)); + WalUsage *walusage; bool leaderparticipates = true; char *sharedquery; int querylen; @@ -1528,6 +1532,18 @@ _bt_begin_parallel(BTBuildState *buildstate, bool isconcurrent, int request) shm_toc_estimate_keys(&pcxt->estimator, 3); } + /* + * Estimate space for WalUsage -- PARALLEL_KEY_WAL_USAGE + * + * WalUsage during execution of maintenance command can be used by an + * extension that reports the WAL usage, such as pg_stat_statements. + * We have no way of knowing whether anyone's looking at pgWalUsage, + * so do it unconditionally. + */ + shm_toc_estimate_chunk(&pcxt->estimator, + mul_size(sizeof(WalUsage), pcxt->nworkers)); + shm_toc_estimate_keys(&pcxt->estimator, 1); + /* Finally, estimate PARALLEL_KEY_QUERY_TEXT space */ querylen = strlen(debug_query_string); shm_toc_estimate_chunk(&pcxt->estimator, querylen + 1); @@ -1599,6 +1615,11 @@ _bt_begin_parallel(BTBuildState *buildstate, bool isconcurrent, int request) memcpy(sharedquery, debug_query_string, querylen + 1); shm_toc_insert(pcxt->toc, PARALLEL_KEY_QUERY_TEXT, sharedquery); + /* Allocate space for each worker's WalUsage; no need to initialize */ + walusage = shm_toc_allocate(pcxt->toc, + mul_size(sizeof(WalUsage), pcxt->nworkers)); + shm_toc_insert(pcxt->toc, PARALLEL_KEY_WAL_USAGE, walusage); + /* Launch workers, saving status for leader/caller */ LaunchParallelWorkers(pcxt); btleader->pcxt = pcxt; @@ -1609,6 +1630,7 @@ _bt_begin_parallel(BTBuildState *buildstate, bool isconcurrent, int request) btleader->sharedsort = sharedsort; btleader->sharedsort2 = sharedsort2; btleader->snapshot = snapshot; + btleader->walusage = walusage; /* If no workers were successfully launched, back out (do serial build) */ if (pcxt->nworkers_launched == 0) @@ -1637,8 +1659,18 @@ _bt_begin_parallel(BTBuildState *buildstate, bool isconcurrent, int request) static void _bt_end_parallel(BTLeader *btleader) { + int i; + /* Shutdown worker processes */ WaitForParallelWorkersToFinish(btleader->pcxt); + + /* + * Next, accumulate WAL usage. (This must wait for the workers to + * finish, or we might get incomplete data.) + */ + for (i = 0; i < btleader->pcxt->nworkers_launched; i++) + InstrAccumParallelQuery(NULL, &btleader->walusage[i]); + /* Free last reference to MVCC snapshot, if one was used */ if (IsMVCCSnapshot(btleader->snapshot)) UnregisterSnapshot(btleader->snapshot); @@ -1769,6 +1801,7 @@ _bt_parallel_build_main(dsm_segment *seg, shm_toc *toc) Relation indexRel; LOCKMODE heapLockmode; LOCKMODE indexLockmode; + WalUsage *walusage; int sortmem; #ifdef BTREE_BUILD_STATS @@ -1830,11 +1863,18 @@ _bt_parallel_build_main(dsm_segment *seg, shm_toc *toc) tuplesort_attach_shared(sharedsort2, seg); } + /* Prepare to track buffer usage during parallel execution */ + InstrStartParallelQuery(); + /* Perform sorting of spool, and possibly a spool2 */ sortmem = maintenance_work_mem / btshared->scantuplesortstates; _bt_parallel_scan_and_sort(btspool, btspool2, btshared, sharedsort, sharedsort2, sortmem, false); + /* Report WAL usage during parallel execution */ + walusage = shm_toc_lookup(toc, PARALLEL_KEY_WAL_USAGE, false); + InstrEndParallelQuery(NULL, &walusage[ParallelWorkerNumber]); + #ifdef BTREE_BUILD_STATS if (log_btree_build_stats) { diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 977d448f50..50b78f3143 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -43,6 +43,7 @@ #include "commands/progress.h" #include "commands/tablespace.h" #include "common/controldata_utils.h" +#include "executor/instrument.h" #include "miscadmin.h" #include "pg_trace.h" #include "pgstat.h" @@ -996,7 +997,8 @@ static void WALInsertLockUpdateInsertingAt(XLogRecPtr insertingAt); XLogRecPtr XLogInsertRecord(XLogRecData *rdata, XLogRecPtr fpw_lsn, - uint8 flags) + uint8 flags, + int num_fpw) { XLogCtlInsert *Insert = &XLogCtl->Insert; pg_crc32c rdata_crc; @@ -1252,6 +1254,14 @@ XLogInsertRecord(XLogRecData *rdata, ProcLastRecPtr = StartPos; XactLastRecEnd = EndPos; + /* Report WAL traffic to the instrumentation. */ + if (inserted) + { + pgWalUsage.wal_bytes += rechdr->xl_tot_len; + pgWalUsage.wal_records++; + pgWalUsage.wal_num_fpw += num_fpw; + } + return EndPos; } diff --git a/src/backend/access/transam/xloginsert.c b/src/backend/access/transam/xloginsert.c index a618dec776..5e032e7042 100644 --- a/src/backend/access/transam/xloginsert.c +++ b/src/backend/access/transam/xloginsert.c @@ -25,6 +25,7 @@ #include "access/xloginsert.h" #include "catalog/pg_control.h" #include "common/pg_lzcompress.h" +#include "executor/instrument.h" #include "miscadmin.h" #include "pg_trace.h" #include "replication/origin.h" @@ -108,7 +109,7 @@ static MemoryContext xloginsert_cxt; static XLogRecData *XLogRecordAssemble(RmgrId rmid, uint8 info, XLogRecPtr RedoRecPtr, bool doPageWrites, - XLogRecPtr *fpw_lsn); + XLogRecPtr *fpw_lsn, int *num_fpw); static bool XLogCompressBackupBlock(char *page, uint16 hole_offset, uint16 hole_length, char *dest, uint16 *dlen); @@ -448,6 +449,7 @@ XLogInsert(RmgrId rmid, uint8 info) bool doPageWrites; XLogRecPtr fpw_lsn; XLogRecData *rdt; + int num_fpw = 0; /* * Get values needed to decide whether to do full-page writes. Since @@ -457,9 +459,9 @@ XLogInsert(RmgrId rmid, uint8 info) GetFullPageWriteInfo(&RedoRecPtr, &doPageWrites); rdt = XLogRecordAssemble(rmid, info, RedoRecPtr, doPageWrites, - &fpw_lsn); + &fpw_lsn, &num_fpw); - EndPos = XLogInsertRecord(rdt, fpw_lsn, curinsert_flags); + EndPos = XLogInsertRecord(rdt, fpw_lsn, curinsert_flags, num_fpw); } while (EndPos == InvalidXLogRecPtr); XLogResetInsertion(); @@ -482,7 +484,7 @@ XLogInsert(RmgrId rmid, uint8 info) static XLogRecData * XLogRecordAssemble(RmgrId rmid, uint8 info, XLogRecPtr RedoRecPtr, bool doPageWrites, - XLogRecPtr *fpw_lsn) + XLogRecPtr *fpw_lsn, int *num_fpw) { XLogRecData *rdt; uint32 total_len = 0; @@ -635,6 +637,9 @@ XLogRecordAssemble(RmgrId rmid, uint8 info, */ bkpb.fork_flags |= BKPBLOCK_HAS_IMAGE; + /* Report a full page image constructed for the WAL record */ + *num_fpw += 1; + /* * Construct XLogRecData entries for the page content. */ diff --git a/src/backend/executor/execParallel.c b/src/backend/executor/execParallel.c index a753d6efa0..7d9ca66fc8 100644 --- a/src/backend/executor/execParallel.c +++ b/src/backend/executor/execParallel.c @@ -12,7 +12,7 @@ * workers and ensuring that their state generally matches that of the * leader; see src/backend/access/transam/README.parallel for details. * However, we must save and restore relevant executor state, such as - * any ParamListInfo associated with the query, buffer usage info, and + * any ParamListInfo associated with the query, buffer/WAL usage info, and * the actual plan to be passed down to the worker. * * IDENTIFICATION @@ -62,6 +62,7 @@ #define PARALLEL_KEY_DSA UINT64CONST(0xE000000000000007) #define PARALLEL_KEY_QUERY_TEXT UINT64CONST(0xE000000000000008) #define PARALLEL_KEY_JIT_INSTRUMENTATION UINT64CONST(0xE000000000000009) +#define PARALLEL_KEY_WAL_USAGE UINT64CONST(0xE00000000000000A) #define PARALLEL_TUPLE_QUEUE_SIZE 65536 @@ -573,6 +574,7 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, char *pstmt_space; char *paramlistinfo_space; BufferUsage *bufusage_space; + WalUsage *walusage_space; SharedExecutorInstrumentation *instrumentation = NULL; SharedJitInstrumentation *jit_instrumentation = NULL; int pstmt_len; @@ -646,6 +648,13 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, mul_size(sizeof(BufferUsage), pcxt->nworkers)); shm_toc_estimate_keys(&pcxt->estimator, 1); + /* + * Same thing for WalUsage. + */ + shm_toc_estimate_chunk(&pcxt->estimator, + mul_size(sizeof(WalUsage), pcxt->nworkers)); + shm_toc_estimate_keys(&pcxt->estimator, 1); + /* Estimate space for tuple queues. */ shm_toc_estimate_chunk(&pcxt->estimator, mul_size(PARALLEL_TUPLE_QUEUE_SIZE, pcxt->nworkers)); @@ -728,6 +737,12 @@ ExecInitParallelPlan(PlanState *planstate, EState *estate, shm_toc_insert(pcxt->toc, PARALLEL_KEY_BUFFER_USAGE, bufusage_space); pei->buffer_usage = bufusage_space; + /* Same for WalUsage. */ + walusage_space = shm_toc_allocate(pcxt->toc, + mul_size(sizeof(WalUsage), pcxt->nworkers)); + shm_toc_insert(pcxt->toc, PARALLEL_KEY_WAL_USAGE, walusage_space); + pei->wal_usage = walusage_space; + /* Set up the tuple queues that the workers will write into. */ pei->tqueue = ExecParallelSetupTupleQueues(pcxt, false); @@ -1069,7 +1084,7 @@ ExecParallelRetrieveJitInstrumentation(PlanState *planstate, /* * Finish parallel execution. We wait for parallel workers to finish, and - * accumulate their buffer usage. + * accumulate their buffer/WAL usage. */ void ExecParallelFinish(ParallelExecutorInfo *pei) @@ -1109,11 +1124,11 @@ ExecParallelFinish(ParallelExecutorInfo *pei) WaitForParallelWorkersToFinish(pei->pcxt); /* - * Next, accumulate buffer usage. (This must wait for the workers to - * finish, or we might get incomplete data.) + * Next, accumulate buffer/WAL usage. (This must wait for the workers + * to finish, or we might get incomplete data.) */ for (i = 0; i < nworkers; i++) - InstrAccumParallelQuery(&pei->buffer_usage[i]); + InstrAccumParallelQuery(&pei->buffer_usage[i], &pei->wal_usage[i]); pei->finished = true; } @@ -1333,6 +1348,7 @@ ParallelQueryMain(dsm_segment *seg, shm_toc *toc) { FixedParallelExecutorState *fpes; BufferUsage *buffer_usage; + WalUsage *wal_usage; DestReceiver *receiver; QueryDesc *queryDesc; SharedExecutorInstrumentation *instrumentation; @@ -1386,11 +1402,11 @@ ParallelQueryMain(dsm_segment *seg, shm_toc *toc) ExecSetTupleBound(fpes->tuples_needed, queryDesc->planstate); /* - * Prepare to track buffer usage during query execution. + * Prepare to track buffer/WAL usage during query execution. * * We do this after starting up the executor to match what happens in the - * leader, which also doesn't count buffer accesses that occur during - * executor startup. + * leader, which also doesn't count buffer accesses and WAL activity that + * occur during executor startup. */ InstrStartParallelQuery(); @@ -1406,9 +1422,11 @@ ParallelQueryMain(dsm_segment *seg, shm_toc *toc) /* Shut down the executor */ ExecutorFinish(queryDesc); - /* Report buffer usage during parallel execution. */ + /* Report buffer/WAL usage during parallel execution. */ buffer_usage = shm_toc_lookup(toc, PARALLEL_KEY_BUFFER_USAGE, false); - InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber]); + wal_usage = shm_toc_lookup (toc, PARALLEL_KEY_WAL_USAGE, false); + InstrEndParallelQuery(&buffer_usage[ParallelWorkerNumber], + &wal_usage[ParallelWorkerNumber]); /* Report instrumentation data if any instrumentation options are set. */ if (instrumentation != NULL) diff --git a/src/backend/executor/instrument.c b/src/backend/executor/instrument.c index 042e10f96b..a77571a895 100644 --- a/src/backend/executor/instrument.c +++ b/src/backend/executor/instrument.c @@ -19,8 +19,11 @@ BufferUsage pgBufferUsage; static BufferUsage save_pgBufferUsage; +WalUsage pgWalUsage; +static WalUsage save_pgWalUsage; static void BufferUsageAdd(BufferUsage *dst, const BufferUsage *add); +static void WalUsageAdd(WalUsage *dst, WalUsage *add); /* Allocate new instrumentation structure(s) */ @@ -31,15 +34,17 @@ InstrAlloc(int n, int instrument_options) /* initialize all fields to zeroes, then modify as needed */ instr = palloc0(n * sizeof(Instrumentation)); - if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER)) + if (instrument_options & (INSTRUMENT_BUFFERS | INSTRUMENT_TIMER | INSTRUMENT_WAL)) { bool need_buffers = (instrument_options & INSTRUMENT_BUFFERS) != 0; + bool need_wal = (instrument_options & INSTRUMENT_WAL) != 0; bool need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; int i; for (i = 0; i < n; i++) { instr[i].need_bufusage = need_buffers; + instr[i].need_walusage = need_wal; instr[i].need_timer = need_timer; } } @@ -53,6 +58,7 @@ InstrInit(Instrumentation *instr, int instrument_options) { memset(instr, 0, sizeof(Instrumentation)); instr->need_bufusage = (instrument_options & INSTRUMENT_BUFFERS) != 0; + instr->need_walusage = (instrument_options & INSTRUMENT_WAL) != 0; instr->need_timer = (instrument_options & INSTRUMENT_TIMER) != 0; } @@ -67,6 +73,9 @@ InstrStartNode(Instrumentation *instr) /* save buffer usage totals at node entry, if needed */ if (instr->need_bufusage) instr->bufusage_start = pgBufferUsage; + + if (instr->need_walusage) + instr->walusage_start = pgWalUsage; } /* Exit from a plan node */ @@ -95,6 +104,10 @@ InstrStopNode(Instrumentation *instr, double nTuples) BufferUsageAccumDiff(&instr->bufusage, &pgBufferUsage, &instr->bufusage_start); + if (instr->need_walusage) + WalUsageAccumDiff(&instr->walusage, + &pgWalUsage, &instr->walusage_start); + /* Is this the first tuple of this cycle? */ if (!instr->running) { @@ -158,6 +171,9 @@ InstrAggNode(Instrumentation *dst, Instrumentation *add) /* Add delta of buffer usage since entry to node's totals */ if (dst->need_bufusage) BufferUsageAdd(&dst->bufusage, &add->bufusage); + + if (dst->need_walusage) + WalUsageAdd(&dst->walusage, &add->walusage); } /* note current values during parallel executor startup */ @@ -165,21 +181,29 @@ void InstrStartParallelQuery(void) { save_pgBufferUsage = pgBufferUsage; + save_pgWalUsage = pgWalUsage; } /* report usage after parallel executor shutdown */ void -InstrEndParallelQuery(BufferUsage *result) +InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage) { - memset(result, 0, sizeof(BufferUsage)); - BufferUsageAccumDiff(result, &pgBufferUsage, &save_pgBufferUsage); + if (bufusage) + { + memset(bufusage, 0, sizeof(BufferUsage)); + BufferUsageAccumDiff(bufusage, &pgBufferUsage, &save_pgBufferUsage); + } + memset(walusage, 0, sizeof(WalUsage)); + WalUsageAccumDiff(walusage, &pgWalUsage, &save_pgWalUsage); } /* accumulate work done by workers in leader's stats */ void -InstrAccumParallelQuery(BufferUsage *result) +InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage) { - BufferUsageAdd(&pgBufferUsage, result); + if (bufusage) + BufferUsageAdd(&pgBufferUsage, bufusage); + WalUsageAdd(&pgWalUsage, walusage); } /* dst += add */ @@ -221,3 +245,20 @@ BufferUsageAccumDiff(BufferUsage *dst, INSTR_TIME_ACCUM_DIFF(dst->blk_write_time, add->blk_write_time, sub->blk_write_time); } + +/* helper functions for WAL usage accumulation */ +static void +WalUsageAdd(WalUsage *dst, WalUsage *add) +{ + dst->wal_bytes += add->wal_bytes; + dst->wal_records += add->wal_records; + dst->wal_num_fpw += add->wal_num_fpw; +} + +void +WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, const WalUsage *sub) +{ + dst->wal_bytes += add->wal_bytes - sub->wal_bytes; + dst->wal_records += add->wal_records - sub->wal_records; + dst->wal_num_fpw += add->wal_num_fpw - sub->wal_num_fpw; +} diff --git a/src/include/access/xlog.h b/src/include/access/xlog.h index 9ec7b31cce..b91e724b2d 100644 --- a/src/include/access/xlog.h +++ b/src/include/access/xlog.h @@ -259,7 +259,8 @@ struct XLogRecData; extern XLogRecPtr XLogInsertRecord(struct XLogRecData *rdata, XLogRecPtr fpw_lsn, - uint8 flags); + uint8 flags, + int num_fpw); extern void XLogFlush(XLogRecPtr RecPtr); extern bool XLogBackgroundFlush(void); extern bool XLogNeedsFlush(XLogRecPtr RecPtr); diff --git a/src/include/executor/execParallel.h b/src/include/executor/execParallel.h index 17d07cf020..1cc5b524fd 100644 --- a/src/include/executor/execParallel.h +++ b/src/include/executor/execParallel.h @@ -26,6 +26,7 @@ typedef struct ParallelExecutorInfo PlanState *planstate; /* plan subtree we're running in parallel */ ParallelContext *pcxt; /* parallel context we're using */ BufferUsage *buffer_usage; /* points to bufusage area in DSM */ + WalUsage *wal_usage; /* walusage area in DSM */ SharedExecutorInstrumentation *instrumentation; /* optional */ struct SharedJitInstrumentation *jit_instrumentation; /* optional */ dsa_area *area; /* points to DSA area in DSM */ diff --git a/src/include/executor/instrument.h b/src/include/executor/instrument.h index 3825a5ac1f..f2bf37ae82 100644 --- a/src/include/executor/instrument.h +++ b/src/include/executor/instrument.h @@ -32,12 +32,20 @@ typedef struct BufferUsage instr_time blk_write_time; /* time spent writing */ } BufferUsage; +typedef struct WalUsage +{ + long wal_records; /* # of WAL records produced */ + long wal_num_fpw; /* # of WAL full page image records produced */ + uint64 wal_bytes; /* size of WAL records produced */ +} WalUsage; + /* Flag bits included in InstrAlloc's instrument_options bitmask */ typedef enum InstrumentOption { INSTRUMENT_TIMER = 1 << 0, /* needs timer (and row counts) */ INSTRUMENT_BUFFERS = 1 << 1, /* needs buffer usage */ INSTRUMENT_ROWS = 1 << 2, /* needs row count */ + INSTRUMENT_WAL = 1 << 3, /* needs WAL usage */ INSTRUMENT_ALL = PG_INT32_MAX } InstrumentOption; @@ -46,6 +54,7 @@ typedef struct Instrumentation /* Parameters set at node creation: */ bool need_timer; /* true if we need timer data */ bool need_bufusage; /* true if we need buffer usage data */ + bool need_walusage; /* true if we need WAL usage data */ /* Info about current plan cycle: */ bool running; /* true if we've completed first tuple */ instr_time starttime; /* start time of current iteration of node */ @@ -53,6 +62,7 @@ typedef struct Instrumentation double firsttuple; /* time for first tuple of this cycle */ double tuplecount; /* # of tuples emitted so far this cycle */ BufferUsage bufusage_start; /* buffer usage at start */ + WalUsage walusage_start; /* WAL usage at start */ /* Accumulated statistics across all completed cycles: */ double startup; /* total startup time (in seconds) */ double total; /* total time (in seconds) */ @@ -62,6 +72,7 @@ typedef struct Instrumentation double nfiltered1; /* # of tuples removed by scanqual or joinqual */ double nfiltered2; /* # of tuples removed by "other" quals */ BufferUsage bufusage; /* total buffer usage */ + WalUsage walusage; /* total WAL usage */ } Instrumentation; typedef struct WorkerInstrumentation @@ -71,6 +82,7 @@ typedef struct WorkerInstrumentation } WorkerInstrumentation; extern PGDLLIMPORT BufferUsage pgBufferUsage; +extern PGDLLIMPORT WalUsage pgWalUsage; extern Instrumentation *InstrAlloc(int n, int instrument_options); extern void InstrInit(Instrumentation *instr, int instrument_options); @@ -79,9 +91,11 @@ extern void InstrStopNode(Instrumentation *instr, double nTuples); extern void InstrEndLoop(Instrumentation *instr); extern void InstrAggNode(Instrumentation *dst, Instrumentation *add); extern void InstrStartParallelQuery(void); -extern void InstrEndParallelQuery(BufferUsage *result); -extern void InstrAccumParallelQuery(BufferUsage *result); +extern void InstrEndParallelQuery(BufferUsage *bufusage, WalUsage *walusage); +extern void InstrAccumParallelQuery(BufferUsage *bufusage, WalUsage *walusage); extern void BufferUsageAccumDiff(BufferUsage *dst, const BufferUsage *add, const BufferUsage *sub); +extern void WalUsageAccumDiff(WalUsage *dst, const WalUsage *add, + const WalUsage *sub); #endif /* INSTRUMENT_H */ diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list index 939de985d3..34623523a7 100644 --- a/src/tools/pgindent/typedefs.list +++ b/src/tools/pgindent/typedefs.list @@ -2643,6 +2643,7 @@ WalSndCtlData WalSndSendDataCallback WalSndState WalTimeSample +WalUsage WalWriteMethod Walfile WindowAgg -- 2.20.1
>From e0cb25e07c59b4e3947ed781e8794bdd59a30903 Mon Sep 17 00:00:00 2001 From: Julien Rouhaud <julien.rouh...@free.fr> Date: Sun, 29 Mar 2020 12:38:14 +0200 Subject: [PATCH v13 2/4] Add option to report WAL usage in EXPLAIN and auto_explain. Author: Julien Rouhaud Reviewed-by: Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4zlxws_cza3...@mail.gmail.com --- contrib/auto_explain/auto_explain.c | 15 ++++++ doc/src/sgml/auto-explain.sgml | 20 ++++++++ doc/src/sgml/ref/explain.sgml | 14 ++++++ src/backend/commands/explain.c | 74 +++++++++++++++++++++++++++-- src/bin/psql/tab-complete.c | 4 +- src/include/commands/explain.h | 3 ++ 6 files changed, 124 insertions(+), 6 deletions(-) diff --git a/contrib/auto_explain/auto_explain.c b/contrib/auto_explain/auto_explain.c index f69dde876c..56c549d84c 100644 --- a/contrib/auto_explain/auto_explain.c +++ b/contrib/auto_explain/auto_explain.c @@ -27,6 +27,7 @@ static int auto_explain_log_min_duration = -1; /* msec or -1 */ static bool auto_explain_log_analyze = false; static bool auto_explain_log_verbose = false; static bool auto_explain_log_buffers = false; +static bool auto_explain_log_wal = false; static bool auto_explain_log_triggers = false; static bool auto_explain_log_timing = true; static bool auto_explain_log_settings = false; @@ -148,6 +149,17 @@ _PG_init(void) NULL, NULL); + DefineCustomBoolVariable("auto_explain.log_wal", + "Log WAL usage.", + NULL, + &auto_explain_log_wal, + false, + PGC_SUSET, + 0, + NULL, + NULL, + NULL); + DefineCustomBoolVariable("auto_explain.log_triggers", "Include trigger statistics in plans.", "This has no effect unless log_analyze is also set.", @@ -280,6 +292,8 @@ explain_ExecutorStart(QueryDesc *queryDesc, int eflags) queryDesc->instrument_options |= INSTRUMENT_ROWS; if (auto_explain_log_buffers) queryDesc->instrument_options |= INSTRUMENT_BUFFERS; + if (auto_explain_log_wal) + queryDesc->instrument_options |= INSTRUMENT_WAL; } } @@ -374,6 +388,7 @@ explain_ExecutorEnd(QueryDesc *queryDesc) es->analyze = (queryDesc->instrument_options && auto_explain_log_analyze); es->verbose = auto_explain_log_verbose; es->buffers = (es->analyze && auto_explain_log_buffers); + es->wal = (es->analyze && auto_explain_log_wal); es->timing = (es->analyze && auto_explain_log_timing); es->summary = es->analyze; es->format = auto_explain_log_format; diff --git a/doc/src/sgml/auto-explain.sgml b/doc/src/sgml/auto-explain.sgml index 3d619d4a3d..d4d29c4a64 100644 --- a/doc/src/sgml/auto-explain.sgml +++ b/doc/src/sgml/auto-explain.sgml @@ -109,6 +109,26 @@ LOAD 'auto_explain'; </listitem> </varlistentry> + <varlistentry> + <term> + <varname>auto_explain.log_wal</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>auto_explain.log_wal</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + <varname>auto_explain.log_wal</varname> controls whether WAL + usage statistics are printed when an execution plan is logged; it's + equivalent to the <literal>WAL</literal> option of <command>EXPLAIN</command>. + This parameter has no effect + unless <varname>auto_explain.log_analyze</varname> is enabled. + This parameter is off by default. + Only superusers can change this setting. + </para> + </listitem> + </varlistentry> + <varlistentry> <term> <varname>auto_explain.log_timing</varname> (<type>boolean</type>) diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml index 385d10411f..024ede4a8d 100644 --- a/doc/src/sgml/ref/explain.sgml +++ b/doc/src/sgml/ref/explain.sgml @@ -41,6 +41,7 @@ EXPLAIN [ ANALYZE ] [ VERBOSE ] <replaceable class="parameter">statement</replac COSTS [ <replaceable class="parameter">boolean</replaceable> ] SETTINGS [ <replaceable class="parameter">boolean</replaceable> ] BUFFERS [ <replaceable class="parameter">boolean</replaceable> ] + WAL [ <replaceable class="parameter">boolean</replaceable> ] TIMING [ <replaceable class="parameter">boolean</replaceable> ] SUMMARY [ <replaceable class="parameter">boolean</replaceable> ] FORMAT { TEXT | XML | JSON | YAML } @@ -192,6 +193,19 @@ ROLLBACK; </listitem> </varlistentry> + <varlistentry> + <term><literal>WAL</literal></term> + <listitem> + <para> + Include information on WAL record generation. Specifically, include the + number of records, number of full page image records and amount of WAL + bytes generated. In text format, only non-zero values are printed. This + parameter may only be used when <literal>ANALYZE</literal> is also + enabled. It defaults to <literal>FALSE</literal>. + </para> + </listitem> + </varlistentry> + <varlistentry> <term><literal>TIMING</literal></term> <listitem> diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index ee0e638f33..cefe2144e5 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -113,6 +113,7 @@ static void show_foreignscan_info(ForeignScanState *fsstate, ExplainState *es); static void show_eval_params(Bitmapset *bms_params, ExplainState *es); static const char *explain_get_index_name(Oid indexId); static void show_buffer_usage(ExplainState *es, const BufferUsage *usage); +static void show_wal_usage(ExplainState *es, const WalUsage *usage); static void ExplainIndexScanDetails(Oid indexid, ScanDirection indexorderdir, ExplainState *es); static void ExplainScanTarget(Scan *plan, ExplainState *es); @@ -175,6 +176,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, es->costs = defGetBoolean(opt); else if (strcmp(opt->defname, "buffers") == 0) es->buffers = defGetBoolean(opt); + else if (strcmp(opt->defname, "wal") == 0) + es->wal = defGetBoolean(opt); else if (strcmp(opt->defname, "settings") == 0) es->settings = defGetBoolean(opt); else if (strcmp(opt->defname, "timing") == 0) @@ -219,6 +222,11 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt, (errcode(ERRCODE_INVALID_PARAMETER_VALUE), errmsg("EXPLAIN option BUFFERS requires ANALYZE"))); + if (es->wal && !es->analyze) + ereport(ERROR, + (errcode(ERRCODE_INVALID_PARAMETER_VALUE), + errmsg("EXPLAIN option WAL requires ANALYZE"))); + /* if the timing was not set explicitly, set default value */ es->timing = (timing_set) ? es->timing : es->analyze; @@ -494,6 +502,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es, if (es->buffers) instrument_option |= INSTRUMENT_BUFFERS; + if (es->wal) + instrument_option |= INSTRUMENT_WAL; /* * We always collect timing for the entire statement, even when node-level @@ -1942,12 +1952,14 @@ ExplainNode(PlanState *planstate, List *ancestors, } } - /* Show buffer usage */ + /* Show buffer/WAL usage */ if (es->buffers && planstate->instrument) show_buffer_usage(es, &planstate->instrument->bufusage); + if (es->wal && planstate->instrument) + show_wal_usage(es, &planstate->instrument->walusage); - /* Prepare per-worker buffer usage */ - if (es->workers_state && es->buffers && es->verbose) + /* Prepare per-worker buffer/WAL usage */ + if (es->workers_state && (es->buffers || es->wal) && es->verbose) { WorkerInstrumentation *w = planstate->worker_instrument; @@ -1960,7 +1972,10 @@ ExplainNode(PlanState *planstate, List *ancestors, continue; ExplainOpenWorker(n, es); - show_buffer_usage(es, &instrument->bufusage); + if (es->buffers) + show_buffer_usage(es, &instrument->bufusage); + if (es->wal) + show_wal_usage(es, &instrument->walusage); ExplainCloseWorker(n, es); } } @@ -3059,6 +3074,44 @@ show_buffer_usage(ExplainState *es, const BufferUsage *usage) } } +/* + * Show WAL usage details. + */ +static void +show_wal_usage(ExplainState *es, const WalUsage *usage) +{ + if (es->format == EXPLAIN_FORMAT_TEXT) + { + /* Show only positive counter values. */ + if ((usage->wal_records > 0) || (usage->wal_num_fpw > 0) || + (usage->wal_bytes > 0)) + { + ExplainIndentText(es); + appendStringInfoString(es->str, "WAL:"); + + if (usage->wal_records > 0) + appendStringInfo(es->str, " records=%ld", + usage->wal_records); + if (usage->wal_num_fpw > 0) + appendStringInfo(es->str, " full page writes=%ld", + usage->wal_num_fpw); + if (usage->wal_bytes > 0) + appendStringInfo(es->str, " bytes=" UINT64_FORMAT, + usage->wal_bytes); + appendStringInfoChar(es->str, '\n'); + } + } + else + { + ExplainPropertyInteger("WAL records", NULL, + usage->wal_records, es); + ExplainPropertyInteger("WAL full page writes", NULL, + usage->wal_num_fpw, es); + ExplainPropertyUInteger("WAL bytes", NULL, + usage->wal_bytes, es); + } +} + /* * Add some additional details about an IndexScan or IndexOnlyScan */ @@ -3843,6 +3896,19 @@ ExplainPropertyInteger(const char *qlabel, const char *unit, int64 value, ExplainProperty(qlabel, unit, buf, true, es); } +/* + * Explain an unsigned integer-valued property. + */ +void +ExplainPropertyUInteger(const char *qlabel, const char *unit, uint64 value, + ExplainState *es) +{ + char buf[32]; + + snprintf(buf, sizeof(buf), UINT64_FORMAT, value); + ExplainProperty(qlabel, unit, buf, true, es); +} + /* * Explain a float-valued property, using the specified number of * fractional digits. diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c index 5fec59723c..0e7a373caf 100644 --- a/src/bin/psql/tab-complete.c +++ b/src/bin/psql/tab-complete.c @@ -3045,8 +3045,8 @@ psql_completion(const char *text, int start, int end) */ if (ends_with(prev_wd, '(') || ends_with(prev_wd, ',')) COMPLETE_WITH("ANALYZE", "VERBOSE", "COSTS", "SETTINGS", - "BUFFERS", "TIMING", "SUMMARY", "FORMAT"); - else if (TailMatches("ANALYZE|VERBOSE|COSTS|SETTINGS|BUFFERS|TIMING|SUMMARY")) + "BUFFERS", "WAL", "TIMING", "SUMMARY", "FORMAT"); + else if (TailMatches("ANALYZE|VERBOSE|COSTS|SETTINGS|BUFFERS|WAL|TIMING|SUMMARY")) COMPLETE_WITH("ON", "OFF"); else if (TailMatches("FORMAT")) COMPLETE_WITH("TEXT", "XML", "JSON", "YAML"); diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h index 54f6240e5e..7b0b0a94a6 100644 --- a/src/include/commands/explain.h +++ b/src/include/commands/explain.h @@ -42,6 +42,7 @@ typedef struct ExplainState bool analyze; /* print actual times */ bool costs; /* print estimated costs */ bool buffers; /* print buffer usage */ + bool wal; /* print WAL usage */ bool timing; /* print detailed node timing */ bool summary; /* print total planning and execution timing */ bool settings; /* print modified settings */ @@ -110,6 +111,8 @@ extern void ExplainPropertyText(const char *qlabel, const char *value, ExplainState *es); extern void ExplainPropertyInteger(const char *qlabel, const char *unit, int64 value, ExplainState *es); +extern void ExplainPropertyUInteger(const char *qlabel, const char *unit, + uint64 value, ExplainState *es); extern void ExplainPropertyFloat(const char *qlabel, const char *unit, double value, int ndigits, ExplainState *es); extern void ExplainPropertyBool(const char *qlabel, bool value, -- 2.20.1
>From 9cf6ff14f3e34b0cf8f95016ef4a2853e792eab9 Mon Sep 17 00:00:00 2001 From: Kirill Bychik <kirill.byc...@gmail.com> Date: Tue, 17 Mar 2020 14:42:02 +0100 Subject: [PATCH v13 3/4] Keep track of WAL usage in pg_stat_statements. Author: Kirill Bychik Reviewed-by: Julien Rouhaud, Fuji Masao Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4zlxws_cza3...@mail.gmail.com --- .../expected/pg_stat_statements.out | 39 +++++++++++++ .../pg_stat_statements--1.7--1.8.sql | 5 +- .../pg_stat_statements/pg_stat_statements.c | 55 +++++++++++++++++-- .../sql/pg_stat_statements.sql | 23 ++++++++ doc/src/sgml/pgstatstatements.sgml | 27 +++++++++ 5 files changed, 144 insertions(+), 5 deletions(-) diff --git a/contrib/pg_stat_statements/expected/pg_stat_statements.out b/contrib/pg_stat_statements/expected/pg_stat_statements.out index 45dbe9e677..f615f8c2bf 100644 --- a/contrib/pg_stat_statements/expected/pg_stat_statements.out +++ b/contrib/pg_stat_statements/expected/pg_stat_statements.out @@ -211,6 +211,45 @@ SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; UPDATE test SET b = $1 WHERE a > $2 | 1 | 3 (10 rows) +-- +-- INSERT, UPDATE, DELETE on test table to validate WAL generation metrics +-- +SELECT pg_stat_statements_reset(); + pg_stat_statements_reset +-------------------------- + +(1 row) + +-- utility "create table" should not be shown +CREATE TABLE pgss_test (a int, b char(20)); +INSERT INTO pgss_test VALUES(generate_series(1, 10), 'aaa'); +UPDATE pgss_test SET b = 'bbb' WHERE a > 7; +DELETE FROM pgss_test WHERE a > 9; +-- DROP test table +SET pg_stat_statements.track_utility = TRUE; +DROP TABLE pgss_test; +SET pg_stat_statements.track_utility = FALSE; +-- Check WAL is generated for the above statements +SELECT query, calls, rows, +wal_bytes > 0 as wal_bytes_generated, +wal_records > 0 as wal_records_generated, +wal_records = rows as wal_records_as_rows +FROM pg_stat_statements ORDER BY query COLLATE "C"; + query | calls | rows | wal_bytes_generated | wal_records_generated | wal_records_as_rows +-----------------------------------------------------------+-------+------+---------------------+-----------------------+--------------------- + DELETE FROM pgss_test WHERE a > $1 | 1 | 1 | t | t | t + DROP TABLE pgss_test | 1 | 0 | t | t | f + INSERT INTO pgss_test VALUES(generate_series($1, $2), $3) | 1 | 10 | t | t | t + SELECT pg_stat_statements_reset() | 1 | 1 | f | f | f + SELECT query, calls, rows, +| 0 | 0 | f | f | t + wal_bytes > $1 as wal_bytes_generated, +| | | | | + wal_records > $2 as wal_records_generated, +| | | | | + wal_records = rows as wal_records_as_rows +| | | | | + FROM pg_stat_statements ORDER BY query COLLATE "C" | | | | | + SET pg_stat_statements.track_utility = FALSE | 1 | 0 | f | f | t + UPDATE pgss_test SET b = $1 WHERE a > $2 | 1 | 3 | t | t | t +(7 rows) + -- -- pg_stat_statements.track = none -- diff --git a/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql index 60d454db7f..30566574ab 100644 --- a/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql +++ b/contrib/pg_stat_statements/pg_stat_statements--1.7--1.8.sql @@ -41,7 +41,10 @@ CREATE FUNCTION pg_stat_statements(IN showtext boolean, OUT temp_blks_read int8, OUT temp_blks_written int8, OUT blk_read_time float8, - OUT blk_write_time float8 + OUT blk_write_time float8, + OUT wal_records int8, + OUT wal_num_fpw int8, + OUT wal_bytes numeric ) RETURNS SETOF record AS 'MODULE_PATHNAME', 'pg_stat_statements_1_8' diff --git a/contrib/pg_stat_statements/pg_stat_statements.c b/contrib/pg_stat_statements/pg_stat_statements.c index 942922b01f..c42bf62fce 100644 --- a/contrib/pg_stat_statements/pg_stat_statements.c +++ b/contrib/pg_stat_statements/pg_stat_statements.c @@ -188,6 +188,9 @@ typedef struct Counters double blk_read_time; /* time spent reading, in msec */ double blk_write_time; /* time spent writing, in msec */ double usage; /* usage factor */ + int64 wal_records; /* # of WAL records generated */ + int64 wal_num_fpw; /* # of WAL full page image records generated */ + uint64 wal_bytes; /* total amount of WAL bytes generated */ } Counters; /* @@ -348,6 +351,7 @@ static void pgss_store(const char *query, uint64 queryId, pgssStoreKind kind, double total_time, uint64 rows, const BufferUsage *bufusage, + const WalUsage *walusage, pgssJumbleState *jstate); static void pg_stat_statements_internal(FunctionCallInfo fcinfo, pgssVersion api_version, @@ -891,6 +895,7 @@ pgss_post_parse_analyze(ParseState *pstate, Query *query) 0, 0, NULL, + NULL, &jstate); } @@ -926,9 +931,16 @@ pgss_planner(Query *parse, instr_time duration; BufferUsage bufusage_start, bufusage; + WalUsage walusage_start, + walusage; /* We need to track buffer usage as the planner can access them. */ bufusage_start = pgBufferUsage; + /* + * Similarly the planner could write some WAL records in some cases + * (e.g. setting a hint bit with those being WAL-logged) + */ + walusage_start = pgWalUsage; INSTR_TIME_SET_CURRENT(start); plan_nested_level++; @@ -954,6 +966,10 @@ pgss_planner(Query *parse, memset(&bufusage, 0, sizeof(BufferUsage)); BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start); + /* calc differences of WAL counters. */ + memset(&walusage, 0, sizeof(WalUsage)); + WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start); + pgss_store(query_string, parse->queryId, parse->stmt_location, @@ -962,6 +978,7 @@ pgss_planner(Query *parse, INSTR_TIME_GET_MILLISEC(duration), 0, &bufusage, + &walusage, NULL); } else @@ -1079,6 +1096,7 @@ pgss_ExecutorEnd(QueryDesc *queryDesc) queryDesc->totaltime->total * 1000.0, /* convert to msec */ queryDesc->estate->es_processed, &queryDesc->totaltime->bufusage, + &queryDesc->totaltime->walusage, NULL); } @@ -1123,8 +1141,10 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, uint64 rows; BufferUsage bufusage_start, bufusage; - + WalUsage walusage_start, + walusage; bufusage_start = pgBufferUsage; + walusage_start = pgWalUsage; INSTR_TIME_SET_CURRENT(start); exec_nested_level++; @@ -1154,6 +1174,10 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, memset(&bufusage, 0, sizeof(BufferUsage)); BufferUsageAccumDiff(&bufusage, &pgBufferUsage, &bufusage_start); + /* calc differences of WAL counters. */ + memset(&walusage, 0, sizeof(WalUsage)); + WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start); + pgss_store(queryString, 0, /* signal that it's a utility stmt */ pstmt->stmt_location, @@ -1162,6 +1186,7 @@ pgss_ProcessUtility(PlannedStmt *pstmt, const char *queryString, INSTR_TIME_GET_MILLISEC(duration), rows, &bufusage, + &walusage, NULL); } else @@ -1197,7 +1222,8 @@ pgss_hash_string(const char *str, int len) * * If jstate is not NULL then we're trying to create an entry for which * we have no statistics as yet; we just want to record the normalized - * query string. total_time, rows, bufusage are ignored in this case. + * query string. total_time, rows, bufusage and walusage are ignored in this + * case. * * If kind is PGSS_PLAN or PGSS_EXEC, its value is used as the array position * for the arrays in the Counters field. @@ -1208,6 +1234,7 @@ pgss_store(const char *query, uint64 queryId, pgssStoreKind kind, double total_time, uint64 rows, const BufferUsage *bufusage, + const WalUsage *walusage, pgssJumbleState *jstate) { pgssHashKey key; @@ -1402,6 +1429,9 @@ pgss_store(const char *query, uint64 queryId, e->counters.blk_read_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_read_time); e->counters.blk_write_time += INSTR_TIME_GET_MILLISEC(bufusage->blk_write_time); e->counters.usage += USAGE_EXEC(total_time); + e->counters.wal_records += walusage->wal_records; + e->counters.wal_num_fpw += walusage->wal_num_fpw; + e->counters.wal_bytes += walusage->wal_bytes; SpinLockRelease(&e->mutex); } @@ -1449,8 +1479,8 @@ pg_stat_statements_reset(PG_FUNCTION_ARGS) #define PG_STAT_STATEMENTS_COLS_V1_1 18 #define PG_STAT_STATEMENTS_COLS_V1_2 19 #define PG_STAT_STATEMENTS_COLS_V1_3 23 -#define PG_STAT_STATEMENTS_COLS_V1_8 29 -#define PG_STAT_STATEMENTS_COLS 29 /* maximum of above */ +#define PG_STAT_STATEMENTS_COLS_V1_8 32 +#define PG_STAT_STATEMENTS_COLS 32 /* maximum of above */ /* * Retrieve statement statistics. @@ -1786,6 +1816,23 @@ pg_stat_statements_internal(FunctionCallInfo fcinfo, values[i++] = Float8GetDatumFast(tmp.blk_read_time); values[i++] = Float8GetDatumFast(tmp.blk_write_time); } + if (api_version >= PGSS_V1_8) + { + char buf[256]; + Datum wal_bytes; + + values[i++] = Int64GetDatumFast(tmp.wal_records); + values[i++] = Int64GetDatumFast(tmp.wal_num_fpw); + + snprintf(buf, sizeof buf, UINT64_FORMAT, tmp.wal_bytes); + + /* Convert to numeric. */ + wal_bytes = DirectFunctionCall3(numeric_in, + CStringGetDatum(buf), + ObjectIdGetDatum(0), + Int32GetDatum(-1)); + values[i++] = wal_bytes; + } Assert(i == (api_version == PGSS_V1_0 ? PG_STAT_STATEMENTS_COLS_V1_0 : api_version == PGSS_V1_1 ? PG_STAT_STATEMENTS_COLS_V1_1 : diff --git a/contrib/pg_stat_statements/sql/pg_stat_statements.sql b/contrib/pg_stat_statements/sql/pg_stat_statements.sql index 435d51008f..75c10554a8 100644 --- a/contrib/pg_stat_statements/sql/pg_stat_statements.sql +++ b/contrib/pg_stat_statements/sql/pg_stat_statements.sql @@ -101,6 +101,29 @@ SELECT * FROM test WHERE a IN (1, 2, 3, 4, 5); SELECT query, calls, rows FROM pg_stat_statements ORDER BY query COLLATE "C"; +-- +-- INSERT, UPDATE, DELETE on test table to validate WAL generation metrics +-- +SELECT pg_stat_statements_reset(); + +-- utility "create table" should not be shown +CREATE TABLE pgss_test (a int, b char(20)); + +INSERT INTO pgss_test VALUES(generate_series(1, 10), 'aaa'); +UPDATE pgss_test SET b = 'bbb' WHERE a > 7; +DELETE FROM pgss_test WHERE a > 9; +-- DROP test table +SET pg_stat_statements.track_utility = TRUE; +DROP TABLE pgss_test; +SET pg_stat_statements.track_utility = FALSE; + +-- Check WAL is generated for the above statements +SELECT query, calls, rows, +wal_bytes > 0 as wal_bytes_generated, +wal_records > 0 as wal_records_generated, +wal_records = rows as wal_records_as_rows +FROM pg_stat_statements ORDER BY query COLLATE "C"; + -- -- pg_stat_statements.track = none -- diff --git a/doc/src/sgml/pgstatstatements.sgml b/doc/src/sgml/pgstatstatements.sgml index b4df84c60b..3d26108649 100644 --- a/doc/src/sgml/pgstatstatements.sgml +++ b/doc/src/sgml/pgstatstatements.sgml @@ -264,6 +264,33 @@ </entry> </row> + <row> + <entry><structfield>wal_bytes</structfield></entry> + <entry><type>numeric</type></entry> + <entry></entry> + <entry> + Total amount of WAL bytes generated by the statement + </entry> + </row> + + <row> + <entry><structfield>wal_records</structfield></entry> + <entry><type>bigint</type></entry> + <entry></entry> + <entry> + Total count of WAL records generated by the statement + </entry> + </row> + + <row> + <entry><structfield>wal_num_fpw</structfield></entry> + <entry><type>bigint</type></entry> + <entry></entry> + <entry> + Total count of WAL full page writes generated by the statement + </entry> + </row> + </tbody> </tgroup> </table> -- 2.20.1
>From fc00f3bc115502395d5b10862be013970b3f29c8 Mon Sep 17 00:00:00 2001 From: Julien Rouhaud <julien.rouh...@free.fr> Date: Thu, 19 Mar 2020 16:08:47 +0100 Subject: [PATCH v13 4/4] Expose WAL usage counters in verbose (auto)vacuum output. Author: Julien Rouhaud Reviewed-by: Fuji Masao Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4zlxws_cza3...@mail.gmail.com --- src/backend/access/heap/vacuumlazy.c | 24 +++++++++++++++++++++++- 1 file changed, 23 insertions(+), 1 deletion(-) diff --git a/src/backend/access/heap/vacuumlazy.c b/src/backend/access/heap/vacuumlazy.c index cc7e8521a5..735087dd74 100644 --- a/src/backend/access/heap/vacuumlazy.c +++ b/src/backend/access/heap/vacuumlazy.c @@ -410,6 +410,8 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params, int nindexes; PGRUsage ru0; TimestampTz starttime = 0; + WalUsage walusage_start = pgWalUsage; + WalUsage walusage = {0, 0, 0}; long secs; int usecs; double read_rate, @@ -614,6 +616,9 @@ heap_vacuum_rel(Relation onerel, VacuumParams *params, TimestampDifference(starttime, endtime, &secs, &usecs); + memset(&walusage, 0, sizeof(WalUsage)); + WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start); + read_rate = 0; write_rate = 0; if ((secs > 0) || (usecs > 0)) @@ -666,7 +671,13 @@ 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); - appendStringInfo(&buf, _("system usage: %s"), pg_rusage_show(&ru0)); + appendStringInfo(&buf, _("system usage: %s\n"), pg_rusage_show(&ru0)); + appendStringInfo(&buf, + _("WAL usage: %ld records, %ld full page writes, " + UINT64_FORMAT " bytes"), + walusage.wal_records, + walusage.wal_num_fpw, + walusage.wal_bytes); ereport(LOG, (errmsg_internal("%s", buf.data))); @@ -758,6 +769,8 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats, IndexBulkDeleteResult **indstats; int i; PGRUsage ru0; + WalUsage walusage_start = pgWalUsage; + WalUsage walusage = {0, 0, 0}; Buffer vmbuffer = InvalidBuffer; BlockNumber next_unskippable_block; bool skipping_blocks; @@ -1727,6 +1740,15 @@ lazy_scan_heap(Relation onerel, VacuumParams *params, LVRelStats *vacrelstats, "%u pages are entirely empty.\n", empty_pages), empty_pages); + + memset(&walusage, 0, sizeof(WalUsage)); + WalUsageAccumDiff(&walusage, &pgWalUsage, &walusage_start); + appendStringInfo(&buf, _("%ld WAL records, %ld WAL full page writes, " + UINT64_FORMAT " WAL bytes\n"), + walusage.wal_records, + walusage.wal_num_fpw, + walusage.wal_bytes); + appendStringInfo(&buf, _("%s."), pg_rusage_show(&ru0)); ereport(elevel, -- 2.20.1
wal_test.sh
Description: Bourne shell script
