Обсуждение: BUG #17871: JIT during postgresql_fdw remote_estimates EXPLAIN have very negatively effect on planning time

The following bug has been logged on the website:

Bug reference:      17871
Logged by:          Maxim Boguk
Email address:      maxim.boguk@gmail.com
PostgreSQL version: 13.9
Operating system:   Linux
Description:

Issue:
postgresql_fdw remote estimated  explain calls could trigger JIT compilation
on the remote side (why explain without analyze trying use JIT at all???),
and with partitioned tables it will lead to very slow planning.

In my case simple query over FDW table have planning time over 150ms with
jit=on on remote side:
explain analyze select * from cold_replica_fdw.interview_review_info_archive
order by topic_id limit 1;
                                                          QUERY PLAN
                                                 

------------------------------------------------------------------------------------------------------------------------------
 Foreign Scan on interview_review_info_archive  (cost=14.10..14.14 rows=1
width=40) (actual time=3.942..4.526 rows=1 loops=1)
 Planning Time: 162.721 ms
 Execution Time: 5.226 ms

And only 15ms with jit=off on remote side:
explain analyze select * from cold_replica_fdw.interview_review_info_archive
order by topic_id limit 1;
                                                          QUERY PLAN
                                                 

------------------------------------------------------------------------------------------------------------------------------
 Foreign Scan on interview_review_info_archive  (cost=14.10..14.14 rows=1
width=40) (actual time=3.724..4.381 rows=1 loops=1)
 Planning Time: 14.655 ms
 Execution Time: 5.048 ms

Checking what's going on the remote side leads to the following results:
remote estimate explain calls from fdw with jit=on
[EXPLAIN] LOG:  duration: 97.050 ms  statement: EXPLAIN SELECT topic_id,
review_id, move_to_invitation_state_time, no_interview_reply_time,
review_suggestion_chat_message_creation_time FROM
public.interview_review_info_archive
vs
remote estimate explain calls from fdw with jit=off
[EXPLAIN] LOG:  duration: 3.343 ms  statement: EXPLAIN SELECT topic_id,
review_id, move_to_invitation_state_time, no_interview_reply_time,
review_suggestion_chat_message_creation_time FROM
public.interview_review_info_archive

Reason with jit=on the database spent a lot of time on the:
 JIT:
   Functions: 200
   Options: Inlining true, Optimization true, Expressions true, Deforming
true

Possible solutions:
band aid:                       postgresql fdw should invoke set jit to
'off';  when doing remote estimates via explain calls.
probably more correct:  explain (without analyze) should not invoke JIT code
path at all (because the database not going to execute query anyway, so
there are no profit from JIT could be gained).

PG Bug reporting form <noreply@postgresql.org> writes:
> Checking what's going on the remote side leads to the following results:
> remote estimate explain calls from fdw with jit=on
> [EXPLAIN] LOG:  duration: 97.050 ms  statement: EXPLAIN SELECT topic_id,
> review_id, move_to_invitation_state_time, no_interview_reply_time,
> review_suggestion_chat_message_creation_time FROM
> public.interview_review_info_archive
> vs
> remote estimate explain calls from fdw with jit=off
> [EXPLAIN] LOG:  duration: 3.343 ms  statement: EXPLAIN SELECT topic_id,
> review_id, move_to_invitation_state_time, no_interview_reply_time,
> review_suggestion_chat_message_creation_time FROM
> public.interview_review_info_archive

Do you see the same discrepancy when you execute EXPLAIN manually
on the remote side?  If so, I wouldn't blame postgres_fdw for it.

I suppose interview_review_info_archive is a view not a plain table?
In either case, could we see the DDL definition for it?

            regards, tom lane

Hi,

On 2023-03-27 08:04:59 +0000, PG Bug reporting form wrote:
> postgresql_fdw remote estimated  explain calls could trigger JIT compilation
> on the remote side (why explain without analyze trying use JIT at all???),
> and with partitioned tables it will lead to very slow planning.

It should not trigger all of JIT, just generating the bitcode, but not
optimizing / emitting it.

