Create top span in ExecutorRun hook if needed

When fetching an existing cursors, the portal already exists and the
query directly starts from ExecutorRun without going through planner,
post_parse or ExecutorStart. Since top spans were only initialised
within those 3 hooks, cursor fetch wouldn't have a matching top span.

This commit fixes the issue by creating the top span in ExecutorRun if
it doesn't exist.

Fixes #10

Makefile

@@ -19,7 +19,7 @@ OBJS = \
 	src/pg_tracing_span.o \
 	src/version_compat.o
 
-REGRESSCHECKS = setup utility select insert trigger
+REGRESSCHECKS = setup utility select insert trigger cursor
 ifeq ($(PG_VERSION),15)
 REGRESSCHECKS += trigger_15
 else

expected/cursor.out

@@ -0,0 +1,148 @@
+BEGIN;
+/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ DECLARE c CURSOR FOR SELECT * from pg_tracing_test;
+/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000002-01'*/ FETCH FORWARD 20 from c \gset
+more than one row returned for \gset
+/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000003-01'*/ FETCH BACKWARD 10 from c \gset
+more than one row returned for \gset
+COMMIT;
+-- First declare
+-- +----------------------------------------+
+-- | A: Declare (Utility)                   |
+-- ++------------------------------------+--+
+--  | B: ProcessUtility                  |
+--  +-+-------------------------------+--+
+--    | C: Declare cursor... (Select) |
+--    +-------------------------------+
+--    | D: Planner   |
+--    +--------------+
+SELECT span_id AS span_a_id,
+        get_epoch(span_start) as span_a_start,
+        get_epoch(span_end) as span_a_end
+		from pg_tracing_peek_spans
+        where trace_id='00000000000000000000000000000001' AND parent_id='0000000000000001' \gset
+SELECT span_id AS span_b_id,
+        get_epoch(span_start) as span_b_start,
+        get_epoch(span_end) as span_b_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_a_id' and span_operation='ProcessUtility' \gset
+SELECT span_id AS span_c_id,
+        get_epoch(span_start) as span_c_start,
+        get_epoch(span_end) as span_c_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_b_id' and span_type='Select query' \gset
+SELECT span_id AS span_d_id,
+        get_epoch(span_start) as span_d_start,
+        get_epoch(span_end) as span_d_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_c_id' and span_operation='Planner' \gset
+SELECT :span_a_end >= MAX(v) as root_ends_last FROM UNNEST(ARRAY[:span_b_end, :span_c_end, :span_d_end]) as v;
+ root_ends_last 
+----------------
+ t
+(1 row)
+
+SELECT :span_c_start >= :span_b_start as nested_declare_starts_after_parent,
+       :span_d_end <= :span_c_end as nested_planner_ends_before_parent;
+ nested_declare_starts_after_parent | nested_planner_ends_before_parent 
+------------------------------------+-----------------------------------
+ t                                  | t
+(1 row)
+
+-- Fetch forward
+-- +----------------------------------------+
+-- | A: Fetch forward (Utility)             |
+-- ++------------------------------------+--+
+--  | B: ProcessUtility                  |
+--  +-+-------------------------------+--+
+--    | C: Declare cursor... (Select) |
+--    +------------------+------------+
+--    | D: ExecutorRun   |
+--    +------------------+
+SELECT span_id AS span_a_id,
+        get_epoch(span_start) as span_a_start,
+        get_epoch(span_end) as span_a_end
+		from pg_tracing_peek_spans
+        where trace_id='00000000000000000000000000000001' AND parent_id='0000000000000002' \gset
+SELECT span_id AS span_b_id,
+        get_epoch(span_start) as span_b_start,
+        get_epoch(span_end) as span_b_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_a_id' and span_operation='ProcessUtility' \gset
+SELECT span_id AS span_c_id,
+        get_epoch(span_start) as span_c_start,
+        get_epoch(span_end) as span_c_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_b_id' and span_type='Select query' \gset
+SELECT span_id AS span_d_id,
+        get_epoch(span_start) as span_d_start,
+        get_epoch(span_end) as span_d_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_c_id' and span_operation='ExecutorRun' \gset
+SELECT :span_a_end >= MAX(v) as root_ends_last FROM UNNEST(ARRAY[:span_b_end, :span_c_end, :span_d_end]) as v;
+ root_ends_last 
+----------------
+ t
+(1 row)
+
+SELECT :span_c_start >= :span_b_start as nested_declare_starts_after_parent,
+       :span_d_end <= :span_c_end as nested_planner_ends_before_parent;
+ nested_declare_starts_after_parent | nested_planner_ends_before_parent 
+------------------------------------+-----------------------------------
+ t                                  | t
+(1 row)
+
+-- Fetch Backward
+-- Same structure as fetch forward
+SELECT span_id AS span_a_id,
+        get_epoch(span_start) as span_a_start,
+        get_epoch(span_end) as span_a_end
+		from pg_tracing_peek_spans
+        where trace_id='00000000000000000000000000000001' AND parent_id='0000000000000003' \gset
+SELECT span_id AS span_b_id,
+        get_epoch(span_start) as span_b_start,
+        get_epoch(span_end) as span_b_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_a_id' and span_operation='ProcessUtility' \gset
+SELECT span_id AS span_c_id,
+        get_epoch(span_start) as span_c_start,
+        get_epoch(span_end) as span_c_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_b_id' and span_type='Select query' \gset
+SELECT span_id AS span_d_id,
+        get_epoch(span_start) as span_d_start,
+        get_epoch(span_end) as span_d_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_c_id' and span_operation='ExecutorRun' \gset
+SELECT :span_a_end >= MAX(v) as root_ends_last FROM UNNEST(ARRAY[:span_b_end, :span_c_end, :span_d_end]) as v;
+ root_ends_last 
+----------------
+ t
+(1 row)
+
+SELECT :span_c_start >= :span_b_start as nested_declare_starts_after_parent,
+       :span_d_end <= :span_c_end as nested_planner_ends_before_parent;
+ nested_declare_starts_after_parent | nested_planner_ends_before_parent 
+------------------------------------+-----------------------------------
+ t                                  | t
+(1 row)
+
+-- Check
+SELECT span_type, span_operation, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000001';
+   span_type    |                   span_operation                    | lvl 
+----------------+-----------------------------------------------------+-----
+ Utility query  | DECLARE c CURSOR FOR SELECT * from pg_tracing_test; |   1
+ ProcessUtility | ProcessUtility                                      |   2
+ Select query   | DECLARE c CURSOR FOR SELECT * from pg_tracing_test; |   3
+ Planner        | Planner                                             |   4
+ Utility query  | FETCH FORWARD 20 from c                             |   1
+ ProcessUtility | ProcessUtility                                      |   2
+ Select query   | DECLARE c CURSOR FOR SELECT * from pg_tracing_test; |   3
+ Executor       | ExecutorRun                                         |   4
+ Utility query  | FETCH BACKWARD 10 from c                            |   1
+ ProcessUtility | ProcessUtility                                      |   2
+ Select query   | DECLARE c CURSOR FOR SELECT * from pg_tracing_test; |   3
+ Executor       | ExecutorRun                                         |   4
+(12 rows)
+
+-- Clean created spans
+CALL clean_spans();

