Skip to content

Commit

Permalink
Generate spans from planstate (#4)
Browse files Browse the repository at this point in the history
* Generate spans from planstate

During ExecutorEnd, we can process the executed plan to generate spans from
the instrumented nodes.

* Update tests with the expected planstate spans

* Add GUC parameter to enable spans from planstate

* pgindent

* Correctly handle deparse offset

* Output plan counters, parameters and deparse info for span nodes

* Avoid cascade in cleanup test

* Update wal test with span node expected values

* Added tests for planstate

* Fix full buffer test expectation

* Remove unecessary prototype

* Don't instrument query if planstate spans are not requested

* Rename planstate spans parameter

* Update doc with new parameters

* Typo

* pgindent

* Export exec_nested_level

* Correctly propagate parent end time to process_query_desc

* Stop node instrumentation on error

* Renamed planstate_start to traced_planstate and fix parent link

* Update test expectations

* Update nested test

* Fix typo in deparse help text
  • Loading branch information
bonnefoa authored Mar 29, 2024
1 parent 30af785 commit 52752a9
Show file tree
Hide file tree
Showing 28 changed files with 1,818 additions and 190 deletions.
7 changes: 5 additions & 2 deletions Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -14,11 +14,14 @@ OBJS = \
src/pg_tracing.o \
src/pg_tracing_query_process.o \
src/pg_tracing_parallel.o \
src/pg_tracing_planstate.o \
src/pg_tracing_explain.o \
src/pg_tracing_span.o

REGRESSCHECKS = utility select extended insert trigger sample \
parallel subxact full_buffer nested wal cleanup
REGRESSCHECKS_OPTS = --no-locale --encoding=UTF8 --temp-config pg_tracing.conf --temp-instance=./tmp_check
planstate parallel subxact full_buffer nested wal \
cleanup
REGRESSCHECKS_OPTS = --no-locale --encoding=UTF8 --temp-config pg_tracing.conf

PGXS := $(shell $(PG_CONFIG) --pgxs)

Expand Down
11 changes: 10 additions & 1 deletion doc/pg_tracing.md
Original file line number Diff line number Diff line change
Expand Up @@ -85,6 +85,7 @@ The spans generated by the module are made available via a view named `pg_tracin
| `jit_optimization_time` | double precision | Total time spent by the node on optimizing, in milliseconds |
| `startup` | bigint | Time to the first tuple in nanoseconds |
| `parameters` | text | Value of the query's parameters |
| `deparse_info` | text | Information extracted from deparsing a plan node |

## Functions

Expand Down Expand Up @@ -120,6 +121,10 @@ Controls span buffer's behaviour when `pg_tracing.max_span` spans is reached. If

Controls the fraction of statements with SQLCommenter tracecontext and an enabled sampled flag that will generate spans. The default value is 1.

### pg_tracing.deparse_plan (boolean)

Controls whether the query plan should be deparsed. Deparsing plan allows to add more details in span's name. A `BitmapHeapScan` node may have `Recheck Cond: (a = 1)` as deparsing information. The default value is `on`.

### pg_tracing.export_parameters (boolean)

Controls whether the query's parameters should be exported in spans metadata. The default value is `on`.
Expand Down Expand Up @@ -149,13 +154,17 @@ FROM pg_shmem_allocations
WHERE name ='PgTracing Spans';
```

### pg_tracing.planstate_spans (boolean)

Controls if spans should be generated from the executed query plan. The default value is true.

### pg_tracing.sample_rate (real)

Controls the fraction of statements that generate spans. Statements with tracecontext propagated with SQLCommenter and sampled flag enabled are not impacted by this parameter. For traces with nested statements, either all will be explained or none. The default value is 0.

### pg_tracing.trace_parallel_workers (boolean)

Controls whether spans should be generated for workers created by parallel queries.
Controls whether spans should be generated for workers created by parallel queries. The default value is true.

### pg_tracing.track (enum)

Expand Down
7 changes: 3 additions & 4 deletions expected/cleanup.out
Original file line number Diff line number Diff line change
Expand Up @@ -2,7 +2,6 @@
DROP TABLE pg_tracing_test;
DROP function test_function_project_set;
DROP function test_function_result;
DROP EXTENSION pg_tracing CASCADE;
NOTICE: drop cascades to 2 other objects
DETAIL: drop cascades to view peek_spans_with_level
drop cascades to view peek_ordered_spans
DROP VIEW peek_ordered_spans;
DROP VIEW peek_spans_with_level;
DROP EXTENSION pg_tracing;
15 changes: 11 additions & 4 deletions expected/extended.out
Original file line number Diff line number Diff line change
Expand Up @@ -13,7 +13,8 @@ SELECT span_type, span_operation, parameters, lvl FROM peek_ordered_spans;
Select query | SELECT $1, $2 | $1 = '1', $2 = '2' | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
(3 rows)
Result | Result | | 3
(4 rows)

CALL clean_spans();
-- Trigger an error due to mismatching number of parameters
Expand Down Expand Up @@ -60,12 +61,14 @@ SELECT span_type, span_operation, parameters, lvl FROM peek_ordered_spans;
Select query | SELECT $1 | $1 = '1' | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
Result | Result | | 3
Select query | SELECT $1, $2 | $1 = '2', $2 = '3' | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
Result | Result | | 3
Utility query | COMMIT; | | 1
ProcessUtility | ProcessUtility | | 2
(10 rows)
(12 rows)

CALL clean_spans();
-- Mix extended protocol and simple protocol
Expand Down Expand Up @@ -104,15 +107,18 @@ SELECT span_type, span_operation, parameters, lvl FROM peek_ordered_spans;
Select query | SELECT $1 | $1 = '1' | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
Result | Result | | 3
Select query | SELECT $1, $2, $3; | $1 = 5, $2 = 6, $3 = 7 | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
Result | Result | | 3
Select query | SELECT $1, $2 | $1 = '2', $2 = '3' | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
Result | Result | | 3
Utility query | COMMIT; | | 1
ProcessUtility | ProcessUtility | | 2
(13 rows)
(16 rows)

CALL clean_spans();
-- gdesc calls a single parse command then execute a query. Make sure we handle this case
Expand All @@ -128,6 +134,7 @@ SELECT span_type, span_operation, parameters, lvl FROM peek_ordered_spans;
Select query | SELECT name AS "Column", pg_catalog.format_type(tp, tpm) AS "Type"FROM (VALUES ($1, $2::pg_catalog.oid,$3)) s(name, tp, tpm) | $1 = '?column?', $2 = '23', $3 = -1 | 1
Planner | Planner | | 2
Executor | ExecutorRun | | 2
(3 rows)
Result | Result | | 3
(4 rows)

CALL clean_spans();
4 changes: 2 additions & 2 deletions expected/full_buffer.out
Original file line number Diff line number Diff line change
Expand Up @@ -25,7 +25,7 @@ select processed_traces, processed_spans, dropped_traces, dropped_spans from pg_
-- Saturate the span buffer. Each call should create at least 2 spans
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ CALL loop_select(20);
-- Check that we have dropped spans. The trace was still partially processed
select processed_traces = 1, processed_spans = 40, dropped_traces = 0, dropped_spans > 0 from pg_tracing_info();
select processed_traces = 1, processed_spans = 50, dropped_traces = 0, dropped_spans > 0 from pg_tracing_info();
?column? | ?column? | ?column? | ?column?
----------+----------+----------+----------
t | t | t | t
Expand All @@ -45,7 +45,7 @@ select processed_traces = 1, processed_spans = 40, dropped_traces = 0, dropped_s
(1 row)

-- We should have only one additional dropped trace
select processed_traces = 1, processed_spans = 40, dropped_traces = 1 from pg_tracing_info();
select processed_traces = 1, processed_spans = 50, dropped_traces = 1 from pg_tracing_info();
?column? | ?column? | ?column?
----------+----------+----------
t | t | t
Expand Down
8 changes: 6 additions & 2 deletions expected/insert.out
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,9 @@ SELECT span_type, span_operation from peek_ordered_spans where trace_id='0000000
Insert query | INSERT INTO pg_tracing_test_table_with_constraint VALUES($1, $2);
Planner | Planner
Executor | ExecutorRun
(3 rows)
Insert | Insert on pg_tracing_test_table_with_constraint
Result | Result
(5 rows)

-- Trigger constraint violation
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000003-0000000000000003-01'*/ INSERT INTO pg_tracing_test_table_with_constraint VALUES(1, 'aaa');
Expand All @@ -31,7 +33,9 @@ SELECT span_type, span_operation, sql_error_code, lvl from peek_ordered_spans wh
Insert query | INSERT INTO pg_tracing_test_table_with_constraint VALUES($1, $2); | 23505 | 1
Planner | Planner | 00000 | 2
Executor | ExecutorRun | 23505 | 2
(3 rows)
Insert | Insert on pg_tracing_test_table_with_constraint | 23505 | 3
Result | Result | 23505 | 4
(5 rows)

-- Trigger an error while calling pg_tracing_peek_spans which resets tracing, nothing should be generated
CALL clean_spans();
Expand Down
Loading

0 comments on commit 52752a9

Please sign in to comment.