> Checking what's going on the remote side leads to the following results:
> remote estimate explain calls from fdw with jit=on
> [EXPLAIN] LOG:  duration: 97.050 ms  statement: EXPLAIN SELECT topic_id,
> review_id, move_to_invitation_state_time, no_interview_reply_time,
> review_suggestion_chat_message_creation_time FROM
> public.interview_review_info_archive
> vs
> remote estimate explain calls from fdw with jit=off
> [EXPLAIN] LOG:  duration: 3.343 ms  statement: EXPLAIN SELECT topic_id,
> review_id, move_to_invitation_state_time, no_interview_reply_time,
> review_suggestion_chat_message_creation_time FROM
> public.interview_review_info_archive

Can you show the explain plan for the remote queries?

Greetings,

Andres Freund

Andres Freund <andres@anarazel.de> writes:
> On 2023-03-27 08:04:59 +0000, PG Bug reporting form wrote:
>> postgresql_fdw remote estimated  explain calls could trigger JIT compilation
>> on the remote side (why explain without analyze trying use JIT at all???),
>> and with partitioned tables it will lead to very slow planning.

> It should not trigger all of JIT, just generating the bitcode, but not
> optimizing / emitting it.

I was wondering if we could skip doing even that much when
EXEC_FLAG_EXPLAIN_ONLY is set.  Without a test case, though,
I'm not very sure where the jitter is getting reached.

            regards, tom lane

On Tue, 28 Mar 2023 at 10:38, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> I was wondering if we could skip doing even that much when
> EXEC_FLAG_EXPLAIN_ONLY is set.  Without a test case, though,
> I'm not very sure where the jitter is getting reached.

It seems to be coming from the qual initialisation in nodeSeqscan.c:
ie. ExecInitSeqScan -> ExecInitQual -> ExecReadyExpr ->
jit_compile_expr

I guess that means just add a check for EXEC_FLAG_EXPLAIN_ONLY in
jit_compile_expr, or only set the es_jit_flags bits in
standard_ExecutorStart() when not in EXEC_FLAG_EXPLAIN_ONLY. I'm not
really sure which of those is better, but the attached does the former
and seems to fix the issue.

David

David Rowley <dgrowleyml@gmail.com> writes:
> I guess that means just add a check for EXEC_FLAG_EXPLAIN_ONLY in
> jit_compile_expr, or only set the es_jit_flags bits in
> standard_ExecutorStart() when not in EXEC_FLAG_EXPLAIN_ONLY. I'm not
> really sure which of those is better, but the attached does the former
> and seems to fix the issue.

Hmm, offhand I'd vote for the latter, because it adds cycles only
once per query not once per expression.  But Andres may have a
better idea about how to do this.

            regards, tom lane

On Tue, 28 Mar 2023 at 17:54, Maxim Boguk <maxim.boguk@gmail.com> wrote:
> During an attempt to create a minimal test case I discovered an effect for which I have no explanation:
> (all tests with jit=on):
>
> Run EXPLAIN on the single partition, so far expected results...
> explain select * from interview_review_info_archive_p028;
>                                           QUERY PLAN
> -----------------------------------------------------------------------------------------------
>  Seq Scan on interview_review_info_archive_p028  (cost=0.00..361819.08 rows=34546848 width=40)
>  JIT:
>    Functions: 2
>    Options: Inlining true, Optimization true, Expressions true, Deforming true

It could be something like a dropped column forcing projection of the
SELECT *.  You might want to try without SELECT * using some subset of
columns instead.

Check if columns have been dropped with:

select attnum,attname from pg_Attribute where
attrelid='interview_review_info_archive_p028'::Regclass;

David

Hi,

On 2023-03-28 13:27:51 +1100, Maxim Boguk wrote:
> Simplest case show huge difference in theEXPLAIN performance with and
> without JIT:
> negotiation_chat_archive=# set jit to on;
> SET
> negotiation_chat_archive=# explain select * FROM
> public.interview_review_info_archive;
>                                                                      QUERY
> PLAN
>
-----------------------------------------------------------------------------------------------------------------------------------------------------
>  Gather  (cost=100.00..4602434.79 rows=354847702 width=40)
>    Workers Planned: 7
>    ->  Parallel Append  (cost=0.00..1053857.77 rows=50692498 width=40)
>          ->  Parallel Seq Scan on interview_review_info_archive_p030
> interview_review_info_archive_30  (cost=0.00..200959.41 rows=15759281
> width=40)
> ...
>          ->  Parallel Seq Scan on interview_review_info_archive_p005
> interview_review_info_archive_5  (cost=0.00..0.11 rows=1 width=40)
>          ->  Parallel Seq Scan on interview_review_info_archive_p009
> interview_review_info_archive_9  (cost=0.00..0.11 rows=1 width=40)
> (103 rows)
>  JIT:
>    Functions: 200
>    Options: Inlining true, Optimization true, Expressions true, Deforming
> true
> (106 rows)
> Time: 33.664 ms
> PS: this sample contradicts Andreas' statement about "It should not trigger
> all of JIT, just generating the bitcode, but not optimizing / emitting it."
> (or I read EXPLAIN output wrong.)

I think you might be misreading it. The output just tells you that we would
perform optimization etc, not that we did.

Upthread JIT caused the explain to take 100ms, here it's "just" 33ms. What's
the difference?

Greetings,

Andres Freund

Hi,

On 2023-03-28 17:28:04 +1100, Maxim Boguk wrote:
> The small update - previous explain was wrong (I forgot enable jit)
> but general explanation correct
> dropping column from test table forcing jit during explain:
>
> set JIT to on;
> alter table tables_to_drop.test drop column move_to_invitation_state_time;
> vacuum ANALYZE tables_to_drop.test;
>
> negotiation_chat_archive=# explain select * from tables_to_drop.test;
>                                    QUERY PLAN
>
> ---------------------------------------------------------------------------------
>  Seq Scan on test  (cost=0.00..361966.20 rows=34567620 width=32)
>  JIT:
>    Functions: 2
>    Options: Inlining false, Optimization false, Expressions true, Deforming
> true
> (4 rows)

That's not really related to JIT - when there are no dropped columns we return
"physical tuples" from e.g. a sequential scan. Physical tuples being tuples
just as they are in the table. But if there are dropped columns, we need to
project, to "filter out" the dropped column.


postgres[3877072][1]=# SHOW max_parallel_workers_per_gather ;
┌─────────────────────────────────┐
│ max_parallel_workers_per_gather │
├─────────────────────────────────┤
│ 0                               │
└─────────────────────────────────┘
(1 row)

postgres[3877072][1]=# ;DROP TABLE large;CREATE TABLE large(id int8, dropme int default 0, data text);INSERT INTO
large(id,data) SELECT g.i, g.i FROM generate_series(1, 5000000) g(i);
 


postgres[3877072][1]=# EXPLAIN (ANALYZE, TIMING OFF) SELECT count(*) FROM large ;
┌───────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                            QUERY PLAN                                             │
├───────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Aggregate  (cost=76830.89..76830.90 rows=1 width=8) (actual rows=1 loops=1)                       │
│   ->  Seq Scan on large  (cost=0.00..67834.11 rows=3598711 width=0) (actual rows=5000000 loops=1) │
│ Planning Time: 0.076 ms                                                                           │
│ Execution Time: 325.636 ms                                                                        │
└───────────────────────────────────────────────────────────────────────────────────────────────────┘
(4 rows)
(repeat a couple times)

ALTER TABLE large DROP COLUMN dropme;


postgres[3877072][1]=# EXPLAIN (ANALYZE, TIMING OFF) SELECT count(*) FROM large ;
┌───────────────────────────────────────────────────────────────────────────────────────────────────┐
│                                            QUERY PLAN                                             │
├───────────────────────────────────────────────────────────────────────────────────────────────────┤
│ Aggregate  (cost=79617.50..79617.51 rows=1 width=8) (actual rows=1 loops=1)                       │
│   ->  Seq Scan on large  (cost=0.00..70063.40 rows=3821640 width=0) (actual rows=5000000 loops=1) │
│ Planning Time: 0.079 ms                                                                           │
│ Execution Time: 365.530 ms                                                                        │
└───────────────────────────────────────────────────────────────────────────────────────────────────┘
(4 rows)