sql/cursor.sql

@@ -0,0 +1,112 @@
+BEGIN;
+/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ DECLARE c CURSOR FOR SELECT * from pg_tracing_test;
+/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000002-01'*/ FETCH FORWARD 20 from c \gset
+/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000003-01'*/ FETCH BACKWARD 10 from c \gset
+COMMIT;
+
+-- First declare
+-- +----------------------------------------+
+-- | A: Declare (Utility)                   |
+-- ++------------------------------------+--+
+--  | B: ProcessUtility                  |
+--  +-+-------------------------------+--+
+--    | C: Declare cursor... (Select) |
+--    +-------------------------------+
+--    | D: Planner   |
+--    +--------------+
+
+SELECT span_id AS span_a_id,
+        get_epoch(span_start) as span_a_start,
+        get_epoch(span_end) as span_a_end
+		from pg_tracing_peek_spans
+        where trace_id='00000000000000000000000000000001' AND parent_id='0000000000000001' \gset
+SELECT span_id AS span_b_id,
+        get_epoch(span_start) as span_b_start,
+        get_epoch(span_end) as span_b_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_a_id' and span_operation='ProcessUtility' \gset
+SELECT span_id AS span_c_id,
+        get_epoch(span_start) as span_c_start,
+        get_epoch(span_end) as span_c_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_b_id' and span_type='Select query' \gset
+SELECT span_id AS span_d_id,
+        get_epoch(span_start) as span_d_start,
+        get_epoch(span_end) as span_d_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_c_id' and span_operation='Planner' \gset
+
+SELECT :span_a_end >= MAX(v) as root_ends_last FROM UNNEST(ARRAY[:span_b_end, :span_c_end, :span_d_end]) as v;
+SELECT :span_c_start >= :span_b_start as nested_declare_starts_after_parent,
+       :span_d_end <= :span_c_end as nested_planner_ends_before_parent;
+
+
+-- Fetch forward
+-- +----------------------------------------+
+-- | A: Fetch forward (Utility)             |
+-- ++------------------------------------+--+
+--  | B: ProcessUtility                  |
+--  +-+-------------------------------+--+
+--    | C: Declare cursor... (Select) |
+--    +------------------+------------+
+--    | D: ExecutorRun   |
+--    +------------------+
+
+SELECT span_id AS span_a_id,
+        get_epoch(span_start) as span_a_start,
+        get_epoch(span_end) as span_a_end
+		from pg_tracing_peek_spans
+        where trace_id='00000000000000000000000000000001' AND parent_id='0000000000000002' \gset
+SELECT span_id AS span_b_id,
+        get_epoch(span_start) as span_b_start,
+        get_epoch(span_end) as span_b_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_a_id' and span_operation='ProcessUtility' \gset
+SELECT span_id AS span_c_id,
+        get_epoch(span_start) as span_c_start,
+        get_epoch(span_end) as span_c_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_b_id' and span_type='Select query' \gset
+SELECT span_id AS span_d_id,
+        get_epoch(span_start) as span_d_start,
+        get_epoch(span_end) as span_d_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_c_id' and span_operation='ExecutorRun' \gset
+
+SELECT :span_a_end >= MAX(v) as root_ends_last FROM UNNEST(ARRAY[:span_b_end, :span_c_end, :span_d_end]) as v;
+SELECT :span_c_start >= :span_b_start as nested_declare_starts_after_parent,
+       :span_d_end <= :span_c_end as nested_planner_ends_before_parent;
+
+-- Fetch Backward
+-- Same structure as fetch forward
+
+SELECT span_id AS span_a_id,
+        get_epoch(span_start) as span_a_start,
+        get_epoch(span_end) as span_a_end
+		from pg_tracing_peek_spans
+        where trace_id='00000000000000000000000000000001' AND parent_id='0000000000000003' \gset
+SELECT span_id AS span_b_id,
+        get_epoch(span_start) as span_b_start,
+        get_epoch(span_end) as span_b_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_a_id' and span_operation='ProcessUtility' \gset
+SELECT span_id AS span_c_id,
+        get_epoch(span_start) as span_c_start,
+        get_epoch(span_end) as span_c_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_b_id' and span_type='Select query' \gset
+SELECT span_id AS span_d_id,
+        get_epoch(span_start) as span_d_start,
+        get_epoch(span_end) as span_d_end
+		from pg_tracing_peek_spans
+        where parent_id =:'span_c_id' and span_operation='ExecutorRun' \gset
+
+SELECT :span_a_end >= MAX(v) as root_ends_last FROM UNNEST(ARRAY[:span_b_end, :span_c_end, :span_d_end]) as v;
+SELECT :span_c_start >= :span_b_start as nested_declare_starts_after_parent,
+       :span_d_end <= :span_c_end as nested_planner_ends_before_parent;
+
+-- Check
+SELECT span_type, span_operation, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000001';
+
+-- Clean created spans
+CALL clean_spans();

src/pg_tracing.c

@@ -1751,7 +1751,16 @@ pg_tracing_ExecutorRun(QueryDesc *queryDesc, ScanDirection direction, uint64 cou
 	{
 		Span	   *executor_run_span;
 		TimestampTz span_start_time = GetCurrentTimestamp();
-		uint64		parent_id = get_latest_top_span(exec_nested_level)->span_id;
+		uint64		parent_id;
+
+		/*
+		 * When fetching an existing cursor, the portal already exists and ExecutorRun
+         * is the first hook called. Create the top span if it doesn't already exist.
+		 */
+		initialize_top_span(trace_context, queryDesc->operation, NULL, NULL, NULL,
+							queryDesc->sourceText, span_start_time, false);
+
+        parent_id = get_latest_top_span(exec_nested_level)->span_id;
 
 		/* Start ExecutorRun span as a new top span */
 		executor_run_span = allocate_new_top_span();