-- Only trace queries with sample flag SET pg_tracing.sample_rate = 0.0; SET pg_tracing.caller_sample_rate = 1.0; -- Run a simple query /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ SELECT 1; ?column? ---------- 1 (1 row) -- Get top span id SELECT span_id AS top_span_id from pg_tracing_peek_spans where parent_id='0000000000000001' and span_type='Select query' \gset -- Check parameters SELECT parameters from pg_tracing_peek_spans where span_id=:'top_span_id'; parameters ------------ {1} (1 row) -- Check the number of children SELECT count(*) from pg_tracing_peek_spans where parent_id=:'top_span_id'; count ------- 2 (1 row) -- Check span_operation SELECT span_type, span_operation from pg_tracing_peek_spans where trace_id='00000000000000000000000000000001' order by span_start, span_end desc; span_type | span_operation --------------+---------------- Select query | SELECT $1 Planner | Planner ExecutorRun | ExecutorRun Result | Result (4 rows) -- Check userid SELECT userid = (SELECT usesysid FROM pg_user WHERE usename = current_user) FROM pg_tracing_peek_spans GROUP BY userid; ?column? ---------- t (1 row) -- Check dbid SELECT dbid = (SELECT oid FROM pg_database WHERE datname = (SELECT current_database())) FROM pg_tracing_peek_spans GROUP BY dbid; ?column? ---------- t (1 row) -- Check count of query_id SELECT count(distinct query_id) from pg_tracing_consume_spans where trace_id='00000000000000000000000000000001'; count ------- 1 (1 row) -- Get initial number of traces reported SELECT processed_traces from pg_tracing_info \gset -- Trace a statement with function call /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000003-0000000000000003-01'*/ SELECT count(*) from current_database(); count ------- 1 (1 row) -- Check the generated span span_type, span_operation and order of function call SELECT span_type, span_operation, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000003'; span_type | span_operation | lvl --------------+------------------------------------------+----- Select query | SELECT count(*) from current_database(); | 0 Planner | Planner | 1 ExecutorRun | ExecutorRun | 1 Aggregate | Aggregate | 2 FunctionScan | FunctionScan on current_database | 3 (5 rows) -- Check expected reported number of trace SELECT processed_traces = :processed_traces + 1 from pg_tracing_info; ?column? ---------- t (1 row) -- Trace a more complex query with multiple function calls /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000004-0000000000000004-01'*/ SELECT s.relation_size + s.index_size as relation_size FROM (SELECT pg_relation_size(C.oid) as relation_size, pg_indexes_size(C.oid) as index_size FROM pg_class C) as s limit 1 \gset -- Check the nested level of spans for a query with multiple function calls SELECT span_type, span_operation, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000004'; span_type | span_operation | lvl --------------+--------------------------------------------------------+----- Select query | SELECT s.relation_size + s.index_size as relation_size+| 0 | FROM (SELECT +| | pg_relation_size(C.oid) as relation_size, +| | pg_indexes_size(C.oid) as index_size +| | FROM pg_class C) as s limit $1 | Planner | Planner | 1 ExecutorRun | ExecutorRun | 1 Limit | Limit | 2 SubqueryScan | SubqueryScan on s | 3 SeqScan | SeqScan on pg_class c | 4 (6 rows) -- Check that we're in a correct state after a timeout set statement_timeout=200; -- Trace query triggering a statement timeout /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000007-0000000000000007-01'*/ select * from pg_sleep(10); ERROR: canceling statement due to statement timeout SELECT span_type, span_operation, sql_error_code, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000007'; span_type | span_operation | sql_error_code | lvl --------------+----------------------------+----------------+----- Select query | select * from pg_sleep($1) | 57014 | 0 Planner | Planner | 00000 | 1 ExecutorRun | ExecutorRun | 57014 | 1 FunctionScan | FunctionScan on pg_sleep | 57014 | 2 (4 rows) -- Cleanup statement setting set statement_timeout=0; -- Trace a working query after the timeout to check we're in a consistent state /*dddbs='postgres.db',traceparent='00-00000000000000000000000000000008-0000000000000008-01'*/ select 1; ?column? ---------- 1 (1 row) -- Check the spans order and error code SELECT span_type, span_operation, sql_error_code, lvl FROM peek_ordered_spans where trace_id='00000000000000000000000000000008'; span_type | span_operation | sql_error_code | lvl --------------+----------------+----------------+----- Select query | select $1 | 00000 | 0 Planner | Planner | 00000 | 1 ExecutorRun | ExecutorRun | 00000 | 1 Result | Result | 00000 | 2 (4 rows) -- Cleanup SET plan_cache_mode='auto'; -- Run a statement with node not executed /*dddbs='postgres.db',traceparent='00-0000000000000000000000000000000b-000000000000000b-01'*/ select 1 limit 0; ?column? ---------- (0 rows) SELECT span_operation, parameters, lvl from peek_ordered_spans where trace_id='0000000000000000000000000000000b'; span_operation | parameters | lvl --------------------+------------+----- select $1 limit $2 | {1,0} | 0 Planner | | 1 ExecutorRun | | 1 Limit | | 2 (4 rows) -- Test multiple statements in a single query /*dddbs='postgres.db',traceparent='00-0000000000000000000000000000000c-000000000000000c-01'*/ select 1; select 2; ?column? ---------- 1 (1 row) ?column? ---------- 2 (1 row) SELECT span_operation, parameters, lvl from peek_ordered_spans where trace_id='0000000000000000000000000000000c'; span_operation | parameters | lvl ----------------+------------+----- select $1 | {1} | 0 Planner | | 1 ExecutorRun | | 1 Result | | 2 (4 rows) -- Check multi statement query CALL clean_spans(); SET pg_tracing.sample_rate = 1.0; -- Force a multi-query statement with \; SELECT 1\; SELECT 1, 2; ?column? ---------- 1 (1 row) ?column? | ?column? ----------+---------- 1 | 2 (1 row) SELECT span_type, span_operation, parameters, lvl from peek_ordered_spans; span_type | span_operation | parameters | lvl --------------+----------------+------------+----- Select query | SELECT $1 | {1} | 0 Planner | Planner | | 1 ExecutorRun | ExecutorRun | | 1 Result | Result | | 2 Select query | SELECT $1, $2 | {1,2} | 0 Planner | Planner | | 1 ExecutorRun | ExecutorRun | | 1 Result | Result | | 2 (8 rows) CALL clean_spans(); -- Check standalone trace SELECT 1; ?column? ---------- 1 (1 row) -- Make sure we have unique span ids SELECT count(span_id) from pg_tracing_consume_spans group by span_id; count ------- 1 1 1 1 (4 rows) -- Trigger a planner error SELECT '\xDEADBEEF'::bytea::text::int; ERROR: invalid input syntax for type integer: "\xdeadbeef" -- Check planner error SELECT span_type, span_operation, parameters, sql_error_code, lvl from peek_ordered_spans; span_type | span_operation | parameters | sql_error_code | lvl --------------+-----------------------------+-------------------+----------------+----- Select query | SELECT $1::bytea::text::int | {"'\\xDEADBEEF'"} | 22P02 | 0 Planner | Planner | | 22P02 | 1 (2 rows) CALL clean_spans(); -- Check spans generated by lazy functions CREATE OR REPLACE FUNCTION lazy_function(IN anyarray, OUT x anyelement) RETURNS SETOF anyelement LANGUAGE sql AS 'select * from pg_catalog.generate_series(array_lower($1, 1), array_upper($1, 1), 1)'; SELECT lazy_function('{1,2,3,4}'::int[]) FROM (VALUES (1,2)) as t; lazy_function --------------- 1 2 3 4 (4 rows) SELECT span_type, span_operation, parameters, lvl from peek_ordered_spans; span_type | span_operation | parameters | lvl -------------------+---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+---------------------+----- Utility query | CREATE OR REPLACE FUNCTION lazy_function(IN anyarray, OUT x anyelement) RETURNS SETOF anyelement LANGUAGE sql AS 'select * from pg_catalog.generate_series(array_lower($1, 1), array_upper($1, 1), 1)'; | | 0 ProcessUtility | ProcessUtility | | 1 TransactionCommit | TransactionCommit | | 0 Select query | SELECT lazy_function($1::int[]) FROM (VALUES ($2,$3)) as t | {"'{1,2,3,4}'",1,2} | 0 Planner | Planner | | 1 ExecutorRun | ExecutorRun | | 1 ProjectSet | ProjectSet | | 2 Result | Result | | 3 Select query | select * from pg_catalog.generate_series(array_lower($1, $2), array_upper($1, $3), $4) | {1,1,1} | 3 Planner | Planner | | 4 (10 rows) CALL clean_spans(); -- Check function calls that don't have sources in pg_proc SELECT information_schema._pg_truetypid(a, t) FROM pg_attribute a, pg_type t limit 1; _pg_truetypid --------------- 26 (1 row) SELECT span_type, span_operation, parameters, lvl from peek_ordered_spans; span_type | span_operation | parameters | lvl --------------+---------------------------------------------------------------------------------------+------------+----- Select query | SELECT information_schema._pg_truetypid(a, t) FROM pg_attribute a, pg_type t limit $1 | {1} | 0 Planner | Planner | | 1 ExecutorRun | ExecutorRun | | 1 Limit | Limit | | 2 NestedLoop | NestedLoop | | 3 SeqScan | SeqScan on pg_attribute a | | 4 Materialize | Materialize | | 4 SeqScan | SeqScan on pg_type t | | 5 Select query | Select query | | 2 Planner | Planner | | 3 ExecutorRun | ExecutorRun | | 3 Result | Result | | 4 (12 rows) -- Cleanup CALL clean_spans(); CALL reset_settings();