Re: RFC: Logging plan of the running query

On 2021-08-11 00:21, Fujii Masao wrote:

> On 2021/08/10 21:22, torikoshia wrote:
>> I have updated the patch in this way.
> 
> Thanks for updating the patch!
> 
> 
>> In this patch, getting the plan to the DO statement is as follows.
> 
> Looks good to me.
> 
> 
>> Any thoughts?
> 
> +    ereport(LOG_SERVER_ONLY,
> +            (errmsg("plan of the query running on backend with PID %d is:\n%s",
> +                    MyProcPid, es->str->data),
> +             errhidestmt(true)));
> 
> Shouldn't we hide context information by calling errhidecontext(true)?

Agreed.

> While "make installcheck" regression test was running, I repeated
> executing pg_log_current_query_plan() and got the failure of join_hash 
> test
> with the following diff. This means that pg_log_current_query_plan() 
> could
> cause the query that should be completed successfully to fail with the 
> error.
> Isn't this a bug?

Thanks for finding the bug.
I also reproduced it.

> I *guess* that the cause of this issue is that ExplainNode() can call
> InstrEndLoop() more than once unexpectedly.

As far as I looked into, pg_log_current_plan() can call InstrEndLoop() 
through ExplainNode().
I added a flag to ExplainState to avoid calling InstrEndLoop() when 
ExplainNode() is called from pg_log_current_plan().

> 
>  
> ------------------------------------------------------------------------------
>  $$
>    select count(*) from simple r join simple s using (id);
>  $$);
> - initially_multibatch | increased_batches
> -----------------------+-------------------
> - f                    | f
> -(1 row)
> -
> +ERROR:  InstrEndLoop called on running node
> +CONTEXT:  PL/pgSQL function hash_join_batches(text) line 6 at FOR
> over EXECUTE statement
>  rollback to settings;
>  -- parallel with parallel-oblivious hash join
>  savepoint settings;
> @@ -687,11 +684,9 @@
>      left join (select b1.id, b1.t from join_bar b1 join join_bar b2
> using (id)) ss
>      on join_foo.id < ss.id + 1 and join_foo.id > ss.id - 1;
>  $$);
> - multibatch
> -------------
> - t
> -(1 row)
> -
> +ERROR:  InstrEndLoop called on running node
> +CONTEXT:  parallel worker
> +PL/pgSQL function hash_join_batches(text) line 6 at FOR over EXECUTE 
> statement
>  rollback to settings;
>  -- single-batch with rescan, parallel-aware
>  savepoint settings;
>  
> ------------------------------------------------------------------------------
> 
> Regards,

-- 
Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION