[asfernandes]

The Default_Profiler used to add a fixed cost to every PSQL statement, record source open and record fetch. That cost came from a clock read and a plugin call for each event, plus the bookkeeping around them. Measured times were also wrong, at about 40% of the real time. This PR makes profiling much cheaper and fixes the measured times. The data reported doesn't change, except that min/max times are NULL when timings are sampled.

Changes

• Per-event bookkeeping (engine and Default_Profiler):
  • The last request and statement are cached, and the statement cache is keyed by statement id.
  • Record source sequences and stats are kept in arrays indexed by id instead of in maps.
  • The "profiler active" state is cached in the attachment, so the per-row checks are an inline read instead of out-of-line calls, also when the profiler is off.
  • StmtNode profile flags replace a virtual call per statement.
  • query_performance_counter() is inline on POSIX.
• Sampled timings (default):
  • A process-wide sampler thread (ProfilerSampler) wakes up at a randomized interval. It reads where each profiled attachment is executing from a seqlock-protected frame stack, and charges the elapsed wall time to each request, PSQL line/column and record source it finds there.
  • The executor only publishes its position, with a few plain stores per event.
  • Counters stay exact. They are kept per request in dense arrays and delivered in batches through the new IProfilerSession methods add*Stats.
  • When all profiled attachments have executed nothing for 10 ms, the sampler sleeps until one of them starts a request or resumes its session, instead of waking up every interval.
• SAMPLING_INTERVAL: a new last parameter of RDB$PROFILER.START_SESSION, in microseconds. The default is 100, and other values must be in 50..1000000. 0 measures every event, which gives exact min/max.
• Measured mode overhead correction:
  • The profiler's own work for each event is bracketed by clock reads and subtracted from the intervals that enclose it.
  • The cost of one clock read is calibrated as a batch average, and calibrated again every 100 ms, because it changes with the CPU frequency.
  • Measured times are now within a few percent of the unprofiled times, instead of about 40% of the real time.
• Request and row costs:
  • When timings are sampled, a finished request skips the overhead accounting.
  • A finished request takes the samples lock only when samples may be pending, and samples taken while the attachment executes nothing don't mark them as pending.
  • Request counter arrays are reused through a free list.
  • One shared status is used for the per-request plugin calls.
  • The GMT timestamp is converted directly, without calendar fields.
  • When the profiler is off, the record source stop watcher is skipped.

[asfernandes]

Test setup

• AMD Ryzen 9 7900 (12 cores / 24 threads), Ubuntu 26.04.1, Linux 7.0.0.
• Release builds (clang 21.1.8):
• Embedded isql. The timing is the elapsed time of set stats on for the timed statement.
• 10 runs per test and mode, alternating modes, each in a fresh isql process with a newly created database. The tables show the median.
• Modes:
  • off: no profiler session.
  • measured: every event is timed. On master this is the default. On the branch it is SAMPLING_INTERVAL 0.
  • sampled 1000 µs, sampled 100 µs (the branch default) and sampled 50 µs (the minimum): branch only, SAMPLING_INTERVAL 1000, 100 and 50.
  • DETAILED_REQUESTS: plugin option. It is measured on master and sampled with the default 100 µs on the branch.
• The session is started before the timed statement and finished afterwards. Neither is timed.

-- master
select rdb$profiler.start_session('bench', null, null, null, <plugin options>) from rdb$database;

-- branch
select rdb$profiler.start_session('bench', null, null, null, <plugin options>, <sampling interval>) from rdb$database;

-- timed statement

execute procedure rdb$profiler.finish_session(true);

Tests

1. PSQL loop

Per-statement cost.

execute block as
    declare i integer = 0;
begin
    while (i < 10000000) do
        i = i + 1;
end

2. SELECT

Per-fetch cost of a record source tree.

select count(*)
  from (select 1 x
          from rdb$types a
          cross join rdb$types b
          cross join rdb$types c
          rows 3000000);

3. Procedure calls

Per-request cost: request start/finish, the plugin's request calls and the counter arrays.

create procedure p_nop as
begin
end;

execute block as
    declare i integer = 0;
begin
    while (i < 1000000) do
    begin
        execute procedure p_nop;
        i = i + 1;
    end
end

4. PSQL cursor

Per-fetch cost of a PSQL cursor, which looks up its statement through the statement cache.

execute block as
    declare i integer = 0;
    declare x integer;
