From ab2ed546743d8059f3ebe121fb0034752f6be1e6 Mon Sep 17 00:00:00 2001 From: Anthonin Bonnefoy Date: Tue, 7 May 2024 10:11:28 +0200 Subject: [PATCH] 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 | 2 +- expected/cursor.out | 148 ++++++++++++++++++++++++++++++++++++++++++++ sql/cursor.sql | 112 +++++++++++++++++++++++++++++++++ src/pg_tracing.c | 17 ++++- 4 files changed, 275 insertions(+), 4 deletions(-) create mode 100644 expected/cursor.out create mode 100644 sql/cursor.sql diff --git a/Makefile b/Makefile index aee628c..ba8fa2c 100644 --- a/Makefile +++ b/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 diff --git a/expected/cursor.out b/expected/cursor.out new file mode 100644 index 0000000..faa22a1 --- /dev/null +++ b/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(); diff --git a/sql/cursor.sql b/sql/cursor.sql new file mode 100644 index 0000000..a5dec5b --- /dev/null +++ b/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(); diff --git a/src/pg_tracing.c b/src/pg_tracing.c index 61e398d..d2329d2 100644 --- a/src/pg_tracing.c +++ b/src/pg_tracing.c @@ -1536,8 +1536,9 @@ pg_tracing_post_parse_analyze(ParseState *pstate, Query *query, JumbleState *jst return; /* - * We want to avoid calling GetCurrentTimestamp at the start of post parse as it will - * impact all queries and we will only use it when the query is sampled. + * We want to avoid calling GetCurrentTimestamp at the start of post parse + * as it will impact all queries and we will only use it when the query is + * sampled. */ start_top_span = GetCurrentTimestamp(); @@ -1751,7 +1752,17 @@ 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();