diff --git a/Makefile b/Makefile index 1778375..a561416 100644 --- a/Makefile +++ b/Makefile @@ -19,7 +19,7 @@ OBJS = \ src/pg_tracing_span.o REGRESSCHECKS = setup utility select extended insert trigger sample \ - planstate planstate_bitmap \ + planstate planstate_bitmap planstate_hash \ parallel subxact full_buffer \ nested wal cleanup REGRESSCHECKS_OPTS = --no-locale --encoding=UTF8 --temp-config pg_tracing.conf diff --git a/expected/planstate_hash.out b/expected/planstate_hash.out new file mode 100644 index 0000000..7f0d1a8 --- /dev/null +++ b/expected/planstate_hash.out @@ -0,0 +1,60 @@ +/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ select count(*) from pg_tracing_test r join pg_tracing_test s using (a); + count +------- + 10000 +(1 row) + +SELECT span_operation, deparse_info, parameters, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000001'; + span_operation | deparse_info | parameters | lvl +--------------------------------------------------------------------------+--------------------+------------+----- + select count(*) from pg_tracing_test r join pg_tracing_test s using (a); | | | 1 + Planner | | | 2 + ExecutorRun | | | 2 + Aggregate | | | 3 + Hash Join | Hash Cond: (a = a) | | 4 + SeqScan on pg_tracing_test r | | | 5 + Hash | | | 5 + SeqScan on pg_tracing_test s | | | 6 +(8 rows) + +-- +-----------------------------------------+ +-- | A: HashJoin | +-- ++-----------------+----------------------+ +-- | B: SeqScan | +-- +-----------------+ +-- +--------------------+ +-- | C: Hash | +-- +--------------------+ +-- | D: SeqScan | +-- +--------------+ +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 span_operation='Hash Join' \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='SeqScan on pg_tracing_test r' \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_a_id' and span_operation='Hash' \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='SeqScan on pg_tracing_test s' \gset +SELECT :span_a_end >= :span_c_end as root_ends_last, + :span_c_start >= :span_b_start as hash_start_after_seqscan, + :span_c_start = :span_d_start as hash_start_same_as_child_seqscan, + :span_d_end <= :span_c_end as nested_seq_scan_end_before_parent; + root_ends_last | hash_start_after_seqscan | hash_start_same_as_child_seqscan | nested_seq_scan_end_before_parent +----------------+--------------------------+----------------------------------+----------------------------------- + t | t | t | t +(1 row) + +-- Clean created spans +CALL clean_spans(); diff --git a/sql/planstate_hash.sql b/sql/planstate_hash.sql new file mode 100644 index 0000000..83867e1 --- /dev/null +++ b/sql/planstate_hash.sql @@ -0,0 +1,42 @@ +/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ select count(*) from pg_tracing_test r join pg_tracing_test s using (a); +SELECT span_operation, deparse_info, parameters, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000001'; + +-- +-----------------------------------------+ +-- | A: HashJoin | +-- ++-----------------+----------------------+ +-- | B: SeqScan | +-- +-----------------+ +-- +--------------------+ +-- | C: Hash | +-- +--------------------+ +-- | D: SeqScan | +-- +--------------+ + +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 span_operation='Hash Join' \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='SeqScan on pg_tracing_test r' \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_a_id' and span_operation='Hash' \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='SeqScan on pg_tracing_test s' \gset + +SELECT :span_a_end >= :span_c_end as root_ends_last, + :span_c_start >= :span_b_start as hash_start_after_seqscan, + :span_c_start = :span_d_start as hash_start_same_as_child_seqscan, + :span_d_end <= :span_c_end as nested_seq_scan_end_before_parent; + +-- Clean created spans +CALL clean_spans(); diff --git a/src/pg_tracing_planstate.c b/src/pg_tracing_planstate.c index 4e435b4..f9aa179 100644 --- a/src/pg_tracing_planstate.c +++ b/src/pg_tracing_planstate.c @@ -68,7 +68,8 @@ drop_traced_planstate(int exec_nested_level) } /* - * If spans from planstate is requested, we override planstate's ExecProcNode's pointer with this function. It will track the time of the first node call needed to place the planstate span. + * If spans from planstate is requested, we override planstate's ExecProcNode's pointer with this function. + * It will track the time of the first node call needed to place the planstate span. */ static TupleTableSlot * ExecProcNodeFirstPgTracing(PlanState *node) @@ -388,17 +389,20 @@ generate_span_from_planstate(PlanState *planstate, planstateTraceContext * plans switch (nodeTag(planstate->plan)) { case T_BitmapIndexScan: - case T_Hash: case T_BitmapAnd: case T_BitmapOr: /* * Those nodes won't go through ExecProcNode so we won't have - * their start. Fallback to the parent start. TODO: Use the child - * start as a fallback instead + * their start. Fallback to the parent start. */ span_start = fallback_start; break; + case T_Hash: + /* For hash node, use the child's start */ + traced_planstate = get_traced_planstate(outerPlanState(planstate)); + span_start = traced_planstate->node_start; + break; default: traced_planstate = get_traced_planstate(planstate); /* TODO: better fallback if planstate is not found */