begin
    for select 1
          from rdb$types a
          cross join rdb$types b
          cross join rdb$types c
          rows 3000000
          into x
    do
        i = i + 1;
end

5. Join + group by, profiler off

Cost of the record source path with no profiler session. This checks that profiling support doesn't slow down unprofiled queries. It runs in the off mode only.

-- setup (not timed)
create table t1 (id integer not null primary key, v integer);
create table t2 (id integer not null primary key, v integer);

execute block as
    declare i integer = 0;
begin
    while (i < 1000000) do
    begin
        insert into t1 values (:i, :i);
        insert into t2 values (:i, :i);
        i = i + 1;
    end
end;

commit;

-- timed
select mod(t1.v, 100), count(*)
  from t1
  join t2 on t2.id = t1.id
  group by 1;

[asfernandes]

Test results

Times are median seconds of 10 runs. Overhead is the profiled time minus the off time of the same build. The change compares the branch overhead with the master overhead of the same mode. Sampled modes, which master doesn't have, are compared with master's measured mode, the only one master has. The off rows compare the times.

Test	Mode	master	branch	master overhead	branch overhead	Change
PSQL loop	off	0.641	0.618	–	–	-3.6%
PSQL loop	measured	1.558	1.492	0.917	0.874	-4.7%
PSQL loop	sampled 1000 µs	–	0.698	–	0.080	-91.2%
PSQL loop	sampled 100 µs	–	0.701	–	0.083	-90.9%
PSQL loop	sampled 50 µs	–	0.702	–	0.084	-90.8%
PSQL loop	DETAILED_REQUESTS	1.562	0.696	0.921	0.078	-91.5%
SELECT	off	0.319	0.304	–	–	-4.5%
SELECT	measured	0.845	0.810	0.526	0.505	-4.0%
SELECT	sampled 1000 µs	–	0.370	–	0.066	-87.5%
SELECT	sampled 100 µs	–	0.373	–	0.069	-86.9%
SELECT	sampled 50 µs	–	0.370	–	0.066	-87.5%
SELECT	DETAILED_REQUESTS	0.857	0.369	0.538	0.065	-88.0%
Procedure calls	off	0.384	0.353	–	–	-8.1%
Procedure calls	measured	0.839	0.732	0.455	0.379	-16.6%
Procedure calls	sampled 1000 µs	–	0.529	–	0.176	-61.3%
Procedure calls	sampled 100 µs	–	0.533	–	0.180	-60.4%
Procedure calls	sampled 50 µs	–	0.542	–	0.189	-58.5%
Procedure calls	DETAILED_REQUESTS	1.193	0.760	0.809	0.407	-49.6%
PSQL cursor	off	0.583	0.521	–	–	-10.6%
PSQL cursor	measured	1.762	1.506	1.179	0.985	-16.4%
PSQL cursor	sampled 1000 µs	–	0.683	–	0.162	-86.3%
PSQL cursor	sampled 100 µs	–	0.683	–	0.162	-86.3%
PSQL cursor	sampled 50 µs	–	0.685	–	0.164	-86.1%
PSQL cursor	DETAILED_REQUESTS	1.732	0.684	1.149	0.163	-85.8%
Join + group by	off	1.359	1.343	–	–	-1.2%

Profiled time / off time:

Test	master (measured)	branch (sampled 100 µs, default)
PSQL loop	2.43	1.13
SELECT	2.65	1.23
Procedure calls	2.18	1.51
PSQL cursor	3.02	1.31

[asfernandes]

Conclusions

• Sampled mode: compared with master's profiling, the default sampled mode (100 µs) cuts the overhead by 87–91% for statements and fetches, and by 60% for very short procedure calls. A profiled run takes 1.13–1.31x the unprofiled time, and 1.51x for 1M empty procedure calls, compared with 2.2–3.0x on master.
• Sampling interval:
  • The overhead is the same from 1000 to 50 µs within the run-to-run spread, so 100 µs, the default, gives 10x the samples of 1000 µs, and so more precise times for short items, at no extra cost.
  • At 50 µs, the minimum, only the procedure-call test showed a higher overhead, by 7%. That is still 58% below master.
• Measured mode: it reports times within a few percent of the unprofiled times, and its overhead is 4–17% lower than master's, which reports wrong times.
• Profiler off: the branch is not slower than master: 4–11% faster in the PSQL and SELECT tests and 1% faster in the join. The PSQL cursor gains the most.