-- Create pg_tracing extension with sampling on
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ CREATE EXTENSION pg_tracing;
-- This will create the following spans (non exhaustive list):
--
-- +-------------------------------------------------------------------------------------+
-- | A: Utility: Create Extension |
-- +-+-----------------------------------------------------------------------------------+
-- +----------------------------------------------------------------------------------+
-- |B: ProcessUtility: Create Extension |
-- +---+-----------------------------------+---+--------------------------------------+
-- +-----------------------------------+ +-------------------------------------+
-- |C: Utility: Create Function1 | |E: Utility: Create Function2 |
-- ++----------------------------------+ ++-----------------------------------++
-- +----------------------------------+ +-----------------------------------+
-- |D: ProcessUtility: Create Function| |F: ProcessUtility: Create Function2|
-- +----------------------------------+ +-----------------------------------+
-- Extract span_ids, start and end of those spans
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 parent_id='0000000000000001' and span_type='Utility query' \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_type='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='Utility query' limit 1 \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_type='ProcessUtility' \gset
SELECT span_id AS span_e_id,
get_epoch(span_start) as span_e_start,
get_epoch(span_end) as span_e_end
from pg_tracing_peek_spans where parent_id=:'span_b_id' and span_type='Utility query' limit 1 offset 1 \gset
-- Check that the start and end of those spans are within expectation
SELECT :span_a_start <= :span_b_start AS span_a_starts_first,
:span_a_end >= :span_b_end AS span_a_ends_last,
:span_d_end <= :span_c_end AS nested_span_ends_before_parent,
:span_c_end <= :span_e_start AS next_utility_starts_after;
span_a_starts_first | span_a_ends_last | nested_span_ends_before_parent | next_utility_starts_after
---------------------+------------------+--------------------------------+---------------------------
t | t | t | t
(1 row)
-- Clean current spans
CALL clean_spans();
--
-- Test that no utility is captured with track_utility off
--
-- Set utility off
SET pg_tracing.track_utility = off;
-- Test utility tracking disabled + full sampling
SET pg_tracing.sample_rate = 1.0;
DROP EXTENSION pg_tracing;
CREATE EXTENSION pg_tracing;
SET pg_tracing.sample_rate = 0.0;
-- Fetching spans with sort and aggregations can lead to very expensive plans
-- while only a small amount of rows is processed. Disable jit as it will add
-- a significant overhead for not much benefit
set jit=false;
-- Create utility view to keep order stable
CREATE VIEW peek_ordered_spans AS
WITH oldest_start AS (
SELECT min(span_start) as min_start
FROM pg_tracing_peek_spans
) select *,
extract(MICROSECONDS FROM age(span_start, oldest_start.min_start)) as us_start,
extract(MICROSECONDS FROM age(span_end, oldest_start.min_start)) as us_end
FROM pg_tracing_peek_spans_with_level, oldest_start order by span_start, span_end desc, lvl, deparse_info;
CREATE VIEW peek_ordered_spans_with_pos AS
WITH oldest_start AS (
SELECT min(span_start) as min_start FROM pg_tracing_peek_spans
), time_position AS (
SELECT time, ROW_NUMBER () OVER (ORDER BY time) as pos FROM (
SELECT span_start as time FROM pg_tracing_peek_spans_with_level
UNION
SELECT span_end as time FROM pg_tracing_peek_spans_with_level) positions
) SELECT pg_tracing_peek_spans_with_level.*, start_time.pos as pos_start, end_time.pos as pos_end,
extract(MICROSECONDS FROM age(span_start, oldest_start.min_start)) as us_start,
extract(MICROSECONDS FROM age(span_end, oldest_start.min_start)) as us_end
FROM oldest_start, pg_tracing_peek_spans_with_level
JOIN time_position start_time ON span_start = start_time.time
JOIN time_position end_time ON span_end = end_time.time
ORDER BY span_start, span_end desc, lvl, deparse_info;
-- Column type to convert json to record
create type span_json as ("traceId" text, "parentSpanId" text, "spanId" text, name text, "startTimeUnixNano" text, "endTimeUnixNano" text, attributes jsonb, kind int, status jsonb);
CREATE VIEW peek_json_spans AS
SELECT *, jsonb_path_query_first(pg_tracing_json_spans()::jsonb, '$.resourceSpans[0].resource.attributes[0].value.stringValue') as service_name
FROM jsonb_populate_recordset(null::span_json, (SELECT jsonb_path_query_array(pg_tracing_json_spans()::jsonb, '$.resourceSpans[0].scopeSpans[*].spans[*]')));
CREATE FUNCTION get_int_attribute(attributes jsonb, keyvalue text) returns bigint
LANGUAGE SQL
IMMUTABLE
RETURN (jsonb_path_query_first(jsonb_path_query_first(attributes, '$ ? (@.key == $key)', jsonb_build_object('key', keyvalue)),
'$.value.intValue'))::bigint;
CREATE FUNCTION get_double_attribute(attributes jsonb, keyvalue text) returns double precision
LANGUAGE SQL
IMMUTABLE
RETURN (jsonb_path_query_first(jsonb_path_query_first(attributes, '$ ? (@.key == $key)', jsonb_build_object('key', keyvalue)),
'$.value.doubleValue'))::double precision;
CREATE FUNCTION get_string_attribute(attributes jsonb, keyvalue text) returns text
LANGUAGE SQL
IMMUTABLE
RETURN (jsonb_path_query_first(jsonb_path_query_first(attributes, '$ ? (@.key == $key)', jsonb_build_object('key', keyvalue)),
'$.value.stringValue')) ->>0;
CREATE FUNCTION get_string_array_attribute(attributes jsonb, keyvalue text) returns text[]
LANGUAGE SQL
IMMUTABLE
RETURN (SELECT NULLIF(ARRAY(SELECT jsonb_array_elements_text(jsonb_path_query_array(
jsonb_path_query_first(attributes,
'$ ? (@.key == $key)', jsonb_build_object('key', keyvalue)),
'$.value.arrayValue.values[*].stringValue[*]'))), '{}'));
-- View spans generated from json with their nested level
-- TODO: There's probably a better way to do this...
CREATE VIEW peek_json_spans_with_level AS
WITH RECURSIVE list_trace_spans(trace_id, parent_id, span_id, name, span_start, span_end,
kind, service_name, query_id, pid, userid, dbid, sql_error_code, subxact_count,
status_code, status_message,
plan_startup_cost, plan_total_cost, plan_rows, plan_width,
rows, nloops,
shared_blks_hit, shared_blks_read, shared_blks_dirtied, shared_blks_written,
local_blks_hit, local_blks_read, local_blks_dirtied, local_blks_written,
blk_read_time, blk_write_time,
temp_blks_read, temp_blks_written, temp_blk_read_time, temp_blk_write_time,
wal_records, wal_fpi, wal_bytes,
jit_functions, jit_generation_time, jit_inlining_time, jit_emission_time,
startup, parameters, deparse_info,
lvl) AS (
SELECT p."traceId", p."parentSpanId", p."spanId", p."name", p."startTimeUnixNano", p."endTimeUnixNano", p.kind,
p.service_name,
get_int_attribute(p.attributes, 'query.query_id'),
get_int_attribute(p.attributes, 'backend.pid'),
get_int_attribute(p.attributes, 'backend.user_id'),
get_int_attribute(p.attributes, 'backend.database_id'),
get_string_attribute(p.attributes, 'query.sql_error_code'),
get_int_attribute(p.attributes, 'query.subxact_count'),
p.status -> 'code',
p.status -> 'message',
get_double_attribute(p.attributes, 'plan.cost.startup'),
get_double_attribute(p.attributes, 'plan.cost.total'),
get_double_attribute(p.attributes, 'plan.rows'),
get_int_attribute(p.attributes, 'plan.width'),
get_int_attribute(p.attributes, 'node.rows'),
get_int_attribute(p.attributes, 'node.nloops'),
get_int_attribute(p.attributes, 'blocks.shared.hit'),
get_int_attribute(p.attributes, 'blocks.shared.read'),
get_int_attribute(p.attributes, 'blocks.shared.dirtied'),
get_int_attribute(p.attributes, 'blocks.shared.written'),
get_int_attribute(p.attributes, 'blocks.local.hit'),
get_int_attribute(p.attributes, 'blocks.local.read'),
get_int_attribute(p.attributes, 'blocks.local.dirtied'),
get_int_attribute(p.attributes, 'blocks.local.written'),
get_double_attribute(p.attributes, 'blocks.io.read_time'),
get_double_attribute(p.attributes, 'blocks.io.write_time'),
get_double_attribute(p.attributes, 'temp_blocks.io.read_time'),
get_double_attribute(p.attributes, 'temp_blocks.io.write_time'),
get_int_attribute(p.attributes, 'temp_blocks.read'),
get_int_attribute(p.attributes, 'temp_blocks.written'),
get_int_attribute(p.attributes, 'wal.records'),
get_int_attribute(p.attributes, 'wal.fpi'),
get_int_attribute(p.attributes, 'wal.bytes'),
get_int_attribute(p.attributes, 'jit.generation_counter'),
get_double_attribute(p.attributes, 'jit.inlining_counter'),
get_double_attribute(p.attributes, 'jit.optimization_counter'),
get_double_attribute(p.attributes, 'jit.emission_counter'),
get_double_attribute(p.attributes, 'query.startup'),
get_string_array_attribute(p.attributes, 'query.parameters'),
get_string_attribute(p.attributes, 'query.deparse_info'),
1
FROM peek_json_spans p where not "parentSpanId"=ANY(SELECT span_id from pg_tracing_peek_spans)
UNION ALL
SELECT s."traceId", s."parentSpanId", s."spanId", s."name", s."startTimeUnixNano", s."endTimeUnixNano", s.kind,
s.service_name,
get_int_attribute(s.attributes, 'query.query_id'),
get_int_attribute(s.attributes, 'backend.pid'),
get_int_attribute(s.attributes, 'backend.user_id'),
get_int_attribute(s.attributes, 'backend.database_id'),
get_string_attribute(s.attributes, 'query.sql_error_code'),
get_int_attribute(s.attributes, 'query.subxact_count'),
s.status -> 'code',
s.status -> 'message',
get_double_attribute(s.attributes, 'plan.cost.startup'),
get_double_attribute(s.attributes, 'plan.cost.total'),
get_double_attribute(s.attributes, 'plan.rows'),
get_int_attribute(s.attributes, 'plan.width'),
get_int_attribute(s.attributes, 'node.rows'),
get_int_attribute(s.attributes, 'node.nloops'),
get_int_attribute(s.attributes, 'blocks.shared.hit'),
get_int_attribute(s.attributes, 'blocks.shared.read'),
get_int_attribute(s.attributes, 'blocks.shared.dirtied'),
get_int_attribute(s.attributes, 'blocks.shared.written'),
get_int_attribute(s.attributes, 'blocks.local.hit'),
get_int_attribute(s.attributes, 'blocks.local.read'),
get_int_attribute(s.attributes, 'blocks.local.dirtied'),
get_int_attribute(s.attributes, 'blocks.local.written'),
get_double_attribute(s.attributes, 'blocks.io.read_time'),
get_double_attribute(s.attributes, 'blocks.io.write_time'),
get_double_attribute(s.attributes, 'temp_blocks.io.read_time'),
get_double_attribute(s.attributes, 'temp_blocks.io.write_time'),
get_int_attribute(s.attributes, 'temp_blocks.read'),
get_int_attribute(s.attributes, 'temp_blocks.written'),
get_int_attribute(s.attributes, 'wal.records'),
get_int_attribute(s.attributes, 'wal.fpi'),
get_int_attribute(s.attributes, 'wal.bytes'),
get_int_attribute(s.attributes, 'jit.generation_counter'),
get_double_attribute(s.attributes, 'jit.inlining_counter'),
get_double_attribute(s.attributes, 'jit.optimization_counter'),
get_double_attribute(s.attributes, 'jit.emission_counter'),
get_double_attribute(s.attributes, 'query.startup'),
get_string_array_attribute(s.attributes, 'query.parameters'),
get_string_attribute(s.attributes, 'query.deparse_info'),
lvl + 1
FROM peek_json_spans s, list_trace_spans st
WHERE s."parentSpanId" = st.span_id
) SELECT * FROM list_trace_spans;
CREATE VIEW peek_ordered_json_spans AS
SELECT * FROM peek_json_spans_with_level order by span_start, lvl, span_end;
-- Nothing should have been generated
select count(*) = 0 from pg_tracing_consume_spans;
?column?
----------
t
(1 row)
-- Prepare and execute a prepared statement
PREPARE test_prepared_one_param (integer) AS SELECT $1;
EXECUTE test_prepared_one_param(100);
?column?
----------
100
(1 row)
-- Nothing should be generated
select count(*) = 0 from pg_tracing_consume_spans;
?column?
----------
t
(1 row)
-- Force a query to start from ExecutorRun
SET plan_cache_mode='force_generic_plan';
CALL clean_spans();
EXECUTE test_prepared_one_param(200);
?column?
----------
200
(1 row)
SET plan_cache_mode TO DEFAULT;
-- Again, nothing should be generated
select count(*) = 0 from pg_tracing_consume_spans;
?column?
----------
t
(1 row)
--
-- Test that no utility is captured with track_utility off
--
-- Enable utility tracking and track everything
SET pg_tracing.track_utility = on;
SET pg_tracing.sample_rate = 1.0;
-- Prepare and execute a prepared statement
PREPARE test_prepared_one_param_2 (integer) AS SELECT $1;
EXECUTE test_prepared_one_param_2(100);
?column?
----------
100
(1 row)
-- Check the number of generated spans
select count(distinct(trace_id)) from pg_tracing_peek_spans;
count
-------
2
(1 row)
-- Check spans of test_prepared_one_param_2 execution
select span_operation, parameters, lvl from peek_ordered_spans;
span_operation | parameters | lvl
-----------------------------------------------------------+------------+-----
PREPARE test_prepared_one_param_2 (integer) AS SELECT $1; | | 0
ProcessUtility | | 1
SELECT $1; | | 2
EXECUTE test_prepared_one_param_2(100); | | 0
ProcessUtility | | 1
SELECT $1; | {100} | 2
Planner | | 3
ExecutorRun | | 3
Result | | 4
(9 rows)
-- Check the top span (standalone top span has trace_id=parent_id)
select span_operation, parameters, lvl from peek_ordered_spans where right(trace_id, 16) = parent_id;
span_operation | parameters | lvl
-----------------------------------------------------------+------------+-----
PREPARE test_prepared_one_param_2 (integer) AS SELECT $1; | | 0
EXECUTE test_prepared_one_param_2(100); | | 0
(2 rows)
CALL clean_spans();
-- Test prepare with table modification
PREPARE test_insert (integer, text) AS INSERT INTO pg_tracing_test(a, b) VALUES ($1, $2);
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ EXECUTE test_insert(100, '2');
-- Check spans of test_insert execution
select trace_id, span_operation, parameters, lvl from peek_ordered_spans WHERE trace_id='00000000000000000000000000000001';
trace_id | span_operation | parameters | lvl
----------------------------------+----------------------------------------------------+------------+-----
00000000000000000000000000000001 | EXECUTE test_insert(100, '2'); | | 0
00000000000000000000000000000001 | ProcessUtility | | 1
00000000000000000000000000000001 | INSERT INTO pg_tracing_test(a, b) VALUES ($1, $2); | {100,2} | 2
00000000000000000000000000000001 | Planner | | 3
00000000000000000000000000000001 | ExecutorRun | | 3
00000000000000000000000000000001 | Insert on pg_tracing_test | | 4
00000000000000000000000000000001 | Result | | 5
00000000000000000000000000000001 | TransactionCommit | | 0
(8 rows)
-- We should have only two query_ids
SELECT count(distinct query_id)=2 from pg_tracing_peek_spans where trace_id='00000000000000000000000000000001';
?column?
----------
t
(1 row)
SELECT query_id from pg_tracing_peek_spans where trace_id='00000000000000000000000000000001' AND span_operation = 'ProcessUtility' \gset
SELECT query_id = :query_id from pg_tracing_peek_spans where trace_id='00000000000000000000000000000001' AND span_operation = 'Commit';
?column?
----------
(0 rows)
CALL clean_spans();
-- Test prepared statement with generic plan
SET plan_cache_mode='force_generic_plan';
CALL clean_spans();
EXECUTE test_prepared_one_param(200);
?column?
----------
200
(1 row)
SET plan_cache_mode TO DEFAULT;
-- Check the number of generated spans
select count(distinct(trace_id)) from pg_tracing_peek_spans;
count
-------
2
(1 row)
-- Check spans of test_prepared_one_param execution
select span_operation, parameters, lvl from peek_ordered_spans;
span_operation | parameters | lvl
---------------------------------------+------------+-----
EXECUTE test_prepared_one_param(200); | | 0
ProcessUtility | | 1
SELECT $1; | | 2
ExecutorRun | | 3
Result | | 4
SET plan_cache_mode TO DEFAULT; | | 0
ProcessUtility | | 1
(7 rows)
-- Check the top span (standalone top span has trace_id=parent_id)
select span_operation, parameters, lvl from peek_ordered_spans where right(trace_id, 16) = parent_id;
span_operation | parameters | lvl
---------------------------------------+------------+-----
EXECUTE test_prepared_one_param(200); | | 0
SET plan_cache_mode TO DEFAULT; | | 0
(2 rows)
CALL clean_spans();
-- Second create extension should generate an error that is captured by span
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000001-0000000000000001-01'*/ CREATE EXTENSION pg_tracing;
ERROR: extension "pg_tracing" already exists
select span_operation, parameters, sql_error_code, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000001';
span_operation | parameters | sql_error_code | lvl
------------------------------+------------+----------------+-----
CREATE EXTENSION pg_tracing; | | 42710 | 0
ProcessUtility | | 42710 | 1
(2 rows)
-- Create test table
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000002-0000000000000002-01'*/ CREATE TABLE test_create_table (a int, b char(20));
-- Check create table spans
select trace_id, span_type, span_operation, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000002';
trace_id | span_type | span_operation | lvl
----------------------------------+-------------------+-----------------------------------------------------+-----
00000000000000000000000000000002 | Utility query | CREATE TABLE test_create_table (a int, b char(20)); | 0
00000000000000000000000000000002 | ProcessUtility | ProcessUtility | 1
00000000000000000000000000000002 | TransactionCommit | TransactionCommit | 0
(3 rows)
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000003-0000000000000003-01'*/ CREATE INDEX test_create_table_index ON test_create_table (a);
-- Check create index spans
select trace_id, span_type, span_operation, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000003';
trace_id | span_type | span_operation | lvl
----------------------------------+-------------------+----------------------------------------------------------------+-----
00000000000000000000000000000003 | Utility query | CREATE INDEX test_create_table_index ON test_create_table (a); | 0
00000000000000000000000000000003 | ProcessUtility | ProcessUtility | 1
00000000000000000000000000000003 | TransactionCommit | TransactionCommit | 0
(3 rows)
CREATE OR REPLACE FUNCTION function_with_error(IN anyarray, OUT x anyelement, OUT n int)
RETURNS SETOF RECORD
LANGUAGE sql STRICT IMMUTABLE PARALLEL SAFE
AS 'select s from pg_catalog.generate_series(1, 1, 1) as g(s)';
CREATE FUNCTION eval_expr(expr text)
RETURNS text AS
$$
DECLARE
result text;
BEGIN
EXECUTE 'select '||expr INTO result;
RETURN result;
EXCEPTION WHEN OTHERS THEN
RETURN SQLERRM;
END
$$
LANGUAGE plpgsql;
-- Check that tracing a function call with the wrong number of arguments is managed correctly
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000004-0000000000000004-01'*/ select function_with_error('{1,2,3}'::int[]);
ERROR: return type mismatch in function declared to return record
DETAIL: Final statement returns too few columns.
CONTEXT: SQL function "function_with_error" during startup
-- Check lazy function call with error
select trace_id, span_type, span_operation, sql_error_code, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000004';
trace_id | span_type | span_operation | sql_error_code | lvl
----------------------------------+--------------+--------------------------------------------------------------+----------------+-----
00000000000000000000000000000004 | Select query | select function_with_error($1::int[]) | 42P13 | 0
00000000000000000000000000000004 | Planner | Planner | 00000 | 1
00000000000000000000000000000004 | ExecutorRun | ExecutorRun | 42P13 | 1
00000000000000000000000000000004 | ProjectSet | ProjectSet | 42P13 | 2
00000000000000000000000000000004 | Result | Result | 42P13 | 3
00000000000000000000000000000004 | Select query | select s from pg_catalog.generate_series($1, $2, $3) as g(s) | 00000 | 3
(6 rows)
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000005-0000000000000005-01'*/ ANALYZE test_create_table;
select trace_id, span_type, span_operation, sql_error_code, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000005';
trace_id | span_type | span_operation | sql_error_code | lvl
----------------------------------+----------------+----------------------------+----------------+-----
00000000000000000000000000000005 | Utility query | ANALYZE test_create_table; | 00000 | 0
00000000000000000000000000000005 | ProcessUtility | ProcessUtility | 00000 | 1
(2 rows)
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000006-0000000000000006-01'*/ DROP TABLE test_create_table;
select trace_id, span_type, span_operation, sql_error_code, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000006';
trace_id | span_type | span_operation | sql_error_code | lvl
----------------------------------+-------------------+-------------------------------+----------------+-----
00000000000000000000000000000006 | Utility query | DROP TABLE test_create_table; | 00000 | 0
00000000000000000000000000000006 | ProcessUtility | ProcessUtility | 00000 | 1
00000000000000000000000000000006 | TransactionCommit | TransactionCommit | 00000 | 0
(3 rows)
-- Check VACUUM ANALYZE call
/*dddbs='postgres.db',traceparent='00-00000000000000000000000000000007-0000000000000007-01'*/ VACUUM ANALYZE pg_tracing_test;
select trace_id, span_type, span_operation, sql_error_code, lvl from peek_ordered_spans where trace_id='00000000000000000000000000000007';
trace_id | span_type | span_operation | sql_error_code | lvl
----------------------------------+-------------------+---------------------------------+----------------+-----
00000000000000000000000000000007 | Utility query | VACUUM ANALYZE pg_tracing_test; | 00000 | 0
00000000000000000000000000000007 | ProcessUtility | ProcessUtility | 00000 | 1
00000000000000000000000000000007 | TransactionCommit | TransactionCommit | 00000 | 0
(3 rows)
-- Cleanup
CALL clean_spans();
CALL reset_settings();
CALL reset_pg_tracing_test_table();