Proposal: Progressive explain

Hello community,

CONTEXT:

Back in October I presented the talk "Debugging active queries with
mid-flight instrumented explain plans" at PGConf EU 2024
(recording: https://www.youtube.com/watch?v=6ahTb-7C05c) presenting
an experimental feature that enables visualization of in progress
EXPLAIN ANALYZE executions. Given the positive feedback and requests,
I am sending this patch with the feature, which I am calling Progressive
Explain.

PROPOSAL:

This proposal introduces a feature to print execution plans of active
queries in an in-memory shared hash object so that other sessions can
visualize them with a new view: pg_stat_progress_explain.

Plans are only printed if the new GUC parameter progressive_explain is
enabled.

For regular queries or queries started with EXPLAIN (without ANALYZE)
the plan is printed only once at the start.

For instrumented runs (started via EXPLAIN ANALYZE or when auto_explain
flag log_analyze is enabled), the plan is printed on a fixed interval
controlled by the new GUC parameter progressive_explain_interval. This plan
includes all instrumentation stats computed so far (per node rows and
execution time).

New view:
- pg_stat_progress_explain
- pid: PID of the process running the query
- last_explain: timestamp when plan was last printed
- explain_count: amount of times plan was printed
- total_explain_time: accumulated time spend printing plans (in ms)
- explain: the actual plan (limited read privileges)

New GUCs:
- progressive_explain: if progressive plans are printed for local
session.
- type: bool
- default: off
- context: user
- progressive_explain_interval: interval between each explain print.
- type: int
- default: 1s
- min: 10ms
- context: user
- progressive_explain_sample_rate: fraction of rows processed by the
query until progressive_explain_interval is evaluated to print a
progressive plan
- type: floating point
- default: 0.1
- range: (0.0 - 1.0)
- context: user
- progressive_explain_output_size: max output size of the plan
printed in the in-memory hash table.
- type: int
- default: 4096
- min: 100
- context: postmaster
- progressive_explain_format: format used to print the plans.
- type: enum
- default: text
- context: user
- progressive_explain_settings: controls whether information about
modified configuration is added to the printed plan.
- type: bool
- default: off
- context: user
- progressive_explain_verbose: controls whether verbose details are
added to the printed plan.
- type: bool
- default: off
- context: user

DEMONSTRATION:

postgres=# SET progressive_explain = ON;
SET
postgres=# EXPLAIN ANALYZE SELECT *
FROM test t1
UNION ALL
SELECT *
FROM test t1;

postgres=# select * from pg_stat_progress_explain;
-[ RECORD 1
]------+---------------------------------------------------------------------------------------------------------------------------------------
pid | 299663
last_explain | 2024-12-29 22:40:33.016833+00
explain_count | 5
total_explain_time | 0.205
explain | Append (cost=0.00..466670.40 rows=20000160 width=37)
(actual time=0.052..3372.318 rows=14013813 loops=1)
| Buffers: shared hit=4288 read=112501
| -> Seq Scan on test t1 (cost=0.00..183334.80
rows=10000080 width=37) (actual time=0.052..1177.428 rows=10000000 loops=1)
| Buffers: shared hit=4288 read=79046
| -> Seq Scan on test t1_1 (cost=0.00..183334.80
rows=10000080 width=37) (actual time=0.072..608.481 rows=4013813 loops=1)
(current)
| Buffers: shared read=33455
|

IMPLEMENTATION HIGHLIGHTS:

- The initial plan is printed at the end of standard_ExecutorStart
if progressive_explain is enabled, for both regular queries and
instrumented ones (EXPLAIN ANALYZE):

/*
* Start progressive explain if enabled.
*/
if (progressive_explain)
ProgressiveExplainBegin(queryDesc);

- The incremental plan print for instrumented runs uses a dedicated
ExecProcNode if progressive_explain is enabled:

if (node->instrument)
if (progressive_explain)
node->ExecProcNode = ExecProcNodeInstrExplain;
else
node->ExecProcNode = ExecProcNodeInstr;
else
node->ExecProcNode = node->ExecProcNodeReal;

- ExecProcNodeInstrExplain is identical to ExecProcNodeInstr with an
additional part to print plans based on a sampling logic:

/*
* Update progressive explain based on sampling.
*/
if (pg_prng_double(&pg_global_prng_state) < progressive_explain_sample_rate)
ProgressiveExplainUpdate(node);

That logic was added because ExecProcNodeInstrExplain is called once per
row processed (a lot of times) and performing the timestamp interval
check with progressive_explain_interval to decide whether to print
the plan (done inside ProgressiveExplainUpdate) is expensive. Benchmarks
(shared at the end of this email) show that sampling + timestamp check
gives much better results than performing the timestamp check at every
ExecProcNodeInstrExplain call.

- The plans are stored in a shared hash object (explainArray) allocated
at database start, similar to procArray. ExplainHashShmemSize() computes
shared memory needed for it, based on max_connections + max_parallel_workers
for the amount of elements in the array and progressive_explain_output_size
for the size per element.

- A memory context release callback is configured in the memory context
where the query is running, being responsible for updating explainArray
even when the query doesn't finish gracefully.

- Instrumented plans being printed incrementally need to clone
instrumentation
objects to change them, so each print uses a dedicated memory context
that gets released after the output is constructed. This avoids extended
private memory usage:

/* Dedicated memory context for the current plan being printed */
tmpCxt = AllocSetContextCreate(CurrentMemoryContext,
"Progressive Explain Temporary Context",
ALLOCSET_DEFAULT_SIZES);

- A new version of InstrEndLoop (InstrEndLoopForce) was created that allows
to be called targeting in-progress instrumented objects. Those are common
when traversing the plan tree of an active query.

- Column explain from pg_stat_progress_explain can only be visualized by
superusers or the same role that is running the query. If none of those
conditions are met, users will see "<insufficient privilege>".

- For instrumented runs, the printed includes 2 per node modifiers when
appropriate:

<current>: the plan node currently being processed.
<never executed>: a plan node not processed yet.

IMPLEMENTATION OVERHEAD:

When not used, the overhead added is:

- One IF at standard_ExecutorStart to check if progressive_explain is
enabled
- For instrumented runs (EXPLAIN ANALYZE), one IF at ExecProcNodeFirst
to define ExecProcNode wrapper

BENCHMARKS:

Performed 3 scenarios of benchmarks:

A) Comparison between unpatched PG18, patched with progressive explain
disabled and patched with feature enabled globally (all queries printing
the plan at query start:

- PG18 without patch:

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -S -n -T 120 -c 30
number of transactions actually processed: 2173978
latency average = 1.655 ms
tps = 18127.977529 (without initial connection time)

- PG18 with patch:

-- progressive_explain = off

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -S -n -T 120 -c 30
number of transactions actually processed: 2198806
latency average = 1.636 ms
tps = 18333.157809 (without initial connection time)

-- progressive_explain = on (prints plan only once per query)

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -S -n -T 120 -c 30
number of transactions actually processed: 2047459
latency average = 1.756 ms
tps = 17081.477199 (without initial connection time)

B) EXPLAIN ANALYZE performance with different progressive_explain_interval
settings in patched:

-- progressive_explain = off

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 120 -c 1 -f
script.sql
number of transactions actually processed: 27
latency average = 4492.845 ms

-- progressive_explain = on
-- progressive_explain_interval = 1s (default)
-- progressive_explain_sample_rate = 0.01 (default)

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 300 -c 1 -f
script.sql
number of transactions actually processed: 26
latency average = 4656.067 ms

-- progressive_explain = on
-- progressive_explain_interval = 10ms
-- progressive_explain_sample_rate = 0.01 (default)

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 300 -c 1 -f
script.sql
number of transactions actually processed: 26
latency average = 4785.608 ms

C) EXPLAIN ANALYZE performance in patched with and without
progressive_explain_sample_rate, ie, sampling with 2 different values
and also no sampling logic:

-- progressive_explain = off

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 120 -c 1 -f
script.sql
number of transactions actually processed: 27
latency average = 4492.845 ms

-- progressive_explain = on
-- progressive_explain_interval = 1s (default)
-- progressive_explain_sample_rate = 0.01 (default)

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 120 -c 1 -f
script.sql
number of transactions actually processed: 26
latency average = 4656.067 ms

-- progressive_explain = on
-- progressive_explain_interval = 1s (default)
-- progressive_explain_sample_rate = 1

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 120 -c 1 -f
script.sql
number of transactions actually processed: 19
latency average = 6432.902 ms

-- progressive_explain = on
-- progressive_explain_interval = 1s (default)
-- NO SAMPLING LOGIC

postgres(at)ip-172-31-39-191:~$ /usr/local/pgsql/bin/pgbench -n -T 120 -c 1 -f
script.sql
number of transactions actually processed: 21
latency average = 5864.820 ms

BENCHMARK RESULTS:

It definitely needs more testing but preliminary results show that:

- From (A) we see that the patch adds negligible overhead when the
feature is not used. Enabling globally reduces overall TPS as all
queries are spending time printing the plan. The idea is to enable
progressive_explain on a per-need basis, only to a subset of sessions
that need it.

- From (B) we see that using progressive explain slightly increases
total execution time. Difference between using progressive_explain_interval
set to 1s (plan printed 4 times per query in the test) and to
10ms (plan printed ~460 times per query in the test) is very small.
The actual overhead appears when changing progressive_explain_sample_rate.

- From (C) we see that progressive_explain_sample_rate with a low
value (default 0.01) performs better than not using sampling or
using progressive_explain_sample_rate = 1. So the overhead of having
the sampling logic is much lower than not sampling at all.

TESTS:

Currently working on tests for a second version of the patch.

DOCUMENTATION:

Added documentation for the new view pg_stat_progress_explain,
new GUCs and a new item in section 14.1:

14.1. Using EXPLAIN
14.1.1. EXPLAIN Basics
14.1.2. EXPLAIN ANALYZE
14.1.3. Caveats
14.1.4. Progressive EXPLAIN

FURTHER DISCUSSION:

Considering that this patch introduces a new major feature with
several new components (view, GUCs, etc), there is open room for
discussion such as:

- Do the columns in pg_stat_progress_explain make sense? Are we
missing or adding unnecessary columns?

- Do the new GUCs make sense and are their default values appropriate?

- Do we want progressive explain to print plans of regular queries
started without EXPLAIN if progressive_explain is enabled or should
the feature be restricted to instrumented queries (EXPLAIN ANALYZE)?

- Is the size of explainHash based on max_connections + max_parallel_workers
large enough or are there other types of backends that use the
executor and will print plans too?

Regards,

Rafael Castro.