After the DROP COLUMN the time is consistently higher.


JIT is used for projections. When we just use physical tuples, there's no
projection. Hence no JIT for a SELECT * FROM tbl; when there's no dropped
columns.

Greetings,

Andres Freund

Hi,

On 2023-03-28 16:05:00 +1300, David Rowley wrote:
> On Tue, 28 Mar 2023 at 10:38, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > I was wondering if we could skip doing even that much when
> > EXEC_FLAG_EXPLAIN_ONLY is set.  Without a test case, though,
> > I'm not very sure where the jitter is getting reached.
> 
> It seems to be coming from the qual initialisation in nodeSeqscan.c:
> ie. ExecInitSeqScan -> ExecInitQual -> ExecReadyExpr ->
> jit_compile_expr
> 
> I guess that means just add a check for EXEC_FLAG_EXPLAIN_ONLY in
> jit_compile_expr, or only set the es_jit_flags bits in
> standard_ExecutorStart() when not in EXEC_FLAG_EXPLAIN_ONLY. I'm not
> really sure which of those is better, but the attached does the former
> and seems to fix the issue.

I'm a bit worried about either of these making EXPLAIN less informative. Right
now we can see whether and how much would be JITed without ANALYZE. After this
not anymore.

Greetings,

Andres Freund

Hi,

On 2023-03-28 11:33:41 -0700, Andres Freund wrote:
> On 2023-03-28 16:05:00 +1300, David Rowley wrote:
> > On Tue, 28 Mar 2023 at 10:38, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> > > I was wondering if we could skip doing even that much when
> > > EXEC_FLAG_EXPLAIN_ONLY is set.  Without a test case, though,
> > > I'm not very sure where the jitter is getting reached.
> > 
> > It seems to be coming from the qual initialisation in nodeSeqscan.c:
> > ie. ExecInitSeqScan -> ExecInitQual -> ExecReadyExpr ->
> > jit_compile_expr
> > 
> > I guess that means just add a check for EXEC_FLAG_EXPLAIN_ONLY in
> > jit_compile_expr, or only set the es_jit_flags bits in
> > standard_ExecutorStart() when not in EXEC_FLAG_EXPLAIN_ONLY. I'm not
> > really sure which of those is better, but the attached does the former
> > and seems to fix the issue.
> 
> I'm a bit worried about either of these making EXPLAIN less informative. Right
> now we can see whether and how much would be JITed without ANALYZE. After this
> not anymore.

I wonder if we should address the postgres_fdw case of potentially doing lots
of EXPLAINs by adding an option geared towards that?

Or perhaps even a dedicated function?  Generating an entire executor tree,
just to get to estimates that the planner already determined, seems a bit
questionable... Explain output can be quite large. And we are just looking at
the top-level cost + rows anyway?

Greetings,

Andres Freund

On Wed, 29 Mar 2023 at 07:33, Andres Freund <andres@anarazel.de> wrote:
>
> On 2023-03-28 16:05:00 +1300, David Rowley wrote:
> > I guess that means just add a check for EXEC_FLAG_EXPLAIN_ONLY in
> > jit_compile_expr, or only set the es_jit_flags bits in
> > standard_ExecutorStart() when not in EXEC_FLAG_EXPLAIN_ONLY. I'm not
> > really sure which of those is better, but the attached does the former
> > and seems to fix the issue.
>
> I'm a bit worried about either of these making EXPLAIN less informative. Right
> now we can see whether and how much would be JITed without ANALYZE. After this
> not anymore.

If you're worried about that, then wouldn't it just be better to do
something like have jit_compile_expr() increment some other counter
when bailing on EXEC_FLAG_EXPLAIN_ONLY then have EXPLAIN add that
counter to created_functions? With that, we don't need to invent any
new syntax and also remove the overhead from EXPLAIN and also keep the
JIT information.

