Subject: Re: RFC: Logging plan of the running query
To: torikoshia <torikoshia@oss.nttdata.com>,
 Pavel Stehule <pavel.stehule@gmail.com>
Cc: Bharath Rupireddy <bharath.rupireddyforpostgres@gmail.com>,
 Dilip Kumar <dilipbalaut@gmail.com>,
 Pgsql Hackers <pgsql-hackers@postgresql.org>
References: <cf8501bcd95ba4d727cbba886ba9eea8@oss.nttdata.com>
 <CAFiTN-vOTFRK1xoAWRAGJ+54mSpDxmenAFexbySRhgy7hNH5Fg@mail.gmail.com>
 <CAFiTN-u6yqaxQyfX0jUMqDZ22fePfuQuQmzuozTxC34ca+ZByg@mail.gmail.com>
 <c6682a25f3f0e9bd520707342219eac5@oss.nttdata.com>
 <0842b5da697a03869fb50be93817e4e1@oss.nttdata.com>
 <CALj2ACUpznbsLbOg9mauSQZfU2eDxnNLYXcBHaAp1yWxMKLK9g@mail.gmail.com>
 <1c1590d3962cea6e06621da76677b5f3@oss.nttdata.com>
 <CALj2ACVeOvBcN2-MZh-P3FKxsxOv-DD=fUgAMQEY8vPEhoJUQw@mail.gmail.com>
 <dfc25182d91ed9491f77c0c8ca5b71fd@oss.nttdata.com>
 <64f716c44629e303b66e6c24502147cc@oss.nttdata.com>
 <CALj2ACXS8oSHbO_gf==jRLGGDoMR-AoeKhoSfd1uh8kw-keY7g@mail.gmail.com>
 <d136f7cc678ba271f90e33a112b3669c@oss.nttdata.com>
 <8b53b32f-26cc-0531-4ac0-27310e0bef4b@oss.nttdata.com>
 <CAFj8pRArY+1cGHrK1qOgbk-4auc27tbA338Ga6gh14LW8AtZpg@mail.gmail.com>
 <7958d03fffe3bafcfe8a505145c63928@oss.nttdata.com>
 <d4dffa658e5d52320eff88205c460b88@oss.nttdata.com>
From: Fujii Masao <masao.fujii@oss.nttdata.com>
Message-ID: <9c4d9da6-48a5-fa18-4bff-f8eb0d4c9787@oss.nttdata.com>
Date: Wed, 11 Aug 2021 00:21:11 +0900
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.14; rv:78.0)
 Gecko/20100101 Thunderbird/78.12.0
MIME-Version: 1.0
In-Reply-To: <d4dffa658e5d52320eff88205c460b88@oss.nttdata.com>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Archived-At: 
 <https://www.postgresql.org/message-id/9c4d9da6-48a5-fa18-4bff-f8eb0d4c9787%40oss.nttdata.com>
Precedence: bulk


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


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?

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

  ------------------------------------------------------------------------------
  $$
    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,

-- 
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION