Waiting for PostgreSQL 13 – Add the option to report WAL usage in EXPLAIN and auto_explain.

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);

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.