David

Andres Freund <andres@anarazel.de> writes:
> I wonder if we should address the postgres_fdw case of potentially doing lots
> of EXPLAINs by adding an option geared towards that?

> Or perhaps even a dedicated function?  Generating an entire executor tree,
> just to get to estimates that the planner already determined, seems a bit
> questionable... Explain output can be quite large. And we are just looking at
> the top-level cost + rows anyway?

I experimented with the idea of adding an EXPLAIN option designed for
postgres_fdw's needs.  It seems quite simple to skip executor startup
(and hence jitting) as well as most of the cost of constructing the
EXPLAIN output.  You could imagine going further and having a way for
the planner to skip create_plan() and just return the Path tree, but
I'm skeptical that that would be worth the mess.  It would be a lot
harder to shoehorn into the existing EXPLAIN APIs, for one thing,
and I'm not sure what the planner side would look like either.

The attached just implements the actual printout without the
infrastructure of a new EXPLAIN option, but that's enough for rough
timing tests.  Using a case similar to Maxim's, with a 100-partition
table with a dropped column, this gives me something like

=# explain select * from tpart;
                   QUERY PLAN
------------------------------------------------
 Plan  (cost=0.00..4390.00 rows=226000 width=8)
(1 row)

Time: 0.795 ms

instead of:

=# explain select * from tpart;
                                  QUERY PLAN
-------------------------------------------------------------------------------
 Append  (cost=0.00..4390.00 rows=226000 width=8)
   ->  Seq Scan on tpart1 tpart_1  (cost=0.00..32.60 rows=2260 width=8)
   ->  Seq Scan on tpart2 tpart_2  (cost=0.00..32.60 rows=2260 width=8)
   ...
   ->  Seq Scan on tpart100 tpart_100  (cost=0.00..32.60 rows=2260 width=8)
 JIT:
   Functions: 200
   Options: Inlining true, Optimization true, Expressions true, Deforming true
(104 rows)

Time: 7.219 ms

Obviously plenty of bikeshedding to be done here about the option name
and the exact output, but that's the basic idea.  It would take only
a couple of lines in postgres_fdw.c to invoke this option if the
remote server is new enough, and its code for parsing the EXPLAIN
output wouldn't need to change at all.

BTW, I'm still wondering how Maxim got to 100-plus-msec overheads;
it's around 10ms at most for me, with what seems like a similar case.

            regards, tom lane

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 7e48e9c210..a979243669 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -538,6 +538,40 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,

     Assert(plannedstmt->commandType != CMD_UTILITY);

+    /*
+     * If option XXX is specified, skip executor setup and just print the cost
+     * estimates from the top-level plan node.
+     */
+    if (1)
+    {
+        Plan       *plan = plannedstmt->planTree;
+
+        if (es->format == EXPLAIN_FORMAT_TEXT)
+        {
+            appendStringInfo(es->str, "Plan  (cost=%.2f..%.2f rows=%.0f width=%d)",
+                             plan->startup_cost, plan->total_cost,
+                             plan->plan_rows, plan->plan_width);
+        }
+        else
+        {
+            ExplainOpenGroup("Query", NULL, true, es);
+            ExplainOpenGroup("Plan", "Plan", true, es);
+
+            ExplainPropertyFloat("Startup Cost", NULL, plan->startup_cost,
+                                 2, es);
+            ExplainPropertyFloat("Total Cost", NULL, plan->total_cost,
+                                 2, es);
+            ExplainPropertyFloat("Plan Rows", NULL, plan->plan_rows,
+                                 0, es);
+            ExplainPropertyInteger("Plan Width", NULL, plan->plan_width,
+                                   es);
+
+            ExplainCloseGroup("Plan", "Plan", true, es);
+            ExplainCloseGroup("Query", NULL, true, es);
+        }
+        return;
+    }
+
     if (es->analyze && es->timing)
         instrument_option |= INSTRUMENT_TIMER;
     else if (es->analyze)