Check firebird.log [no messages found for interval when this test was running]
Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
2 @message
assert   
    Sub-query (invariant)
    ....-> Filter
    ........-> Aggregate
    ............-> Table "TDETL" as "K DY" Access By ID
    ................-> Index "TDETL_FK" Full Scan
    Cursor "K"(line, column)
    ....-> Filter (preliminary)
    ........-> Nested Loop Join (inner)
    ............-> Table "TMAIN" as "K M4" Full Scan
    ............-> Filter
    ................-> Table "TDETL" as "K D4 DX" Access By ID
    ....................-> Bitmap And
    ........................-> Bitmap And
    ............................-> Bitmap
    ................................-> Index "TDETL_Z" Range Scan (lower bound: 1/1)
    ............................-> Bitmap
    ................................-> Index "TDETL_Y" Range Scan (upper bound: 1/1)
    ........................-> Bitmap
    ............................-> Index "TDETL_FK" Range Scan (full match)
    Sub-query
    ....-> Filter
    ........-> Table "TMAIN" as "M0" Access By ID
    ............-> Bitmap
    ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
    Sub-query
    ....-> Filter
    ........-> Table "TMAIN" as "R M0A" Access By ID
  - ............-> Bitmap
  + ............-> Bitmap Or
  + ................-> Bitmap
  - ................-> Index "TMAIN_X" List Scan (full match)
  + ....................-> Index "TMAIN_X" Range Scan (full match)
  + ................-> Bitmap
  + ....................-> Index "TMAIN_X" Range Scan (full match)
    Select Expression(line, column)
    ....-> Singularity Check
    ........-> Aggregate
    ............-> Filter
    ................-> Recursion
    ....................-> Filter
    ........................-> Table "TDETL" as "R D0" Access By ID
    ............................-> Bitmap
    ................................-> Index "TDETL_FK" Range Scan (full match)
    ....................-> Filter
    ........................-> Table "TDETL" as "R DX" Access By ID
    ............................-> Bitmap
    ................................-> Index "TDETL_FK" Range Scan (full match)
    Sub-query(line, column)
    ....-> Singularity Check
    ........-> Aggregate
    ............-> Table "TMAIN" as "M1A" Full Scan
    Sub-query(line, column)
    ....-> Singularity Check
    ........-> Aggregate
    ............-> Table "TMAIN" as "M1B" Access By ID
    ................-> Index "TMAIN_X" Full Scan
    Sub-query(line, column)
    ....-> Singularity Check
    ........-> Aggregate
    ............-> Table "TDETL" as "D1B" Access By ID
    ................-> Index "TDETL_FK" Full Scan
    Sub-query(line, column)
    ....-> Singularity Check
    ........-> Aggregate
    ............-> Table "TDETL" as "D1C" Full Scan
    Select Expression(line, column)
    ....-> Aggregate
    ........-> Nested Loop Join (inner)
    ............-> Filter
    ................-> Table "TMAIN" as "M2" Access By ID
    ....................-> Index "TMAIN_PK" Full Scan
    ........................-> Bitmap
    ............................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
    ............-> Filter
    ................-> Table "TDETL" as "D" Access By ID
    ....................-> Bitmap
    ........................-> Index "TDETL_PK" Unique Scan
    Sub-query
    ....-> Filter
    ........-> Table "TDETL" as "D" Access By ID
    ............-> Bitmap
    ................-> Index "TDETL_FK" Range Scan (full match)
    Select Expression(line, column)
    ....-> Filter
    ........-> Table "TMAIN" as "M3" Access By ID
    ............-> Bitmap
    ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
    ......0 ms

LOG DETAILS:

2024-12-24 23:47:15.181
2024-12-24 23:47:15.185 act = <firebird.qa.plugin.Action object at [hex]>
2024-12-24 23:47:15.191 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-12-24 23:47:15.195
2024-12-24 23:47:15.200 @pytest.mark.trace
2024-12-24 23:47:15.205 @pytest.mark.version('>=5.0')
2024-12-24 23:47:15.209 def test_1(act: Action, capsys):
2024-12-24 23:47:15.214
2024-12-24 23:47:15.219 test_script = f"""
2024-12-24 23:47:15.223 recreate table tdetl(id int);
2024-12-24 23:47:15.228 recreate table tmain(id int primary key using index tmain_pk, x int);
2024-12-24 23:47:15.233 recreate table tdetl(id int primary key using index tdetl_pk, pid int references tmain using index tdetl_fk, y int, z int);
2024-12-24 23:47:15.237
2024-12-24 23:47:15.242 insert into tmain(id,x)
2024-12-24 23:47:15.247 select i, -100 + mod(i,200) from (select row_number()over() i from rdb$types rows 200);
2024-12-24 23:47:15.251
2024-12-24 23:47:15.256 insert into tdetl(id, pid, y,z)
2024-12-24 23:47:15.261 select i, 1+mod(i,10), mod(i,30), mod(i,70) from (select row_number()over() i from rdb$types,rdb$types rows 1000);
2024-12-24 23:47:15.266 commit;
2024-12-24 23:47:15.270
2024-12-24 23:47:15.275 create index tmain_x on tmain(x);
2024-12-24 23:47:15.280 create index tdetl_y on tdetl(y);
2024-12-24 23:47:15.285 create index tdetl_z on tdetl(z);
2024-12-24 23:47:15.291
2024-12-24 23:47:15.296 set statistics index tdetl_fk;
2024-12-24 23:47:15.302 commit;
2024-12-24 23:47:15.307
2024-12-24 23:47:15.312 set term ^;
2024-12-24 23:47:15.317 create or alter procedure sp_test returns(id int, c int)
2024-12-24 23:47:15.322 as
2024-12-24 23:47:15.327 declare k cursor for (
2024-12-24 23:47:15.332 select m4.id, d4.y, d4.z
2024-12-24 23:47:15.337 from tmain m4
2024-12-24 23:47:15.343 cross join lateral (
2024-12-24 23:47:15.348 select y, z
2024-12-24 23:47:15.353 from tdetl dx
2024-12-24 23:47:15.358 where
2024-12-24 23:47:15.363 dx.pid = m4.id
2024-12-24 23:47:15.368 and m4.x between dx.y and dx.z
2024-12-24 23:47:15.373 ) d4
2024-12-24 23:47:15.378 where exists(select count(*) from tdetl dy group by dy.pid having count(*) > 2)
2024-12-24 23:47:15.382 );
2024-12-24 23:47:15.387 begin
2024-12-24 23:47:15.392
2024-12-24 23:47:15.397 if ( not exists(select * from tmain m0 where m0.x > 0) ) then
2024-12-24 23:47:15.403 exception;
2024-12-24 23:47:15.408
2024-12-24 23:47:15.413 ----------------------------
2024-12-24 23:47:15.418
2024-12-24 23:47:15.422 with recursive
2024-12-24 23:47:15.427 r as (
2024-12-24 23:47:15.432 select 0 as i, d0.id, d0.pid
2024-12-24 23:47:15.437 from tdetl d0
2024-12-24 23:47:15.441 where d0.pid is null
2024-12-24 23:47:15.446 UNION ALL
2024-12-24 23:47:15.451 select r.i + 1, dx.id, dx.pid
2024-12-24 23:47:15.456 from tdetl dx
2024-12-24 23:47:15.461 join r on dx.pid = r.id
2024-12-24 23:47:15.466 where exists(
2024-12-24 23:47:15.470 select * from tmain m0a
2024-12-24 23:47:15.475 where
2024-12-24 23:47:15.480 m0a.id <> dx.pid
2024-12-24 23:47:15.486 -- ::: NB ::: Rest part is IN-list with computable but non-invariant elements.
2024-12-24 23:47:15.491 -- Execution plan for this kind was changed 07-sep-2023, see:
2024-12-24 23:47:15.496 -- https://github.com/FirebirdSQL/firebird/commit/5df6668c7bf5a4b27e15f687f8c6cc40e260ced8
2024-12-24 23:47:15.501 -- (Allow computable but non-invariant lists to be used for index lookup)
2024-12-24 23:47:15.505 -- See also: tests/functional/tabloid/test_e260ced8.py
2024-12-24 23:47:15.510 -- Here "Index "TMAIN_X" List Scan (full match)" will be!
2024-12-24 23:47:15.515 -- Old: "Index "TMAIN_X" Range Scan (full match)"
2024-12-24 23:47:15.520 and m0a.x in (dx.y, dx.z) -- ### ATTENTION ###
2024-12-24 23:47:15.525 )
2024-12-24 23:47:15.529 )
2024-12-24 23:47:15.534 select count(*) from r where r.i > 2
2024-12-24 23:47:15.539 into c;
2024-12-24 23:47:15.543
2024-12-24 23:47:15.548 ----------------------------
2024-12-24 23:47:15.553 c = decode( (select mod(count(*), 3) from tmain m1a)
2024-12-24 23:47:15.557 ,0, (select min(x) from tmain m1b)
2024-12-24 23:47:15.562 ,1, (select min(d1b.pid) from tdetl d1b)
2024-12-24 23:47:15.566 ,2, (select max(d1c.pid) from tdetl d1c)
2024-12-24 23:47:15.571 );
2024-12-24 23:47:15.575
2024-12-24 23:47:15.580 ----------------------------
2024-12-24 23:47:15.584 for
2024-12-24 23:47:15.589 select m2.id, count(*)
2024-12-24 23:47:15.594 from tmain m2
2024-12-24 23:47:15.598 join tdetl d using(id)
2024-12-24 23:47:15.603 where m2.x > 0
2024-12-24 23:47:15.607 group by 1
2024-12-24 23:47:15.612 into id, c
2024-12-24 23:47:15.616 do
2024-12-24 23:47:15.621 suspend;
2024-12-24 23:47:15.625 ----------------------------
2024-12-24 23:47:15.630 for
2024-12-24 23:47:15.634 select m3.id, 0
2024-12-24 23:47:15.639 from tmain m3
2024-12-24 23:47:15.643 where
2024-12-24 23:47:15.648 m3.x > 0 and
2024-12-24 23:47:15.652 not exists(select * from tdetl d where d.pid = m3.id)
2024-12-24 23:47:15.657 into id, c
2024-12-24 23:47:15.662 do
2024-12-24 23:47:15.666 suspend;
2024-12-24 23:47:15.671 end
2024-12-24 23:47:15.676 ^
2024-12-24 23:47:15.680 set term ;^
2024-12-24 23:47:15.685 commit;
2024-12-24 23:47:15.689 """
2024-12-24 23:47:15.694
2024-12-24 23:47:15.698 with act.trace(db_events=trace, encoding = locale.getpreferredencoding(), encoding_errors='utf8'):
2024-12-24 23:47:15.703 act.isql(switches = ['-q'], input = test_script, combine_output = True, io_enc = locale.getpreferredencoding())
2024-12-24 23:47:15.708
2024-12-24 23:47:15.712 # Parse trace log:
2024-12-24 23:47:15.717 start_show = 0
2024-12-24 23:47:15.722 for line in act.trace_log:
2024-12-24 23:47:15.727 if line.startswith("^^^"):
2024-12-24 23:47:15.733 start_show = 1
2024-12-24 23:47:15.739 continue
2024-12-24 23:47:15.745 if start_show and line.rstrip():
2024-12-24 23:47:15.751 print( replace_leading(line,'.') )
2024-12-24 23:47:15.756
2024-12-24 23:47:15.761 expected_stdout = f"""
2024-12-24 23:47:15.766 Sub-query (invariant)
2024-12-24 23:47:15.771 ....-> Filter
2024-12-24 23:47:15.780 ........-> Aggregate
2024-12-24 23:47:15.789 ............-> Table "TDETL" as "K DY" Access By ID
2024-12-24 23:47:15.796 ................-> Index "TDETL_FK" Full Scan
2024-12-24 23:47:15.801 Cursor "K"(line, column)
2024-12-24 23:47:15.807 ....-> Filter (preliminary)
2024-12-24 23:47:15.813 ........-> Nested Loop Join (inner)
2024-12-24 23:47:15.818 ............-> Table "TMAIN" as "K M4" Full Scan
2024-12-24 23:47:15.823 ............-> Filter
2024-12-24 23:47:15.829 ................-> Table "TDETL" as "K D4 DX" Access By ID
2024-12-24 23:47:15.834 ....................-> Bitmap And
2024-12-24 23:47:15.838 ........................-> Bitmap And
2024-12-24 23:47:15.846 ............................-> Bitmap
2024-12-24 23:47:15.857 ................................-> Index "TDETL_Z" Range Scan (lower bound: 1/1)
2024-12-24 23:47:15.865 ............................-> Bitmap
2024-12-24 23:47:15.871 ................................-> Index "TDETL_Y" Range Scan (upper bound: 1/1)
2024-12-24 23:47:15.879 ........................-> Bitmap
2024-12-24 23:47:15.887 ............................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:15.893 Sub-query
2024-12-24 23:47:15.899 ....-> Filter
2024-12-24 23:47:15.905 ........-> Table "TMAIN" as "M0" Access By ID
2024-12-24 23:47:15.911 ............-> Bitmap
2024-12-24 23:47:15.918 ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
2024-12-24 23:47:15.925 Sub-query
2024-12-24 23:47:15.931 ....-> Filter
2024-12-24 23:47:15.938 ........-> Table "TMAIN" as "R M0A" Access By ID
2024-12-24 23:47:15.945 ............-> Bitmap
2024-12-24 23:47:15.951 ................-> Index "TMAIN_X" List Scan (full match)
2024-12-24 23:47:15.957 Select Expression(line, column)
2024-12-24 23:47:15.963 ....-> Singularity Check
2024-12-24 23:47:15.970 ........-> Aggregate
2024-12-24 23:47:15.975 ............-> Filter
2024-12-24 23:47:15.980 ................-> Recursion
2024-12-24 23:47:15.987 ....................-> Filter
2024-12-24 23:47:15.994 ........................-> Table "TDETL" as "R D0" Access By ID
2024-12-24 23:47:16.000 ............................-> Bitmap
2024-12-24 23:47:16.005 ................................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.011 ....................-> Filter
2024-12-24 23:47:16.016 ........................-> Table "TDETL" as "R DX" Access By ID
2024-12-24 23:47:16.022 ............................-> Bitmap
2024-12-24 23:47:16.027 ................................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.034 Sub-query(line, column)
2024-12-24 23:47:16.042 ....-> Singularity Check
2024-12-24 23:47:16.049 ........-> Aggregate
2024-12-24 23:47:16.056 ............-> Table "TMAIN" as "M1A" Full Scan
2024-12-24 23:47:16.062 Sub-query(line, column)
2024-12-24 23:47:16.069 ....-> Singularity Check
2024-12-24 23:47:16.074 ........-> Aggregate
2024-12-24 23:47:16.080 ............-> Table "TMAIN" as "M1B" Access By ID
2024-12-24 23:47:16.086 ................-> Index "TMAIN_X" Full Scan
2024-12-24 23:47:16.092 Sub-query(line, column)
2024-12-24 23:47:16.097 ....-> Singularity Check
2024-12-24 23:47:16.103 ........-> Aggregate
2024-12-24 23:47:16.109 ............-> Table "TDETL" as "D1B" Access By ID
2024-12-24 23:47:16.115 ................-> Index "TDETL_FK" Full Scan
2024-12-24 23:47:16.120 Sub-query(line, column)
2024-12-24 23:47:16.125 ....-> Singularity Check
2024-12-24 23:47:16.131 ........-> Aggregate
2024-12-24 23:47:16.136 ............-> Table "TDETL" as "D1C" Full Scan
2024-12-24 23:47:16.142 Select Expression(line, column)
2024-12-24 23:47:16.149 ....-> Aggregate
2024-12-24 23:47:16.154 ........-> Nested Loop Join (inner)
2024-12-24 23:47:16.159 ............-> Filter
2024-12-24 23:47:16.165 ................-> Table "TMAIN" as "M2" Access By ID
2024-12-24 23:47:16.174 ....................-> Index "TMAIN_PK" Full Scan
2024-12-24 23:47:16.181 ........................-> Bitmap
2024-12-24 23:47:16.188 ............................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
2024-12-24 23:47:16.193 ............-> Filter
2024-12-24 23:47:16.199 ................-> Table "TDETL" as "D" Access By ID
2024-12-24 23:47:16.203 ....................-> Bitmap
2024-12-24 23:47:16.209 ........................-> Index "TDETL_PK" Unique Scan
2024-12-24 23:47:16.214 Sub-query
2024-12-24 23:47:16.219 ....-> Filter
2024-12-24 23:47:16.224 ........-> Table "TDETL" as "D" Access By ID
2024-12-24 23:47:16.231 ............-> Bitmap
2024-12-24 23:47:16.238 ................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.245 Select Expression(line, column)
2024-12-24 23:47:16.250 ....-> Filter
2024-12-24 23:47:16.256 ........-> Table "TMAIN" as "M3" Access By ID
2024-12-24 23:47:16.261 ............-> Bitmap
2024-12-24 23:47:16.266 ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
2024-12-24 23:47:16.272 ......0 ms
2024-12-24 23:47:16.277 """
2024-12-24 23:47:16.283
2024-12-24 23:47:16.289 act.expected_stdout = expected_stdout
2024-12-24 23:47:16.295 act.stdout = capsys.readouterr().out
2024-12-24 23:47:16.301 >       assert act.clean_stdout == act.clean_expected_stdout
2024-12-24 23:47:16.309 E       assert
2024-12-24 23:47:16.315 E           Sub-query (invariant)
2024-12-24 23:47:16.321 E           ....-> Filter
2024-12-24 23:47:16.326 E           ........-> Aggregate
2024-12-24 23:47:16.333 E           ............-> Table "TDETL" as "K DY" Access By ID
2024-12-24 23:47:16.339 E           ................-> Index "TDETL_FK" Full Scan
2024-12-24 23:47:16.345 E           Cursor "K"(line, column)
2024-12-24 23:47:16.350 E           ....-> Filter (preliminary)
2024-12-24 23:47:16.357 E           ........-> Nested Loop Join (inner)
2024-12-24 23:47:16.364 E           ............-> Table "TMAIN" as "K M4" Full Scan
2024-12-24 23:47:16.370 E           ............-> Filter
2024-12-24 23:47:16.376 E           ................-> Table "TDETL" as "K D4 DX" Access By ID
2024-12-24 23:47:16.384 E           ....................-> Bitmap And
2024-12-24 23:47:16.393 E           ........................-> Bitmap And
2024-12-24 23:47:16.399 E           ............................-> Bitmap
2024-12-24 23:47:16.406 E           ................................-> Index "TDETL_Z" Range Scan (lower bound: 1/1)
2024-12-24 23:47:16.411 E           ............................-> Bitmap
2024-12-24 23:47:16.418 E           ................................-> Index "TDETL_Y" Range Scan (upper bound: 1/1)
2024-12-24 23:47:16.425 E           ........................-> Bitmap
2024-12-24 23:47:16.432 E           ............................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.440 E           Sub-query
2024-12-24 23:47:16.446 E           ....-> Filter
2024-12-24 23:47:16.452 E           ........-> Table "TMAIN" as "M0" Access By ID
2024-12-24 23:47:16.458 E           ............-> Bitmap
2024-12-24 23:47:16.463 E           ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
2024-12-24 23:47:16.468 E           Sub-query
2024-12-24 23:47:16.473 E           ....-> Filter
2024-12-24 23:47:16.478 E           ........-> Table "TMAIN" as "R M0A" Access By ID
2024-12-24 23:47:16.483 E         - ............-> Bitmap
2024-12-24 23:47:16.491 E         + ............-> Bitmap Or
2024-12-24 23:47:16.505 E         + ................-> Bitmap
2024-12-24 23:47:16.511 E         - ................-> Index "TMAIN_X" List Scan (full match)
2024-12-24 23:47:16.522 E         + ....................-> Index "TMAIN_X" Range Scan (full match)
2024-12-24 23:47:16.532 E         + ................-> Bitmap
2024-12-24 23:47:16.538 E         + ....................-> Index "TMAIN_X" Range Scan (full match)
2024-12-24 23:47:16.543 E           Select Expression(line, column)
2024-12-24 23:47:16.548 E           ....-> Singularity Check
2024-12-24 23:47:16.558 E           ........-> Aggregate
2024-12-24 23:47:16.567 E           ............-> Filter
2024-12-24 23:47:16.573 E           ................-> Recursion
2024-12-24 23:47:16.581 E           ....................-> Filter
2024-12-24 23:47:16.588 E           ........................-> Table "TDETL" as "R D0" Access By ID
2024-12-24 23:47:16.596 E           ............................-> Bitmap
2024-12-24 23:47:16.605 E           ................................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.612 E           ....................-> Filter
2024-12-24 23:47:16.620 E           ........................-> Table "TDETL" as "R DX" Access By ID
2024-12-24 23:47:16.627 E           ............................-> Bitmap
2024-12-24 23:47:16.635 E           ................................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.648 E           Sub-query(line, column)
2024-12-24 23:47:16.657 E           ....-> Singularity Check
2024-12-24 23:47:16.666 E           ........-> Aggregate
2024-12-24 23:47:16.675 E           ............-> Table "TMAIN" as "M1A" Full Scan
2024-12-24 23:47:16.683 E           Sub-query(line, column)
2024-12-24 23:47:16.689 E           ....-> Singularity Check
2024-12-24 23:47:16.694 E           ........-> Aggregate
2024-12-24 23:47:16.699 E           ............-> Table "TMAIN" as "M1B" Access By ID
2024-12-24 23:47:16.704 E           ................-> Index "TMAIN_X" Full Scan
2024-12-24 23:47:16.709 E           Sub-query(line, column)
2024-12-24 23:47:16.714 E           ....-> Singularity Check
2024-12-24 23:47:16.719 E           ........-> Aggregate
2024-12-24 23:47:16.725 E           ............-> Table "TDETL" as "D1B" Access By ID
2024-12-24 23:47:16.734 E           ................-> Index "TDETL_FK" Full Scan
2024-12-24 23:47:16.740 E           Sub-query(line, column)
2024-12-24 23:47:16.747 E           ....-> Singularity Check
2024-12-24 23:47:16.753 E           ........-> Aggregate
2024-12-24 23:47:16.759 E           ............-> Table "TDETL" as "D1C" Full Scan
2024-12-24 23:47:16.764 E           Select Expression(line, column)
2024-12-24 23:47:16.769 E           ....-> Aggregate
2024-12-24 23:47:16.774 E           ........-> Nested Loop Join (inner)
2024-12-24 23:47:16.780 E           ............-> Filter
2024-12-24 23:47:16.785 E           ................-> Table "TMAIN" as "M2" Access By ID
2024-12-24 23:47:16.790 E           ....................-> Index "TMAIN_PK" Full Scan
2024-12-24 23:47:16.796 E           ........................-> Bitmap
2024-12-24 23:47:16.802 E           ............................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
2024-12-24 23:47:16.809 E           ............-> Filter
2024-12-24 23:47:16.818 E           ................-> Table "TDETL" as "D" Access By ID
2024-12-24 23:47:16.823 E           ....................-> Bitmap
2024-12-24 23:47:16.829 E           ........................-> Index "TDETL_PK" Unique Scan
2024-12-24 23:47:16.835 E           Sub-query
2024-12-24 23:47:16.843 E           ....-> Filter
2024-12-24 23:47:16.850 E           ........-> Table "TDETL" as "D" Access By ID
2024-12-24 23:47:16.855 E           ............-> Bitmap
2024-12-24 23:47:16.863 E           ................-> Index "TDETL_FK" Range Scan (full match)
2024-12-24 23:47:16.870 E           Select Expression(line, column)
2024-12-24 23:47:16.876 E           ....-> Filter
2024-12-24 23:47:16.881 E           ........-> Table "TMAIN" as "M3" Access By ID
2024-12-24 23:47:16.887 E           ............-> Bitmap
2024-12-24 23:47:16.892 E           ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
2024-12-24 23:47:16.897 E           ......0 ms
2024-12-24 23:47:16.902
2024-12-24 23:47:16.907 tests/bugs/gh_7466_plans_tracking_test.py:280: AssertionError
2024-12-24 23:47:16.912 ---------------------------- Captured stdout setup -----------------------------
2024-12-24 23:47:16.917 Creating db: localhost:/var/tmp/qa_2024/test_11546/test.fdb [page_size=None, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.trace
    @pytest.mark.version('>=5.0')
    def test_1(act: Action, capsys):
    
        test_script = f"""
            recreate table tdetl(id int);
            recreate table tmain(id int primary key using index tmain_pk, x int);
            recreate table tdetl(id int primary key using index tdetl_pk, pid int references tmain using index tdetl_fk, y int, z int);
    
            insert into tmain(id,x)
            select i, -100 + mod(i,200) from (select row_number()over() i from rdb$types rows 200);
    
            insert into tdetl(id, pid, y,z)
            select i, 1+mod(i,10), mod(i,30), mod(i,70) from (select row_number()over() i from rdb$types,rdb$types rows 1000);
            commit;
    
            create index tmain_x on tmain(x);
            create index tdetl_y on tdetl(y);
            create index tdetl_z on tdetl(z);
    
            set statistics index tdetl_fk;
            commit;
    
            set term ^;
            create or alter procedure sp_test returns(id int, c int)
            as
                declare k cursor for (
                    select m4.id, d4.y, d4.z
                    from tmain m4
                    cross join lateral (
                        select y, z
                        from tdetl dx
                        where
                            dx.pid = m4.id
                            and m4.x between dx.y and dx.z
                    ) d4
                    where exists(select count(*) from tdetl dy group by dy.pid having count(*) > 2)
                );
            begin
    
                if ( not exists(select * from tmain m0 where m0.x > 0) ) then
                    exception;
    
                ----------------------------
    
                with recursive
                r as (
                   select 0 as i, d0.id, d0.pid
                   from tdetl d0
                   where d0.pid is null
                   UNION ALL
                   select r.i + 1, dx.id, dx.pid
                   from tdetl dx
                   join r on dx.pid = r.id
                   where exists(
                       select * from tmain m0a
                       where
                           m0a.id <> dx.pid
                           -- ::: NB ::: Rest part is IN-list with computable but non-invariant elements.
                           -- Execution plan for this kind was changed 07-sep-2023, see:
                           -- https://github.com/FirebirdSQL/firebird/commit/5df6668c7bf5a4b27e15f687f8c6cc40e260ced8
                           -- (Allow computable but non-invariant lists to be used for index lookup)
                           -- See also: tests/functional/tabloid/test_e260ced8.py
                           -- Here "Index "TMAIN_X" List Scan (full match)" will be!
                           -- Old: "Index "TMAIN_X" Range Scan (full match)"
                           and m0a.x in (dx.y, dx.z) -- ### ATTENTION ###
                   )
                )
                select count(*) from r where r.i > 2
                into c;
    
                ----------------------------
                c = decode( (select mod(count(*), 3) from tmain m1a)
                            ,0, (select min(x) from tmain m1b)
                            ,1, (select min(d1b.pid) from tdetl d1b)
                            ,2, (select max(d1c.pid) from tdetl d1c)
                    );
    
                ----------------------------
                for
                    select m2.id, count(*)
                    from tmain m2
                    join tdetl d using(id)
                    where m2.x > 0
                    group by 1
                    into id, c
                do
                    suspend;
                ----------------------------
                for
                    select m3.id, 0
                    from tmain m3
                    where
                        m3.x > 0 and
                        not exists(select * from tdetl d where d.pid = m3.id)
                    into id, c
                do
                    suspend;
            end
            ^
            set term ;^
            commit;
        """
    
        with act.trace(db_events=trace, encoding = locale.getpreferredencoding(), encoding_errors='utf8'):
            act.isql(switches = ['-q'], input = test_script, combine_output = True, io_enc = locale.getpreferredencoding())
    
        # Parse trace log:
        start_show = 0
        for line in act.trace_log:
            if line.startswith("^^^"):
                start_show = 1
                continue
            if start_show and line.rstrip():
                print( replace_leading(line,'.') )
    
        expected_stdout = f"""
            Sub-query (invariant)
            ....-> Filter
            ........-> Aggregate
            ............-> Table "TDETL" as "K DY" Access By ID
            ................-> Index "TDETL_FK" Full Scan
            Cursor "K"(line, column)
            ....-> Filter (preliminary)
            ........-> Nested Loop Join (inner)
            ............-> Table "TMAIN" as "K M4" Full Scan
            ............-> Filter
            ................-> Table "TDETL" as "K D4 DX" Access By ID
            ....................-> Bitmap And
            ........................-> Bitmap And
            ............................-> Bitmap
            ................................-> Index "TDETL_Z" Range Scan (lower bound: 1/1)
            ............................-> Bitmap
            ................................-> Index "TDETL_Y" Range Scan (upper bound: 1/1)
            ........................-> Bitmap
            ............................-> Index "TDETL_FK" Range Scan (full match)
            Sub-query
            ....-> Filter
            ........-> Table "TMAIN" as "M0" Access By ID
            ............-> Bitmap
            ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
            Sub-query
            ....-> Filter
            ........-> Table "TMAIN" as "R M0A" Access By ID
            ............-> Bitmap
            ................-> Index "TMAIN_X" List Scan (full match)
            Select Expression(line, column)
            ....-> Singularity Check
            ........-> Aggregate
            ............-> Filter
            ................-> Recursion
            ....................-> Filter
            ........................-> Table "TDETL" as "R D0" Access By ID
            ............................-> Bitmap
            ................................-> Index "TDETL_FK" Range Scan (full match)
            ....................-> Filter
            ........................-> Table "TDETL" as "R DX" Access By ID
            ............................-> Bitmap
            ................................-> Index "TDETL_FK" Range Scan (full match)
            Sub-query(line, column)
            ....-> Singularity Check
            ........-> Aggregate
            ............-> Table "TMAIN" as "M1A" Full Scan
            Sub-query(line, column)
            ....-> Singularity Check
            ........-> Aggregate
            ............-> Table "TMAIN" as "M1B" Access By ID
            ................-> Index "TMAIN_X" Full Scan
            Sub-query(line, column)
            ....-> Singularity Check
            ........-> Aggregate
            ............-> Table "TDETL" as "D1B" Access By ID
            ................-> Index "TDETL_FK" Full Scan
            Sub-query(line, column)
            ....-> Singularity Check
            ........-> Aggregate
            ............-> Table "TDETL" as "D1C" Full Scan
            Select Expression(line, column)
            ....-> Aggregate
            ........-> Nested Loop Join (inner)
            ............-> Filter
            ................-> Table "TMAIN" as "M2" Access By ID
            ....................-> Index "TMAIN_PK" Full Scan
            ........................-> Bitmap
            ............................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
            ............-> Filter
            ................-> Table "TDETL" as "D" Access By ID
            ....................-> Bitmap
            ........................-> Index "TDETL_PK" Unique Scan
            Sub-query
            ....-> Filter
            ........-> Table "TDETL" as "D" Access By ID
            ............-> Bitmap
            ................-> Index "TDETL_FK" Range Scan (full match)
            Select Expression(line, column)
            ....-> Filter
            ........-> Table "TMAIN" as "M3" Access By ID
            ............-> Bitmap
            ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
            ......0 ms
        """
    
        act.expected_stdout = expected_stdout
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E           Sub-query (invariant)
E           ....-> Filter
E           ........-> Aggregate
E           ............-> Table "TDETL" as "K DY" Access By ID
E           ................-> Index "TDETL_FK" Full Scan
E           Cursor "K"(line, column)
E           ....-> Filter (preliminary)
E           ........-> Nested Loop Join (inner)
E           ............-> Table "TMAIN" as "K M4" Full Scan
E           ............-> Filter
E           ................-> Table "TDETL" as "K D4 DX" Access By ID
E           ....................-> Bitmap And
E           ........................-> Bitmap And
E           ............................-> Bitmap
E           ................................-> Index "TDETL_Z" Range Scan (lower bound: 1/1)
E           ............................-> Bitmap
E           ................................-> Index "TDETL_Y" Range Scan (upper bound: 1/1)
E           ........................-> Bitmap
E           ............................-> Index "TDETL_FK" Range Scan (full match)
E           Sub-query
E           ....-> Filter
E           ........-> Table "TMAIN" as "M0" Access By ID
E           ............-> Bitmap
E           ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
E           Sub-query
E           ....-> Filter
E           ........-> Table "TMAIN" as "R M0A" Access By ID
E         - ............-> Bitmap
E         + ............-> Bitmap Or
E         + ................-> Bitmap
E         - ................-> Index "TMAIN_X" List Scan (full match)
E         + ....................-> Index "TMAIN_X" Range Scan (full match)
E         + ................-> Bitmap
E         + ....................-> Index "TMAIN_X" Range Scan (full match)
E           Select Expression(line, column)
E           ....-> Singularity Check
E           ........-> Aggregate
E           ............-> Filter
E           ................-> Recursion
E           ....................-> Filter
E           ........................-> Table "TDETL" as "R D0" Access By ID
E           ............................-> Bitmap
E           ................................-> Index "TDETL_FK" Range Scan (full match)
E           ....................-> Filter
E           ........................-> Table "TDETL" as "R DX" Access By ID
E           ............................-> Bitmap
E           ................................-> Index "TDETL_FK" Range Scan (full match)
E           Sub-query(line, column)
E           ....-> Singularity Check
E           ........-> Aggregate
E           ............-> Table "TMAIN" as "M1A" Full Scan
E           Sub-query(line, column)
E           ....-> Singularity Check
E           ........-> Aggregate
E           ............-> Table "TMAIN" as "M1B" Access By ID
E           ................-> Index "TMAIN_X" Full Scan
E           Sub-query(line, column)
E           ....-> Singularity Check
E           ........-> Aggregate
E           ............-> Table "TDETL" as "D1B" Access By ID
E           ................-> Index "TDETL_FK" Full Scan
E           Sub-query(line, column)
E           ....-> Singularity Check
E           ........-> Aggregate
E           ............-> Table "TDETL" as "D1C" Full Scan
E           Select Expression(line, column)
E           ....-> Aggregate
E           ........-> Nested Loop Join (inner)
E           ............-> Filter
E           ................-> Table "TMAIN" as "M2" Access By ID
E           ....................-> Index "TMAIN_PK" Full Scan
E           ........................-> Bitmap
E           ............................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
E           ............-> Filter
E           ................-> Table "TDETL" as "D" Access By ID
E           ....................-> Bitmap
E           ........................-> Index "TDETL_PK" Unique Scan
E           Sub-query
E           ....-> Filter
E           ........-> Table "TDETL" as "D" Access By ID
E           ............-> Bitmap
E           ................-> Index "TDETL_FK" Range Scan (full match)
E           Select Expression(line, column)
E           ....-> Filter
E           ........-> Table "TMAIN" as "M3" Access By ID
E           ............-> Bitmap
E           ................-> Index "TMAIN_X" Range Scan (lower bound: 1/1)
E           ......0 ms

tests/bugs/gh_7466_plans_tracking_test.py:280: AssertionError
Full history of outcomes and elapsed time, ms:
NN SNAP_INFO CS_outcome SS_outcome CS_run_time SS_run_time CS_run_beg CS_run_end SS_run_beg SS_run_end
1 5.0.3.1674 2025.06.27 3ee5c P P 3383 2525 2025.06.30 12:44:23.341 2025.06.30 12:44:26.724 2025.06.30 11:24:39.461 2025.06.30 11:24:41.986
2 5.0.3.1657 2025.06.19 4bd4c P P 3083 2510 2025.06.27 12:16:38.133 2025.06.27 12:16:41.216 2025.06.27 10:58:42.817 2025.06.27 10:58:45.327
3 5.0.3.1657 2025.06.11 dae6f P P 3112 2535 2025.06.17 07:21:37.246 2025.06.17 07:21:40.358 2025.06.17 06:02:32.746 2025.06.17 06:02:35.281
4 5.0.3.1657 2025.06.10 dbc92 P P 3067 2572 2025.06.11 12:11:48.423 2025.06.11 12:11:51.490 2025.06.11 10:43:38.824 2025.06.11 10:43:41.396
5 5.0.3.1656 2025.05.20 c4b11 P P 3433 2560 2025.06.10 12:05:38.081 2025.06.10 12:05:41.514 2025.06.10 10:42:36.809 2025.06.10 10:42:39.369
6 5.0.3.1652 2025.05.13 f51c6 P P 3474 3632 2025.05.20 05:09:11.712 2025.05.20 05:09:15.186 2025.05.20 03:34:28.226 2025.05.20 03:34:31.858
7 5.0.3.1651 2025.04.30 141ef P P 3462 2648 2025.05.13 12:07:16.996 2025.05.13 12:07:20.458 2025.05.13 10:31:22.888 2025.05.13 10:31:25.536
8 5.0.3.1650 2025.04.28 4cbff P P 3465 2620 2025.05.01 11:41:02.561 2025.05.01 11:41:06.026 2025.05.01 10:06:08.110 2025.05.01 10:06:10.730
9 5.0.3.1649 2025.04.21 5b2d0 P P 3422 2604 2025.04.28 05:38:54.892 2025.04.28 05:38:58.314 2025.04.28 04:05:59.524 2025.04.28 04:06:02.128
10 5.0.3.1648 2025.04.18 2f4c5 P P 3490 2612 2025.04.20 05:30:37.515 2025.04.20 05:30:41.005 2025.04.20 04:00:30.661 2025.04.20 04:00:33.273
11 5.0.3.1635 2025.03.31 22ec6 P P 3547 2612 2025.04.18 11:53:37.994 2025.04.18 11:53:41.541 2025.04.18 10:19:26.111 2025.04.18 10:19:28.723
12 5.0.3.1633 2025.03.28 3123a P P 3431 2598 2025.03.31 10:28:01.921 2025.03.31 10:28:05.352 2025.03.31 08:59:55.469 2025.03.31 08:59:58.067
13 5.0.3.1633 2025.03.27 e0fb8 P P 3471 2539 2025.03.28 11:03:01.127 2025.03.28 11:03:04.598 2025.03.28 09:31:45.361 2025.03.28 09:31:47.900
14 5.0.3.1631 2025.03.21 1925b P P 3509 3617 2025.03.27 10:50:48.400 2025.03.27 10:50:51.909 2025.03.27 09:20:52.350 2025.03.27 09:20:55.967
15 5.0.3.1628 2025.03.14 16d05 P P 3215 2636 2025.03.17 08:23:35.264 2025.03.17 08:23:38.479 2025.03.17 06:44:51.821 2025.03.17 06:44:54.457
16 5.0.3.1627 2025.02.26 4e218 P P 3213 2649 2025.03.14 11:38:03.371 2025.03.14 11:38:06.584 2025.03.14 09:58:06.665 2025.03.14 09:58:09.314
17 5.0.3.1624 2025.02.25 dc3b2 P P 3154 3555 2025.02.26 10:28:43.664 2025.02.26 10:28:46.818 2025.02.26 08:54:25.465 2025.02.26 08:54:29.020
18 5.0.2.1615 2025.02.20 4a726 P P 3228 3587 2025.02.25 10:56:06.401 2025.02.25 10:56:09.629 2025.02.25 09:20:01.171 2025.02.25 09:20:04.758
19 5.0.2.1615 2025.02.14 9cb76 P P 3189 3612 2025.02.20 07:45:25.943 2025.02.20 07:45:29.132 2025.02.20 06:13:02.175 2025.02.20 06:13:05.787
20 5.0.2.1577 2024.12.24 3c80e P P 3267 3575 2025.02.14 10:59:00.606 2025.02.14 10:59:03.873 2025.02.14 09:26:29.533 2025.02.14 09:26:33.108
21 5.0.2.1576 2024.12.17 646b0 F F 3041 2501 2024.12.24 20:23:05.975 2024.12.24 20:23:09.016 2024.12.24 17:12:52.882 2024.12.24 17:12:55.383
22 5.0.2.1575 2024.12.08 63d39 F F 2982 2475 2024.12.16 08:04:33.200 2024.12.16 08:04:36.182 2024.12.16 06:55:39.651 2024.12.16 06:55:42.126
23 5.0.2.1567 2024.11.26 56e63 F F 3054 2505 2024.12.04 07:45:26.947 2024.12.04 07:45:30.001 2024.12.04 06:34:54.005 2024.12.04 06:34:56.510
24 5.0.2.1567 2024.11.21 96f61 F F 2998 2507 2024.11.26 05:27:27.133 2024.11.26 05:27:30.131 2024.11.26 04:20:08.206 2024.11.26 04:20:10.713
25 5.0.2.1567 2024.11.18 e1289 F F 3789 2503 2024.11.21 07:31:50.361 2024.11.21 07:31:54.150 2024.11.21 06:25:15.014 2024.11.21 06:25:17.517
26 5.0.2.1533 2024.10.23 0ec43 P P 2992 2526 2024.11.18 07:48:04.949 2024.11.18 07:48:07.941 2024.11.18 06:39:34.848 2024.11.18 06:39:37.374
27 5.0.2.1533 2024.10.22 8af7a P P 3036 2483 2024.10.23 09:45:12.484 2024.10.23 09:45:15.520 2024.10.23 08:35:33.613 2024.10.23 08:35:36.096
28 5.0.2.1532 2024.10.15 36dc0 P P 3058 2511 2024.10.22 19:56:55.875 2024.10.22 19:56:58.933 2024.10.22 18:47:45.024 2024.10.22 18:47:47.535
29 5.0.2.1518 2024.10.04 259ba P P 3014 2531 2024.10.15 09:30:35.183 2024.10.15 09:30:38.197 2024.10.15 08:21:09.824 2024.10.15 08:21:12.355
30 5.0.2.1518 2024.09.26 703cd P P 3076 2506 2024.10.03 07:57:56.222 2024.10.03 07:57:59.298 2024.10.03 06:46:19.884 2024.10.03 06:46:22.390
31 5.0.2.1489 2024.09.05 40838 P P 3069 2506 2024.09.25 07:58:49.967 2024.09.25 07:58:53.036 2024.09.25 06:46:10.498 2024.09.25 06:46:13.004
32 5.0.2.1489 2024.08.31 994a6 P P 3378 3693 2024.09.05 12:09:12.974 2024.09.05 12:09:16.352 2024.09.05 10:28:54.455 2024.09.05 10:28:58.148
33 5.0.2.1476 2024.08.09 843ea P P 3759 3112 2024.08.31 14:40:41.113 2024.08.31 14:40:44.872 2024.08.31 12:32:57.421 2024.08.31 12:33:00.533
34 5.0.1.1454 2024.08.08 30f9f P P 3178 2637 2024.08.09 08:38:01.261 2024.08.09 08:38:04.439 2024.08.09 07:24:51.615 2024.08.09 07:24:54.252
35 5.0.1.1453 2024.08.06 1b9d0 P P 3205 2659 2024.08.08 21:16:25.265 2024.08.08 21:16:28.470 2024.08.08 20:03:03.912 2024.08.08 20:03:06.571
36 5.0.1.1453 2024.07.30 48044 P P 3199 2448 2024.08.06 07:19:31.613 2024.08.06 07:19:34.812 2024.08.06 06:15:24.369 2024.08.06 06:15:26.817
37 5.0.1.1453 2024.07.28 8d956 P P 2918 2696 2024.07.30 07:13:53.951 2024.07.30 07:13:56.869 2024.07.30 06:10:37.937 2024.07.30 06:10:40.633
38 5.0.1.1429 2024.07.19 8ee90 P P 2899 2682 2024.07.27 07:13:53.198 2024.07.27 07:13:56.097 2024.07.27 06:09:42.015 2024.07.27 06:09:44.697
39 5.0.1.1428 2024.07.15 00392 P P 3194 2731 2024.07.19 07:06:57.456 2024.07.19 07:07:00.650 2024.07.19 06:04:08.224 2024.07.19 06:04:10.955
40 5.0.1.1428 2024.06.30 67a31 P P 3212 2702 2024.07.15 07:08:31.488 2024.07.15 07:08:34.700 2024.07.15 06:05:12.291 2024.07.15 06:05:14.993
41 5.0.1.1415 2024.06.11 31d74 P P 2892 2454 2024.06.22 06:56:09.456 2024.06.22 06:56:12.348 2024.06.22 05:55:31.779 2024.06.22 05:55:34.233

Elapsed time, ms. Chart for last 41 runs:

Last commits information (all timestamps in UTC):