Subject: Re: Proposal: Progressive explain

From: torikoshia <[email-masked]>
Date: Tue, 01 Apr 2025 22:38:23 +0900

On 2025-04-01 15:23, Rafael Thofehrn Castro wrote:
> Hello again,
> 
>> ERROR:  could not attach to dynamic shared area
> 
> In addition to that refactoring issue, the current patch had a race
> condition in pg_stat_progress_explain to access the DSA of a process
> running a query that gets aborted.
> 
> While discussing with Robert we agreed that it would be wiser to take
> a step back and change the strategy used to share progressive explain
> data in shared memory.
> 
> Instead of using per backend's DSAs shared via a hash structure I now
> define a dsa_pointer and a LWLock in each backend's PGPROC.
> 
> A global DSA is created by the first backend that attempts to use
> the progressive explain feature. After the DSA is created, subsequent
> uses of the feature will just allocate memory there and reference
> via PGPROC's dsa_pointer.
> 
> This solves the race condition reported by Torikoshi and improves
> concurrency performance as now we don't have a global LWLock
> controlling shared memory access, but a per-backend LWLock.
> 
> Performed the same tests done by Torikoshi and it looks like we are
> good now. Even with more frequent inspects in pg_stat_progress_explain
> (\watch 0.01).

Thanks for updating the patch!
Have you tested enabling progressive_explain?

When I ran the 'make installcheck' test again setting 
progressive_explain to on, there was the same assertion failure:

   TRAP: failed Assert("param->paramkind == PARAM_EXTERN"), File: 
"ruleutils.c", Line: 8802, PID: 116832
   postgres: parallel worker for PID 116822 
(ExceptionalCondition+0x98)[0xb7311ea8bf80]
   postgres: parallel worker for PID 116822 (+0x89de6c)[0xb7311e9ede6c]
   postgres: parallel worker for PID 116822 (+0x89eb68)[0xb7311e9eeb68]
   postgres: parallel worker for PID 116822 (+0x89e78c)[0xb7311e9ee78c]
   postgres: parallel worker for PID 116822 (+0x8a1d10)[0xb7311e9f1d10]
   postgres: parallel worker for PID 116822 (+0x89ed80)[0xb7311e9eed80]
   postgres: parallel worker for PID 116822 (+0x89e78c)[0xb7311e9ee78c]
   postgres: parallel worker for PID 116822 (+0x89f174)[0xb7311e9ef174]
   postgres: parallel worker for PID 116822 (+0x89e78c)[0xb7311e9ee78c]
   postgres: parallel worker for PID 116822 (+0x89f0b8)[0xb7311e9ef0b8]
   postgres: parallel worker for PID 116822 (+0x8928dc)[0xb7311e9e28dc]
   postgres: parallel worker for PID 116822 
(deparse_expression+0x34)[0xb7311e9e2834]
   postgres: parallel worker for PID 116822 (+0x347870)[0xb7311e497870]
   postgres: parallel worker for PID 116822 (+0x3478e4)[0xb7311e4978e4]
   postgres: parallel worker for PID 116822 (+0x347970)[0xb7311e497970]
   ...
   TRAP: failed Assert("param->paramkind == PARAM_EXTERN"), File: 
"ruleutils.c", Line: 8802, PID: 116831
   [115650] LOG:  00000: background worker "parallel worker" (PID 116831) 
was terminated by signal 6: Aborted
   [115650] DETAIL:  Failed process was running: explain (analyze, costs 
off, summary off, timing off, buffers off) select count(*) from ab where 
(a = (select 1) or a = (select 3)) and b = 2
   [115650] LOCATION:  LogChildExit, postmaster.c:2846

We can reproduce it as follows:

   show progressive_explain;
   progressive_explain
  ---------------------
   on

   create table ab (a int not null, b int not null) partition by list 
(a);
   create table ab_a2 partition of ab for values in(2) partition by list 
(b);
   create table ab_a2_b1 partition of ab_a2 for values in (1);
   create table ab_a2_b2 partition of ab_a2 for values in (2);
   create table ab_a2_b3 partition of ab_a2 for values in (3);
   create table ab_a1 partition of ab for values in(1) partition by list 
(b);
   create table ab_a1_b1 partition of ab_a1 for values in (1);
   create table ab_a1_b2 partition of ab_a1 for values in (2);
   create table ab_a1_b3 partition of ab_a1 for values in (3);
   create table ab_a3 partition of ab for values in(3) partition by list 
(b);
   create table ab_a3_b1 partition of ab_a3 for values in (1);
   create table ab_a3_b2 partition of ab_a3 for values in (2);
   create table ab_a3_b3 partition of ab_a3 for values in (3);

   set parallel_setup_cost = 0;
   set parallel_tuple_cost = 0;
   set min_parallel_table_scan_size = 0;
   set max_parallel_workers_per_gather = 2;

   explain (analyze, costs off, summary off, timing off, buffers off) 
