Re: RFC: Logging plan of the running query - Mailing list pgsql-hackers

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?


Regards,

--
Atsushi Torikoshi
NTT DATA CORPORATION