Re: RFC: Logging plan of the running query

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.

(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;

(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;

Regards,

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