Firebird 5 profiler error with subselects

[tonne1]

Testing profiler with WI-T5.0.0.973 Firebid 5.0 Beta 1. It seems to handle subselects incorrectly. This test case

`set term !;
execute block
as
declare dummy varchar(200);
declare num bigint;
begin
select rdb$profiler.start_session('Profile Session 1') from rdb$database into :num;

num = 1;
if (:num in (select rdb$linger from rdb$database)) then
dummy = 'xxx';

execute procedure rdb$profiler.finish_session(true);
end!
set term ;!`

fails to write profile data to the snapshot tables and creates a message in firebird.log like e.g.:

Profiler flush
violation of FOREIGN KEY constraint "PLG$PROF_RECORD_SOURCES_CURSOR_FK" on table "PLG$PROF_RECORD_SOURCES"
Foreign key reference target does not exist
Problematic key value is ("PROFILE_ID" = 56, "STATEMENT_ID" = 41327, "CURSOR_ID" = 2)

[asfernandes]

Please test in next snapshot.

[tonne1]

Testing WI-T5.0.0.1035 Firebid 5.0 Beta 2. The profiler runs without errors now, even with complex SPs, which use dozens of other SPs and recursion, great, thanks!

Please include a simple evaluation example in the release notes on how to interprete records and numbers. Right now I can't tell if the reported numbers are plausible. For example, a test run of a SP needed a total execution time of 344 milliseconds as reported by the dba tool (Flamerobin) , but the biggest total_elapsed_time reported by
select * from plg$prof_statement_stats_view
was 16719430 for that SP.
which does not match the total execution time of 344 milliseconds anywhere near. The second biggest value was 3125539 and more plausible.

Similar, the same test:
select * from plg$prof_psql_stats_view
gives 10593129 as the biggest total_elapsed_time for the test run. The second biggest value 3017511 is more plausible.

I assume precision is 100 nanoseconds? plg$prof_sessions was always emptied before the test, only data of a single session was present. Should I post a new issue and test case?

[asfernandes]

The timings are nanosecond-based. My tests based on https://github.com/FirebirdSQL/firebird/blob/master/doc/sql.extensions/README.profiler.md shows correct timings.

If yours don't, post a reproducible test case with your timings and detailed explanations of what is not matching.

[tonne1]

1. I increased the loop counter in your example from 1000 to 100000 so the SP needs more time

CREATE PROCEDURE INS
AS
declare n integer = 1;
begin
    while (n <= 100000)
    do
    begin
        if (mod(n, 2) = 1) then
            insert into tab values (:n, mult(:n, 2));
        n = n + 1;
    end
end
^
SET TERM ; ^

2. Then ran the test and committed each action

select rdb$profiler.start_session('Profile Session 1') from rdb$database;
commit;

set term !;

execute block
as
begin
    execute procedure ins;
    delete from tab;
end!

set term ;!
commit;

execute procedure rdb$profiler.finish_session(true);
commit;

Flamerobin reported the execution time of the EB as 1.427 seconds:

...
execute block
as
begin
    execute procedure ins;
    delete from tab;
end
Statement prepared (elapsed time: 0.002s).
-- line 7, column 5
PLAN (TAB NATURAL)
Parameters: 0


Executing statement...
Statement executed (elapsed time: 1.427s).               <======= 
648493 fetches, 201882 marks, 380 reads, 558 writes.
50000 inserts, 0 updates, 50000 deletes, 27 index, 50003 seq.
Delta memory: 1341888 bytes.
TAB: 50000 inserts. 50000 deletes. 
0 rows affected directly.
Total execution time: 1.439s
Committing transaction...
Transaction committed (elapsed time: 0.020s).
...

Now I tried to find that value of 1.427 seconds somewehere in the profiler stats. The closest match is in 

select preq.*, 
datediff(millisecond, preq.start_timestamp, preq.finish_timestamp) / 1000.000 dif_sec,
preq.total_elapsed_time / 1000000000.000000 tet_sec
  from plg$prof_requests preq
  join plg$prof_sessions pses
    on pses.profile_id = preq.profile_id and
       pses.description = 'Profile Session 1'

which I extended to show the timing in seconds. 
dif_sec is simply the time difference between start and fiinish timestamp.
tet_sec is preq.total_elapsed_time divided by 10^9 to get seconds from nanoseconds.

Those two should roughly match I assume, but they don't. Only when I multiply tet_sec by 100, 
I get a matching value. That's why I have the impression that timing is in 100 nanoseconds. 

[asfernandes]

select *
  from plg$prof_requests
  where statement_id = (select statement_id from plg$prof_statements where sql_text starting 'execute block')

I get 1303032597, which matches my execution time of ~1.3s.

Don't it work this way for you?

What's your OS?

[asfernandes]

I was testing in Linux. Now I see that in Windows precision is different.
Please create new issue.

[asfernandes]

Fixed in #7562

[tonne1]

Done in #7563.