Re: POC: Extension for adding distributed tracing - pg_tracing

Hi!

Storing spans is a tricky question. Monitoring systems often use pull model
and use probes or SQL
API for pulling data, so from this point of view it is much more convenient
to keep spans in separate
table. But in this case we come to another issue - how to flush this data
into the table? Automatic
flushing on a full buffer would randomly (to the user) significantly affect
query performance. I'd rather
make a GUC turned off by default to store spans into the table instead of
buffer.

>3) I'm testing more complex queries. Most of my previous tests were using
simple query protocol but extended protocol introduces
>differences that break some assumptions I did. For example, with multi
statement transaction like
>BEGIN;
>SELECT 1;
>SELECT 2;
>The parse of SELECT 2 will happen before the ExecutorEnd (and the
end_tracing) of SELECT 1. For now, I'm skipping the post parse
>hook if we still have an ongoing tracing.

I've checked this behavior before and haven't noticed the case you
mentioned, but for
loops like
for i in 1..2 loop
StartTime := clock_timestamp();
insert into t2 values (i, a_data);
EndTime := clock_timestamp();
Delta := 1000 * ( extract(epoch from EndTime) - extract(epoch from
StartTime) );
end loop;

I've got the following call sequence:
psql:/home/postgres/tests/trace.sql:52: NOTICE:
pg_tracing_post_parse_analyze hook <1>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook <1>
psql:/home/postgres/tests/trace.sql:52: NOTICE:
pg_tracing_post_parse_analyze hook <2>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook <2>
psql:/home/postgres/tests/trace.sql:52: NOTICE:
pg_tracing_post_parse_analyze hook <StartTime := clock_timestamp()>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook
<StartTime := clock_timestamp()>
psql:/home/postgres/tests/trace.sql:52: NOTICE:
pg_tracing_post_parse_analyze hook <insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorStart
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorRun
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorFinish
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorEnd
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE:
pg_tracing_post_parse_analyze hook <EndTime := clock_timestamp()>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook
<EndTime := clock_timestamp()>
psql:/home/postgres/tests/trace.sql:52: NOTICE:
pg_tracing_post_parse_analyze hook <Delta := 1000 * ( extract(epoch from
EndTime) - extract(epoch from StartTime) )>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook
<Delta := 1000 * ( extract(epoch from EndTime) - extract(epoch from
StartTime) )>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_planner_hook
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorStart
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorRun
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorFinish
<insert into t2 values (i, a_data)>
psql:/home/postgres/tests/trace.sql:52: NOTICE: pg_tracing_ExecutorEnd
<insert into t2 values (i, a_data)>

--
Regards,
Nikita Malakhov
Postgres Professional
The Russian Postgres Company
https://postgrespro.ru/