select count(*) from ab where (a = (select 1) or a = (select 3)) and b = 
2;
   WARNING:  terminating connection because of crash of another server 
process
   DETAIL:  The postmaster has commanded this server process to roll back 
the current transaction and exit, because another server process exited 
abnormally and possibly corrupted shared memory.
   HINT:  In a moment you should be able to reconnect to the database and 
repeat your command.
   server closed the connection unexpectedly
           This probably means the server terminated abnormally
           before or while processing the request.
   The connection to the server was lost. Attempting reset: Failed.

Note that there is no need to access pg_stat_progress_explain.

Could you please check if you can reproduce this?

-- 
Regards,

--
Atsushi Torikoshi
Seconded from NTT DATA GROUP CORPORATION to SRA OSS K.K.

---

From: Robert Haas <[email-masked]>
Date: Tue, 1 Apr 2025 10:37:58 -0400

> Could you please check if you can reproduce this?

I can, and I now see that this patch has a pretty big design problem.
The assertion failure occurs when a background worker tries to call
ruleutils.c's get_parameter(), which tries to find the expression from
which the parameter was computed. To do that, it essentially looks
upward in the plan tree until it finds the source of the parameter.
For example, if the parameter came from the bar_id column of relation
foo, we would then deparse the parameter as foo.bar_id, rather than as
$1 or similar. However, this doesn't work when the deparsing is
attempted from within a parallel worker, because the parallel worker
only gets the portion of the plan it's attempting to execute, not the
whole thing. In your test case, the whole plan looks like this:

 Aggregate
   InitPlan 1
     ->  Result
   InitPlan 2
     ->  Result
   ->  Gather
         Workers Planned: 2
         ->  Parallel Append
               ->  Parallel Seq Scan on ab_a1_b2 ab_1
                     Filter: ((b = 2) AND ((a = (InitPlan 1).col1) OR
(a = (InitPlan 2).col1)))
               ->  Parallel Seq Scan on ab_a2_b2 ab_2
                     Filter: ((b = 2) AND ((a = (InitPlan 1).col1) OR
(a = (InitPlan 2).col1)))
               ->  Parallel Seq Scan on ab_a3_b2 ab_3
                     Filter: ((b = 2) AND ((a = (InitPlan 1).col1) OR
(a = (InitPlan 2).col1)))

Those references to (InitPlan 1).col1 are actually Params. I think
what's happening here is approximately that the worker tries to find
the source of those Params, but (InitPlan 1) is above the Gather node
and thus not available to the worker, and so the worker can't find it
and the assertion fails.

In one sense, it is not hard to fix this: the workers shouldn't really
be doing progressive_explain at all, because then we get a
progressive_explain from each process individually instead of one for
the query as a whole, so we could just think of having the workers
ignore the progressive_explain GUC. However, one thing I realized
earlier this morning is that the progressive EXPLAIN can't show any of
the instrumentation that is relayed back from workers to the leader
only at the end of the execution. See the code in ParallelQueryMain()
just after ExecutorFinish().

