Re: RFC: Logging plan of the running query

On 2021-09-07 12:39, torikoshia wrote:
> On 2021-08-20 01:12, Fujii Masao wrote:
>> On 2021/08/11 21:14, torikoshia wrote:
>>> 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().
>> 
>> Thanks for updating the patch!
>> I tried to test the patch again and encountered two issues.
> 
> Thanks for finding these issues!
> 
>> 
>> (1)
>> The following WITH RECURSIVE query failed with the error
>> "ERROR:  failed to find plan for CTE sg" when I ran
>> pg_log_current_query_plan() against the backend executing that query.
>> Is this a bug?
>> 
>>     create table graph0( f int, t int, label text );
>>     insert into graph0 values (1, 2, 'arc 1 -> 2'),(1, 3, 'arc 1 ->
>> 3'),(2, 3, 'arc 2 -> 3'),(1, 4, 'arc 1 -> 4'),(4, 5, 'arc 4 -> 5');
>> 
>>     with recursive search_graph(f, t, label, i) as (
>>         select *, 1||pg_sleep(1)::text from graph0 g
>>         union distinct
>>         select g.*,1||pg_sleep(1)::text
>>         from graph0 g, search_graph sg
>>        where g.f = sg.t
>>     ) search breadth first by f, t set seq
>>     select * from search_graph order by seq;
> 
> This ERROR occurred without applying the patch and just calling
> EXPLAIN(VERBOSE) to CTE with SEARCH BREADTH FIRST.
> 
> I'm going to make another thread to discuss it.
> 
>> (2)
>> When I ran pg_log_current_query_plan() while "make installcheck" test
>> was running, I got the following assertion failure.
>> 
>> TRAP: FailedAssertion("!IsPageLockHeld || (locktag->locktag_type ==
>> LOCKTAG_RELATION_EXTEND)", File: "lock.c", Line: 894, PID: 61512)
>> 
>> 0   postgres                            0x000000010ec23557
>> ExceptionalCondition + 231
>> 1   postgres                            0x000000010e9eff15
>> LockAcquireExtended + 1461
>> 2   postgres                            0x000000010e9ed14d 
>> LockRelationOid + 61
>> 3   postgres                            0x000000010e41251b 
>> relation_open + 91
>> 4   postgres                            0x000000010e509679 table_open 
>> + 25
>> 5   postgres                            0x000000010ebf9462
>> SearchCatCacheMiss + 274
>> 6   postgres                            0x000000010ebf5979
>> SearchCatCacheInternal + 761
>> 7   postgres                            0x000000010ebf566c 
>> SearchCatCache + 60
>> 8   postgres                            0x000000010ec1a9e0 
>> SearchSysCache + 144
>> 9   postgres                            0x000000010ec1ae03
>> SearchSysCacheExists + 51
>> 10  postgres                            0x000000010e58ce35 
>> TypeIsVisible + 437
>> 11  postgres                            0x000000010ea98e4c
>> format_type_extended + 1964
>> 12  postgres                            0x000000010ea9900e
>> format_type_with_typemod + 30
>> 13  postgres                            0x000000010eb78d76 
>> get_const_expr + 742
>> 14  postgres                            0x000000010eb79bc8 
>> get_rule_expr + 232
>> 15  postgres                            0x000000010eb8140f 
>> get_func_expr + 1247
>> 16  postgres                            0x000000010eb79dcd 
>> get_rule_expr + 749
>> 17  postgres                            0x000000010eb81688
>> get_rule_expr_paren + 136
>> 18  postgres                            0x000000010eb7bf38 
>> get_rule_expr + 9304
>> 19  postgres                            0x000000010eb72ad5
>> deparse_expression_pretty + 149
>> 20  postgres                            0x000000010eb73463
>> deparse_expression + 83
>> 21  postgres                            0x000000010e68eaf1 
>> show_plan_tlist + 353
>> 22  postgres                            0x000000010e68adaf ExplainNode 
>> + 4991
>> 23  postgres                            0x000000010e688b4b
>> ExplainPrintPlan + 283
>> 24  postgres                            0x000000010e68e1aa
>> ProcessLogCurrentPlanInterrupt + 266
>> 25  postgres                            0x000000010ea133bb
>> ProcessInterrupts + 3435
>> 26  postgres                            0x000000010e738c97
>> vacuum_delay_point + 55
>> 27  postgres                            0x000000010e42bb4b
>> ginInsertCleanup + 1531
>> 28  postgres                            0x000000010e42d418
>> gin_clean_pending_list + 776
>> 29  postgres                            0x000000010e74955a 
>> ExecInterpExpr + 2522
>> 30  postgres                            0x000000010e7487e2
>> ExecInterpExprStillValid + 82
>> 31  postgres                            0x000000010e7ae83b
>> ExecEvalExprSwitchContext + 59
>> 32  postgres                            0x000000010e7ae7be ExecProject 
>> + 78
>> 33  postgres                            0x000000010e7ae4e9 ExecResult 
>> + 345
>> 34  postgres                            0x000000010e764e42
>> ExecProcNodeFirst + 82
>> 35  postgres                            0x000000010e75ccb2 
>> ExecProcNode + 50
>> 36  postgres                            0x000000010e758301 ExecutePlan 
>> + 193
>> 37  postgres                            0x000000010e7581d1
>> standard_ExecutorRun + 609
>> 38  auto_explain.so                     0x000000010f1df3a7
>> explain_ExecutorRun + 247
>> 39  postgres                            0x000000010e757f3b ExecutorRun 
>> + 91
>> 40  postgres                            0x000000010ea1cb49 
>> PortalRunSelect + 313
>> 41  postgres                            0x000000010ea1c4dd PortalRun + 
>> 861
>> 42  postgres                            0x000000010ea17474
>> exec_simple_query + 1540
>> 43  postgres                            0x000000010ea164d4 
>> PostgresMain + 2580
>> 44  postgres                            0x000000010e91d159 BackendRun 
>> + 89
>> 45  postgres                            0x000000010e91c6a5 
>> BackendStartup + 565
>> 46  postgres                            0x000000010e91b3fe ServerLoop 
>> + 638
>> 47  postgres                            0x000000010e918b9d 
>> PostmasterMain + 6717
>> 48  postgres                            0x000000010e7efd43 main + 819
>> 49  libdyld.dylib                       0x00007fff6a46e3d5 start + 1
>> 50  ???                                 0x0000000000000003 0x0 + 3
>> 
>> LOG:  server process (PID 61512) was terminated by signal 6: Abort 
>> trap: 6
>> DETAIL:  Failed process was running: select
>> gin_clean_pending_list('t_gin_test_tbl_i_j_idx') is not null;
> 
> As far as I understand, since explaining plans can acquire heavyweight
> lock for example to get column names, when page lock is held at the
> time of the interrupt, this assertion error occurs.
> 
> The attached patch tries to avoid this by checking each LocalLock
> entry and when finding even one, giving up logging the plan.
> 
> Thoughts?

Regression tests failed on windows.
Updated patch attached.


Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION