On 6th of April 2020, Amit Kapila committed patch:
Add the option to report WAL usage in EXPLAIN and auto_explain. This commit adds a new option WAL similar to existing option BUFFERS in the EXPLAIN command. This option allows to include information on WAL record generation added by commit df3b181499 in EXPLAIN output. This also allows the WAL usage information to be displayed via the auto_explain module. A new parameter auto_explain.log_wal controls whether WAL usage statistics are printed when an execution plan is logged. This parameter has no effect unless auto_explain.log_analyze is enabled. Author: Julien Rouhaud Reviewed-by: Dilip Kumar and Amit Kapila Discussion: https://postgr.es/m/CAB-hujrP8ZfUkvL5OYETipQwA=e3n7oqHFU=4ZLxWS_Cza3kQQ@mail.gmail.com
This, of course, it useful only for queries that write stuff, so let's see how it looks. First table to test things on:
$ CREATE TABLE test (id serial PRIMARY KEY, payload text); CREATE TABLE
And now for a test, first INSERT:
$ EXPLAIN (analyze ON, wal ON) INSERT INTO test (payload) SELECT 'depesz #' || i FROM generate_series(1,1000) i; QUERY PLAN ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── INSERT ON test (cost=0.00..22.50 ROWS=1000 width=36) (actual TIME=11.854..11.855 ROWS=0 loops=1) WAL: records=2034 bytes=139646 -> FUNCTION Scan ON generate_series i (cost=0.00..22.50 ROWS=1000 width=36) (actual TIME=0.407..3.442 ROWS=1000 loops=1) WAL: records=31 bytes=3069 Planning TIME: 0.244 ms Execution TIME: 12.140 ms (6 ROWS)
then UPDATE:
$ EXPLAIN (analyze ON, wal ON) UPDATE test SET payload = payload || 'x' WHERE random() < 0.25; QUERY PLAN ────────────────────────────────────────────────────────────────────────────────────────────────────────── UPDATE ON test (cost=0.00..30.11 ROWS=423 width=42) (actual TIME=5.093..5.093 ROWS=0 loops=1) WAL: records=809 bytes=63265 -> Seq Scan ON test (cost=0.00..30.11 ROWS=423 width=42) (actual TIME=0.107..0.683 ROWS=267 loops=1) FILTER: (random() < '0.25'::DOUBLE PRECISION) ROWS Removed BY FILTER: 733 Planning TIME: 0.140 ms Execution TIME: 5.148 ms (7 ROWS)
and finally DELETE:
$ EXPLAIN (analyze ON, wal ON) DELETE FROM test WHERE random() < 0.5; QUERY PLAN ───────────────────────────────────────────────────────────────────────────────────────────────────────── DELETE ON test (cost=0.00..23.00 ROWS=333 width=6) (actual TIME=1.824..1.824 ROWS=0 loops=1) WAL: records=510 FULL page writes=8 bytes=79884 -> Seq Scan ON test (cost=0.00..23.00 ROWS=333 width=6) (actual TIME=0.023..0.406 ROWS=510 loops=1) FILTER: (random() < '0.5'::DOUBLE PRECISION) ROWS Removed BY FILTER: 490 Planning TIME: 0.258 ms Execution TIME: 1.869 ms (7 ROWS)
Nice. In all of the cases we've seen WAL info:
- WAL: records=2034 bytes=139646
- WAL: records=809 bytes=63265
- WAL: records=510 full page writes=8 bytes=79884
To be honest, I don't fully understand why we see these particular numbers – inserting 1k rows generates 2034 wal records, updating 267 – 809 records. Only delete seems to be understandable – 510 records deleted, 510 records in wal.
This could be related to some background activity (autovacuum?), but I'm not sure if that's the case.
Anyway – all kinds of additional info we can get from Pg are welcome, so I'm happy to have it. Thanks a lot, to all involved.