What I think this means is that this patch needs significant
rethinking to cope with parallel query. I don't think users are going
to be happy with a progressive EXPLAIN that just ignores what the
workers are doing, and I don't think they're going to be happy with N
separate progressive explains that they have to merge together to get
an overall picture of what the query is doing, and I'm absolutely
positive that they're not going to be happy with something that
crashes. I think there may be a way to come up with a good design here
that avoids these problems, but we definitely don't have time before
feature freeze (not that we were necessarily in a great place to think
of committing this before feature freeze anyway, but it definitely
doesn't make sense now that I understand this problem).

-- 
Robert Haas
EDB: http://www.enterprisedb.com

---

From: Rafael Thofehrn Castro <[email-masked]>
Date: Tue, 1 Apr 2025 14:17:58 -0300

My bad, I mistakenly did the tests without assertion enabled in the last 2
days,
so couldn't catch that Assertion failure. Was able to reproduce it, thanks.

I guess when the code was designed we were not expecting to be doing
explains
in parallel workers.

One comment is that this has nothing to do with instrumentation. So the
hacks
done with instrument objects are not to blame here.

What is interesting is that removing that Assert (not saying we should do
that)
fixes it and there doesn't seem to be other Asserts complaining anywhere.
The
feature works as expected and there are no crashes.

> doesn't make sense now that I understand this problem).

Yeah, that is a fair point. But I actually envisioned this feature to also
target parallel workers, from the start. I see a lot of value in being able
to debug what each parallel worker is doing in their blackboxes. It could be
that a  worker is lagging behind others as it is dealing with non cached
data blocks for example.

According to my tests the parallel workers can actually push instrumentation
to the parent while still running. It all depends on the types of operations
being performed in the plan.

For example, if the parallel worker is doing a parallel seq scan, then it
will
continuously send chunks of rows to the parent and instrumentation goes with
the data. So we don't actually need to wait for the workers to finish until
instrumentation on the parent gets updated. Here is what I got from
Torikoshi's
test after removing that Assert and enabling instrumented progressive
explain (progressive_explain_interval = '10ms'):

-[ RECORD 1
]-------------------------------------------------------------------------------------------------------------------------------------------------
datid       | 5
datname     | postgres
pid         | 169555
last_update | 2025-04-01 12:44:07.36775-03
query_plan  | Gather  (cost=0.02..137998.03 rows=10000002 width=8) (actual
time=0.715..868.619 rows=9232106.00 loops=1) (current)
        +
            |   Workers Planned: 2

       +
            |   Workers Launched: 2

      +
            |   InitPlan 1

       +
            |     ->  Result  (cost=0.00..0.01 rows=1 width=4) (actual
time=0.002..0.002 rows=1.00 loops=1)
            +
            |   InitPlan 2

       +
            |     ->  Result  (cost=0.00..0.01 rows=1 width=4) (actual
time=0.000..0.000 rows=1.00 loops=1)
            +
            |   ->  Parallel Append  (cost=0.00..137998.01 rows=4166669
width=8) (actual time=0.364..264.804 rows=1533011.00 loops=1)
          +
            |         ->  Seq Scan on ab_a2_b1 ab_2  (cost=0.00..0.00
rows=1 width=8) (never executed)
             +
            |               Filter: ((b = 1) AND ((a = (InitPlan 1).col1)
OR (a = (InitPlan 2).col1)))
         +
            |         ->  Seq Scan on ab_a3_b1 ab_3  (cost=0.00..0.00
rows=1 width=8) (never executed)
             +
            |               Filter: ((b = 1) AND ((a = (InitPlan 1).col1)
OR (a = (InitPlan 2).col1)))
         +
            |         ->  Parallel Seq Scan on ab_a1_b1 ab_1
 (cost=0.00..117164.67 rows=4166667 width=8) (actual time=0.361..192.896
rows=1533011.00 loops=1)+
            |               Filter: ((b = 1) AND ((a = (InitPlan 1).col1)
OR (a = (InitPlan 2).col1)))
         +
            |
-[ RECORD 2
]-------------------------------------------------------------------------------------------------------------------------------------------------
datid       | 5
datname     | postgres
pid         | 169596
last_update | 2025-04-01 12:44:07.361846-03
query_plan  | Parallel Append  (cost=0.00..137998.01 rows=4166669 width=8)
(actual time=0.990..666.845 rows=3839515.00 loops=1) (current)
        +
            |   ->  Seq Scan on ab_a2_b1 ab_2  (cost=0.00..0.00 rows=1
width=8) (never executed)
           +
            |         Filter: ((b = 1) AND ((a = $0) OR (a = $1)))

       +
            |   ->  Seq Scan on ab_a3_b1 ab_3  (cost=0.00..0.00 rows=1
width=8) (never executed)
           +
            |         Filter: ((b = 1) AND ((a = $0) OR (a = $1)))

       +
            |   ->  Parallel Seq Scan on ab_a1_b1 ab_1
 (cost=0.00..117164.67 rows=4166667 width=8) (actual time=0.985..480.531
rows=3839515.00 loops=1)      +
            |         Filter: ((b = 1) AND ((a = $0) OR (a = $1)))

       +
            |
-[ RECORD 3
]-------------------------------------------------------------------------------------------------------------------------------------------------
datid       | 5
datname     | postgres
pid         | 169597
last_update | 2025-04-01 12:44:07.36181-03
query_plan  | Parallel Append  (cost=0.00..137998.01 rows=4166669 width=8)
(actual time=1.003..669.398 rows=3830293.00 loops=1) (current)
        +
            |   ->  Seq Scan on ab_a2_b1 ab_2  (cost=0.00..0.00 rows=1
width=8) (never executed)
           +
            |         Filter: ((b = 1) AND ((a = $0) OR (a = $1)))

       +
            |   ->  Seq Scan on ab_a3_b1 ab_3  (cost=0.00..0.00 rows=1
width=8) (actual time=0.019..0.019 rows=0.00 loops=1)
           +
            |         Filter: ((b = 1) AND ((a = $0) OR (a = $1)))

       +
            |   ->  Parallel Seq Scan on ab_a1_b1 ab_1
 (cost=0.00..117164.67 rows=4166667 width=8) (actual time=0.979..482.420
rows=3830293.00 loops=1)      +
            |         Filter: ((b = 1) AND ((a = $0) OR (a = $1)))

       +
            |

But yeah, if the parallel worker does a hash join and the HASH node is a
huge
block of sub operations, then yes, upstream will not see anything until the
HASH
is computed. That is why IMO having visibility on background workers has
value
too.

I even designed a query visualizer that combines plans of the parent and
parallel workers in side-by-side windows that includes other stats (per
process wait events, CPU, memory consumption, temp file generation) allowing
us to correlate with specific operations being done in the plans.

But Robert is right, the engineering required to make this happen isn't
easy. Changing that Assert can open a pandora box of other issues and we
have no time to do that for PG18.

Rafael.