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   
  - Expected: data dispersion is low.
  + UNEXPECTED: standard deviation of elapsed time ratios is 1.0961457137935446 - greater than MAX_STD_DEV=0.5
  + Elapsed time ratios: [4.546666666666667, 0.9648093841642229, 2.0060790273556233, 2.015151515151515, 2.006015037593985, 2.0089955022488755, 2.014179104477612]

LOG DETAILS:

2025-06-26 14:41:32.711
2025-06-26 14:41:32.711 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-26 14:41:32.711 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-26 14:41:32.711
2025-06-26 14:41:32.711     @pytest.mark.version('>=5.0.3')
2025-06-26 14:41:32.711     def test_1(act: Action, capsys):
2025-06-26 14:41:32.711
2025-06-26 14:41:32.711         #############################################
2025-06-26 14:41:32.711         MAX_STD_DEV = 0.5 if os.name == 'nt' else 0.8
2025-06-26 14:41:32.711         #############################################
2025-06-26 14:41:32.711
2025-06-26 14:41:32.711
2025-06-26 14:41:32.712         ddl_lst = []
2025-06-26 14:41:32.712         ddl_lst.extend(
2025-06-26 14:41:32.712             (
2025-06-26 14:41:32.712                 """
2025-06-26 14:41:32.712                     recreate table log_table(
2025-06-26 14:41:32.712                         log_id bigint generated by default as identity constraint pk_log_table primary key
2025-06-26 14:41:32.712                        ,field_name varchar(31) not null
2025-06-26 14:41:32.712                        ,old_value blob
2025-06-26 14:41:32.712                     )
2025-06-26 14:41:32.712                 """
2025-06-26 14:41:32.712                ,"""
2025-06-26 14:41:32.712                     recreate table test_table (
2025-06-26 14:41:32.712                         id             bigint not null,
2025-06-26 14:41:32.712                         fld_01         varchar(40),
2025-06-26 14:41:32.712                         fld_02         date,
2025-06-26 14:41:32.712                         fld_03         varchar(40),
2025-06-26 14:41:32.712                         fld_04         date,
2025-06-26 14:41:32.712                         fld_05         varchar(1000),
2025-06-26 14:41:32.712                         fld_06         varchar(1000),
2025-06-26 14:41:32.712                         fld_07         numeric(15,2),
2025-06-26 14:41:32.713                         fld_08         date,
2025-06-26 14:41:32.713                         fld_09         varchar(95),
2025-06-26 14:41:32.713                         fld_10         bigint,
2025-06-26 14:41:32.713                         fld_11         bigint,
2025-06-26 14:41:32.713                         fld_12         bigint,
2025-06-26 14:41:32.713                         fld_13         varchar(250),
2025-06-26 14:41:32.713                         fld_14         bigint,
2025-06-26 14:41:32.713                         fld_15         date,
2025-06-26 14:41:32.713                         fld_16         integer,
2025-06-26 14:41:32.713                         fld_17         bigint,
2025-06-26 14:41:32.713                         fld_18         date,
2025-06-26 14:41:32.713                         fld_19         bigint,
2025-06-26 14:41:32.713                         fld_20         varchar(95),
2025-06-26 14:41:32.713                         fld_21         date,
2025-06-26 14:41:32.713                         fld_22         bigint,
2025-06-26 14:41:32.713                         fld_23         numeric(16,0),
2025-06-26 14:41:32.713                         fld_24         smallint,
2025-06-26 14:41:32.713                         fld_25         bigint,
2025-06-26 14:41:32.714                         fld_26         bigint,
2025-06-26 14:41:32.714                         fld_27         smallint default 0,
2025-06-26 14:41:32.714                         fld_28         date,
2025-06-26 14:41:32.714                         fld_29         smallint,
2025-06-26 14:41:32.714                         fld_30         date,
2025-06-26 14:41:32.714                         fld_31         date,
2025-06-26 14:41:32.714                         fld_32         date,
2025-06-26 14:41:32.714                         fld_33         date,
2025-06-26 14:41:32.714                         fld_34         date,
2025-06-26 14:41:32.714                         fld_35         date,
2025-06-26 14:41:32.714                         fld_36         date,
2025-06-26 14:41:32.714                         fld_37         date,
2025-06-26 14:41:32.714                         fld_38         date,
2025-06-26 14:41:32.714                         fld_39         date,
2025-06-26 14:41:32.714                         fld_40         smallint,
2025-06-26 14:41:32.714                         fld_41         smallint,
2025-06-26 14:41:32.714                         fld_42         smallint,
2025-06-26 14:41:32.714                         fld_43         bigint,
2025-06-26 14:41:32.714                         fld_44         bigint,
2025-06-26 14:41:32.714                         fld_45         bigint,
2025-06-26 14:41:32.715                         fld_46         smallint,
2025-06-26 14:41:32.715                         fld_47         varchar(1000),
2025-06-26 14:41:32.715                         fld_48         bigint,
2025-06-26 14:41:32.715                         fld_49         varchar(4000),
2025-06-26 14:41:32.715                         fld_50         bigint
2025-06-26 14:41:32.715                     )
2025-06-26 14:41:32.715                 """
2025-06-26 14:41:32.715                ,'create generator audit'
2025-06-26 14:41:32.715                ,'alter table test_table add constraint pk_test_table primary key (id) using descending index pk_test_table'
2025-06-26 14:41:32.715                ,"""
2025-06-26 14:41:32.715                     create or alter trigger h$test_table for test_table
2025-06-26 14:41:32.715                     active after update position 0
2025-06-26 14:41:32.715                     as
2025-06-26 14:41:32.715                         declare id bigint;
2025-06-26 14:41:32.715                         declare o blob sub_type 1 segment size 80;
2025-06-26 14:41:32.715                     begin
2025-06-26 14:41:32.715                         id = gen_id(audit, 1);
2025-06-26 14:41:32.715                         o = old.fld_01; if (o is distinct from new.fld_01) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_01', :o); end
2025-06-26 14:41:32.715                         o = old.fld_02; if (o is distinct from new.fld_02) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_02', :o); end
2025-06-26 14:41:32.716                         o = old.fld_03; if (o is distinct from new.fld_03) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_03', :o); end
2025-06-26 14:41:32.716                         o = old.fld_04; if (o is distinct from new.fld_04) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_04', :o); end
2025-06-26 14:41:32.716                         o = old.fld_05; if (o is distinct from new.fld_05) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_05', :o); end
2025-06-26 14:41:32.716                         o = old.fld_06; if (o is distinct from new.fld_06) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_06', :o); end
2025-06-26 14:41:32.716                         o = old.fld_07; if (o is distinct from new.fld_07) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_07', :o); end
2025-06-26 14:41:32.716                         o = old.fld_08; if (o is distinct from new.fld_08) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_08', :o); end
2025-06-26 14:41:32.716                         o = old.fld_09; if (o is distinct from new.fld_09) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_09', :o); end
2025-06-26 14:41:32.716                         o = old.fld_10; if (o is distinct from new.fld_10) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_10', :o); end
2025-06-26 14:41:32.716
2025-06-26 14:41:32.716
2025-06-26 14:41:32.716                         o = old.fld_11; if (o is distinct from new.fld_11) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_11', :o); end
2025-06-26 14:41:32.716                         o = old.fld_12; if (o is distinct from new.fld_12) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_12', :o); end
2025-06-26 14:41:32.716                         o = old.fld_13; if (o is distinct from new.fld_13) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_13', :o); end
2025-06-26 14:41:32.716                         o = old.fld_14; if (o is distinct from new.fld_14) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_14', :o); end
2025-06-26 14:41:32.716                         o = old.fld_15; if (o is distinct from new.fld_15) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_15', :o); end
2025-06-26 14:41:32.716                         o = old.fld_16; if (o is distinct from new.fld_16) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_16', :o); end
2025-06-26 14:41:32.716                         o = old.fld_17; if (o is distinct from new.fld_17) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_17', :o); end
2025-06-26 14:41:32.717                         o = old.fld_18; if (o is distinct from new.fld_18) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_18', :o); end
2025-06-26 14:41:32.717                         o = old.fld_19; if (o is distinct from new.fld_19) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_19', :o); end
2025-06-26 14:41:32.717                         o = old.fld_20; if (o is distinct from new.fld_20) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_20', :o); end
2025-06-26 14:41:32.717
2025-06-26 14:41:32.717
2025-06-26 14:41:32.717                         o = old.fld_21; if (o is distinct from new.fld_21) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_21', :o); end
2025-06-26 14:41:32.717                         o = old.fld_22; if (o is distinct from new.fld_22) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_22', :o); end
2025-06-26 14:41:32.717                         o = old.fld_23; if (o is distinct from new.fld_23) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_23', :o); end
2025-06-26 14:41:32.717                         o = old.fld_24; if (o is distinct from new.fld_24) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_24', :o); end
2025-06-26 14:41:32.717                         o = old.fld_25; if (o is distinct from new.fld_25) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_25', :o); end
2025-06-26 14:41:32.717                         o = old.fld_26; if (o is distinct from new.fld_26) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_26', :o); end
2025-06-26 14:41:32.717                         o = old.fld_27; if (o is distinct from new.fld_27) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_27', :o); end
2025-06-26 14:41:32.717                         o = old.fld_28; if (o is distinct from new.fld_28) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_28', :o); end
2025-06-26 14:41:32.717                         o = old.fld_29; if (o is distinct from new.fld_29) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_29', :o); end
2025-06-26 14:41:32.717                         o = old.fld_30; if (o is distinct from new.fld_30) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_30', :o); end
2025-06-26 14:41:32.717
2025-06-26 14:41:32.717
2025-06-26 14:41:32.718                         o = old.fld_31; if (o is distinct from new.fld_31) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_31', :o); end
2025-06-26 14:41:32.718                         o = old.fld_32; if (o is distinct from new.fld_32) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_32', :o); end
2025-06-26 14:41:32.718                         o = old.fld_33; if (o is distinct from new.fld_33) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_33', :o); end
2025-06-26 14:41:32.718                         o = old.fld_34; if (o is distinct from new.fld_34) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_34', :o); end
2025-06-26 14:41:32.718                         o = old.fld_35; if (o is distinct from new.fld_35) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_35', :o); end
2025-06-26 14:41:32.718                         o = old.fld_36; if (o is distinct from new.fld_36) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_36', :o); end
2025-06-26 14:41:32.718                         o = old.fld_37; if (o is distinct from new.fld_37) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_37', :o); end
2025-06-26 14:41:32.718                         o = old.fld_38; if (o is distinct from new.fld_38) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_38', :o); end
2025-06-26 14:41:32.718                         o = old.fld_39; if (o is distinct from new.fld_39) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_39', :o); end
2025-06-26 14:41:32.718                         o = old.fld_40; if (o is distinct from new.fld_40) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_40', :o); end
2025-06-26 14:41:32.718
2025-06-26 14:41:32.718
2025-06-26 14:41:32.718
2025-06-26 14:41:32.718                         o = old.fld_41; if (o is distinct from new.fld_41) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_41', :o); end
2025-06-26 14:41:32.718                         o = old.fld_42; if (o is distinct from new.fld_42) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_42', :o); end
2025-06-26 14:41:32.718                         o = old.fld_43; if (o is distinct from new.fld_43) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_43', :o); end
2025-06-26 14:41:32.718                         o = old.fld_44; if (o is distinct from new.fld_44) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_44', :o); end
2025-06-26 14:41:32.718                         o = old.fld_45; if (o is distinct from new.fld_45) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_45', :o); end
2025-06-26 14:41:32.719                         o = old.fld_46; if (o is distinct from new.fld_46) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_46', :o); end
2025-06-26 14:41:32.719                         o = old.fld_47; if (o is distinct from new.fld_47) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_47', :o); end
2025-06-26 14:41:32.719                         o = old.fld_48; if (o is distinct from new.fld_48) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_48', :o); end
2025-06-26 14:41:32.719                         o = old.fld_49; if (o is distinct from new.fld_49) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_49', :o); end
2025-06-26 14:41:32.719                         o = old.fld_50; if (o is distinct from new.fld_50) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_50', :o); end
2025-06-26 14:41:32.719                     end
2025-06-26 14:41:32.719                 """
2025-06-26 14:41:32.719                ,"""
2025-06-26 14:41:32.719                     execute block
2025-06-26 14:41:32.719                     as
2025-06-26 14:41:32.719                         declare id bigint;
2025-06-26 14:41:32.719                     begin
2025-06-26 14:41:32.719                         id = 0;
2025-06-26 14:41:32.719                         while (id < 128000) do
2025-06-26 14:41:32.719                         begin
2025-06-26 14:41:32.719                             insert into test_table (id,fld_01,fld_02,fld_03,fld_04,fld_05,fld_06,fld_07,fld_08,fld_09,fld_10,fld_11,fld_12,fld_13,fld_14,fld_15,fld_16,fld_17,fld_18,fld_19,fld_20,fld_21,fld_22,fld_23,fld_24,fld_25,fld_26,fld_27,fld_28,fld_29,fld_30,fld_31,fld_32,fld_33,fld_34,fld_35,fld_36,fld_37,fld_38,fld_39,fld_40,fld_41,fld_42,fld_43,fld_44,fld_45,fld_46,fld_47,fld_48,fld_49,fld_50)
2025-06-26 14:41:32.719                                 values (
2025-06-26 14:41:32.719                                          :id,
2025-06-26 14:41:32.720                                          'Identifier',
2025-06-26 14:41:32.720                                          '2025-01-23',
2025-06-26 14:41:32.720                                          '1234567890123456789',
2025-06-26 14:41:32.720                                          '2025-01-23',
2025-06-26 14:41:32.720                                          'Test data',
2025-06-26 14:41:32.720                                          'Test another data',
2025-06-26 14:41:32.720                                          500,
2025-06-26 14:41:32.720                                          '2025-01-24',
2025-06-26 14:41:32.720                                          'Test Test Test',
2025-06-26 14:41:32.720                                          3,
2025-06-26 14:41:32.720                                          12345678901234,
2025-06-26 14:41:32.720                                          12,
2025-06-26 14:41:32.720                                          'Test',
2025-06-26 14:41:32.720                                          12345678901234,
2025-06-26 14:41:32.720                                          '2025-01-30',
2025-06-26 14:41:32.720                                          0,
2025-06-26 14:41:32.720                                          NULL,
2025-06-26 14:41:32.720                                          '2025-01-31',
2025-06-26 14:41:32.720                                          12345679801234,
2025-06-26 14:41:32.721                                          'Test Test data',
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          1234,
2025-06-26 14:41:32.721                                          1234567,
2025-06-26 14:41:32.721                                          2025,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          0,
2025-06-26 14:41:32.721                                          '2025-02-01',
2025-06-26 14:41:32.721                                          0,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          '2025-01-15',
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.721                                          NULL,
2025-06-26 14:41:32.722                                          1,
2025-06-26 14:41:32.722                                          0,
2025-06-26 14:41:32.722                                          0,
2025-06-26 14:41:32.722                                          NULL,
2025-06-26 14:41:32.722                                          12346579801234,
2025-06-26 14:41:32.722                                          12345678901234,
2025-06-26 14:41:32.722                                          NULL,
2025-06-26 14:41:32.722                                          'Long test data for varchar(1000)',
2025-06-26 14:41:32.722                                          12345678901234,
2025-06-26 14:41:32.722                                          'Very long test data for varchar(4000)... Very long test data for varchar(4000)... Very long test data for varchar(4000)... Very long test data for varchar(4000)... Very long test data for varchar(4000)...',
2025-06-26 14:41:32.722                                          0
2025-06-26 14:41:32.722                                        );
2025-06-26 14:41:32.722
2025-06-26 14:41:32.722                             id = id + 1;
2025-06-26 14:41:32.722                         end
2025-06-26 14:41:32.722                     end
2025-06-26 14:41:32.722                 """
2025-06-26 14:41:32.722                ,"""
2025-06-26 14:41:32.723                     create or alter procedure run_test(a int)
2025-06-26 14:41:32.723                     returns (t_cnt int, t_diff bigint)
2025-06-26 14:41:32.723                     as
2025-06-26 14:41:32.723                         declare id bigint;
2025-06-26 14:41:32.723                         declare t_begin timestamp;
2025-06-26 14:41:32.723                         declare t_end timestamp;
2025-06-26 14:41:32.723                     begin
2025-06-26 14:41:32.723                         t_cnt = a;
2025-06-26 14:41:32.723                         t_begin = 'now';
2025-06-26 14:41:32.723                         for
2025-06-26 14:41:32.723                             select id
2025-06-26 14:41:32.723                             from test_table
2025-06-26 14:41:32.723                             where
2025-06-26 14:41:32.723                                 id >= 0 and id < :t_cnt
2025-06-26 14:41:32.723                          into :id do
2025-06-26 14:41:32.723                             update test_table set fld_50 = :t_cnt where id = :id;
2025-06-26 14:41:32.723                         t_end = 'now';
2025-06-26 14:41:32.723                         t_diff = datediff(millisecond from :t_begin to :t_end);
2025-06-26 14:41:32.723                         suspend;
2025-06-26 14:41:32.723                     end
2025-06-26 14:41:32.724                 """
2025-06-26 14:41:32.724             )
2025-06-26 14:41:32.724         )
2025-06-26 14:41:32.724
2025-06-26 14:41:32.724         with act.db.connect() as con:
2025-06-26 14:41:32.724             for x in ddl_lst:
2025-06-26 14:41:32.724                 con.execute_immediate(x)
2025-06-26 14:41:32.724                 con.commit()
2025-06-26 14:41:32.724
2025-06-26 14:41:32.724             #--------------------------------------
2025-06-26 14:41:32.724
2025-06-26 14:41:32.724             cur = con.cursor()
2025-06-26 14:41:32.724             rs = None
2025-06-26 14:41:32.724             ps = cur.prepare('select t.* from run_test(?) t')
2025-06-26 14:41:32.724             elapsed_time_ratios = []
2025-06-26 14:41:32.724             ms_prev = -1
2025-06-26 14:41:32.724             for n in (0.375, 0.75, 1.5, 3, 6, 12, 24, 48):
2025-06-26 14:41:32.724                 # d1 = py_dt.timedelta(0)
2025-06-26 14:41:32.724                 rs = cur.execute(ps, ( int(n * 1000),))
2025-06-26 14:41:32.724                 t1 = py_dt.datetime.now()
2025-06-26 14:41:32.725                 cur.fetchall()
2025-06-26 14:41:32.725                 t2 = py_dt.datetime.now()
2025-06-26 14:41:32.725                 con.commit()
2025-06-26 14:41:32.725                 d1 = t2-t1
2025-06-26 14:41:32.725                 ms_curr = d1.seconds*1000 + d1.microseconds//1000
2025-06-26 14:41:32.725
2025-06-26 14:41:32.725                 if ms_prev > 0:
2025-06-26 14:41:32.725                     elapsed_time_ratios.append(ms_curr / ms_prev)
2025-06-26 14:41:32.725                 ms_prev = ms_curr
2025-06-26 14:41:32.725
2025-06-26 14:41:32.725             if rs:
2025-06-26 14:41:32.725                 rs.close() # <<< EXPLICITLY CLOSING CURSOR RESULTS
2025-06-26 14:41:32.725             if ps:
2025-06-26 14:41:32.725                 ps.free()
2025-06-26 14:41:32.725
2025-06-26 14:41:32.725         expected_msg = 'Expected: data dispersion is low.'
2025-06-26 14:41:32.725         std_deviation = stdev(elapsed_time_ratios)
2025-06-26 14:41:32.725         if std_deviation <= MAX_STD_DEV:
2025-06-26 14:41:32.725             print(expected_msg)
2025-06-26 14:41:32.725         else:
2025-06-26 14:41:32.726             print(f'UNEXPECTED: standard deviation of elapsed time ratios is {std_deviation} - greater than {MAX_STD_DEV=}')
2025-06-26 14:41:32.726             print(f'Elapsed time ratios: {elapsed_time_ratios}')
2025-06-26 14:41:32.726
2025-06-26 14:41:32.726         act.expected_stdout = f"""
2025-06-26 14:41:32.726             {expected_msg}
2025-06-26 14:41:32.726         """
2025-06-26 14:41:32.726         act.stdout = capsys.readouterr().out
2025-06-26 14:41:32.726 >       assert act.clean_stdout == act.clean_expected_stdout
2025-06-26 14:41:32.726 E       assert
2025-06-26 14:41:32.726 E         - Expected: data dispersion is low.
2025-06-26 14:41:32.726 E         + UNEXPECTED: standard deviation of elapsed time ratios is 1.0961457137935446 - greater than MAX_STD_DEV=0.5
2025-06-26 14:41:32.726 E         + Elapsed time ratios: [4.546666666666667, 0.9648093841642229, 2.0060790273556233, 2.015151515151515, 2.006015037593985, 2.0089955022488755, 2.014179104477612]
2025-06-26 14:41:32.726
2025-06-26 14:41:32.726 tests\bugs\gh_8421_test.py:332: AssertionError
2025-06-26 14:41:32.726 ---------------------------- Captured stdout setup ----------------------------
2025-06-26 14:41:32.726 Creating db: localhost:H:\QA\temp\qa2024.tmp\fbqa\test_11711\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.version('>=5.0.3')
    def test_1(act: Action, capsys):
    
        #############################################
        MAX_STD_DEV = 0.5 if os.name == 'nt' else 0.8
        #############################################
    
    
        ddl_lst = []
        ddl_lst.extend(
            (
                """
                    recreate table log_table(
                        log_id bigint generated by default as identity constraint pk_log_table primary key
                       ,field_name varchar(31) not null
                       ,old_value blob
                    )
                """
               ,"""
                    recreate table test_table (
                        id             bigint not null,
                        fld_01         varchar(40),
                        fld_02         date,
                        fld_03         varchar(40),
                        fld_04         date,
                        fld_05         varchar(1000),
                        fld_06         varchar(1000),
                        fld_07         numeric(15,2),
                        fld_08         date,
                        fld_09         varchar(95),
                        fld_10         bigint,
                        fld_11         bigint,
                        fld_12         bigint,
                        fld_13         varchar(250),
                        fld_14         bigint,
                        fld_15         date,
                        fld_16         integer,
                        fld_17         bigint,
                        fld_18         date,
                        fld_19         bigint,
                        fld_20         varchar(95),
                        fld_21         date,
                        fld_22         bigint,
                        fld_23         numeric(16,0),
                        fld_24         smallint,
                        fld_25         bigint,
                        fld_26         bigint,
                        fld_27         smallint default 0,
                        fld_28         date,
                        fld_29         smallint,
                        fld_30         date,
                        fld_31         date,
                        fld_32         date,
                        fld_33         date,
                        fld_34         date,
                        fld_35         date,
                        fld_36         date,
                        fld_37         date,
                        fld_38         date,
                        fld_39         date,
                        fld_40         smallint,
                        fld_41         smallint,
                        fld_42         smallint,
                        fld_43         bigint,
                        fld_44         bigint,
                        fld_45         bigint,
                        fld_46         smallint,
                        fld_47         varchar(1000),
                        fld_48         bigint,
                        fld_49         varchar(4000),
                        fld_50         bigint
                    )
                """
               ,'create generator audit'
               ,'alter table test_table add constraint pk_test_table primary key (id) using descending index pk_test_table'
               ,"""
                    create or alter trigger h$test_table for test_table
                    active after update position 0
                    as
                        declare id bigint;
                        declare o blob sub_type 1 segment size 80;
                    begin
                        id = gen_id(audit, 1);
                        o = old.fld_01; if (o is distinct from new.fld_01) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_01', :o); end
                        o = old.fld_02; if (o is distinct from new.fld_02) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_02', :o); end
                        o = old.fld_03; if (o is distinct from new.fld_03) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_03', :o); end
                        o = old.fld_04; if (o is distinct from new.fld_04) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_04', :o); end
                        o = old.fld_05; if (o is distinct from new.fld_05) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_05', :o); end
                        o = old.fld_06; if (o is distinct from new.fld_06) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_06', :o); end
                        o = old.fld_07; if (o is distinct from new.fld_07) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_07', :o); end
                        o = old.fld_08; if (o is distinct from new.fld_08) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_08', :o); end
                        o = old.fld_09; if (o is distinct from new.fld_09) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_09', :o); end
                        o = old.fld_10; if (o is distinct from new.fld_10) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_10', :o); end
    
    
                        o = old.fld_11; if (o is distinct from new.fld_11) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_11', :o); end
                        o = old.fld_12; if (o is distinct from new.fld_12) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_12', :o); end
                        o = old.fld_13; if (o is distinct from new.fld_13) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_13', :o); end
                        o = old.fld_14; if (o is distinct from new.fld_14) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_14', :o); end
                        o = old.fld_15; if (o is distinct from new.fld_15) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_15', :o); end
                        o = old.fld_16; if (o is distinct from new.fld_16) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_16', :o); end
                        o = old.fld_17; if (o is distinct from new.fld_17) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_17', :o); end
                        o = old.fld_18; if (o is distinct from new.fld_18) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_18', :o); end
                        o = old.fld_19; if (o is distinct from new.fld_19) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_19', :o); end
                        o = old.fld_20; if (o is distinct from new.fld_20) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_20', :o); end
    
    
                        o = old.fld_21; if (o is distinct from new.fld_21) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_21', :o); end
                        o = old.fld_22; if (o is distinct from new.fld_22) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_22', :o); end
                        o = old.fld_23; if (o is distinct from new.fld_23) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_23', :o); end
                        o = old.fld_24; if (o is distinct from new.fld_24) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_24', :o); end
                        o = old.fld_25; if (o is distinct from new.fld_25) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_25', :o); end
                        o = old.fld_26; if (o is distinct from new.fld_26) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_26', :o); end
                        o = old.fld_27; if (o is distinct from new.fld_27) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_27', :o); end
                        o = old.fld_28; if (o is distinct from new.fld_28) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_28', :o); end
                        o = old.fld_29; if (o is distinct from new.fld_29) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_29', :o); end
                        o = old.fld_30; if (o is distinct from new.fld_30) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_30', :o); end
    
    
                        o = old.fld_31; if (o is distinct from new.fld_31) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_31', :o); end
                        o = old.fld_32; if (o is distinct from new.fld_32) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_32', :o); end
                        o = old.fld_33; if (o is distinct from new.fld_33) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_33', :o); end
                        o = old.fld_34; if (o is distinct from new.fld_34) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_34', :o); end
                        o = old.fld_35; if (o is distinct from new.fld_35) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_35', :o); end
                        o = old.fld_36; if (o is distinct from new.fld_36) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_36', :o); end
                        o = old.fld_37; if (o is distinct from new.fld_37) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_37', :o); end
                        o = old.fld_38; if (o is distinct from new.fld_38) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_38', :o); end
                        o = old.fld_39; if (o is distinct from new.fld_39) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_39', :o); end
                        o = old.fld_40; if (o is distinct from new.fld_40) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_40', :o); end
    
    
    
                        o = old.fld_41; if (o is distinct from new.fld_41) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_41', :o); end
                        o = old.fld_42; if (o is distinct from new.fld_42) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_42', :o); end
                        o = old.fld_43; if (o is distinct from new.fld_43) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_43', :o); end
                        o = old.fld_44; if (o is distinct from new.fld_44) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_44', :o); end
                        o = old.fld_45; if (o is distinct from new.fld_45) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_45', :o); end
                        o = old.fld_46; if (o is distinct from new.fld_46) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_46', :o); end
                        o = old.fld_47; if (o is distinct from new.fld_47) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_47', :o); end
                        o = old.fld_48; if (o is distinct from new.fld_48) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_48', :o); end
                        o = old.fld_49; if (o is distinct from new.fld_49) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_49', :o); end
                        o = old.fld_50; if (o is distinct from new.fld_50) then begin insert into log_table(log_id, field_name, old_value) values(:id, 'fld_50', :o); end
                    end
                """
               ,"""
                    execute block
                    as
                        declare id bigint;
                    begin
                        id = 0;
                        while (id < 128000) do
                        begin
                            insert into test_table (id,fld_01,fld_02,fld_03,fld_04,fld_05,fld_06,fld_07,fld_08,fld_09,fld_10,fld_11,fld_12,fld_13,fld_14,fld_15,fld_16,fld_17,fld_18,fld_19,fld_20,fld_21,fld_22,fld_23,fld_24,fld_25,fld_26,fld_27,fld_28,fld_29,fld_30,fld_31,fld_32,fld_33,fld_34,fld_35,fld_36,fld_37,fld_38,fld_39,fld_40,fld_41,fld_42,fld_43,fld_44,fld_45,fld_46,fld_47,fld_48,fld_49,fld_50)
                                values (
                                         :id,
                                         'Identifier',
                                         '2025-01-23',
                                         '1234567890123456789',
                                         '2025-01-23',
                                         'Test data',
                                         'Test another data',
                                         500,
                                         '2025-01-24',
                                         'Test Test Test',
                                         3,
                                         12345678901234,
                                         12,
                                         'Test',
                                         12345678901234,
                                         '2025-01-30',
                                         0,
                                         NULL,
                                         '2025-01-31',
                                         12345679801234,
                                         'Test Test data',
                                         NULL,
                                         1234,
                                         1234567,
                                         2025,
                                         NULL,
                                         NULL,
                                         0,
                                         '2025-02-01',
                                         0,
                                         NULL,
                                         NULL,
                                         NULL,
                                         NULL,
                                         '2025-01-15',
                                         NULL,
                                         NULL,
                                         NULL,
                                         NULL,
                                         NULL,
                                         1,
                                         0,
                                         0,
                                         NULL,
                                         12346579801234,
                                         12345678901234,
                                         NULL,
                                         'Long test data for varchar(1000)',
                                         12345678901234,
                                         'Very long test data for varchar(4000)... Very long test data for varchar(4000)... Very long test data for varchar(4000)... Very long test data for varchar(4000)... Very long test data for varchar(4000)...',
                                         0
                                       );
    
                            id = id + 1;
                        end
                    end
                """
               ,"""
                    create or alter procedure run_test(a int)
                    returns (t_cnt int, t_diff bigint)
                    as
                        declare id bigint;
                        declare t_begin timestamp;
                        declare t_end timestamp;
                    begin
                        t_cnt = a;
                        t_begin = 'now';
                        for
                            select id
                            from test_table
                            where
                                id >= 0 and id < :t_cnt
                         into :id do
                            update test_table set fld_50 = :t_cnt where id = :id;
                        t_end = 'now';
                        t_diff = datediff(millisecond from :t_begin to :t_end);
                        suspend;
                    end
                """
            )
        )
    
        with act.db.connect() as con:
            for x in ddl_lst:
                con.execute_immediate(x)
                con.commit()
    
            #--------------------------------------
    
            cur = con.cursor()
            rs = None
            ps = cur.prepare('select t.* from run_test(?) t')
            elapsed_time_ratios = []
            ms_prev = -1
            for n in (0.375, 0.75, 1.5, 3, 6, 12, 24, 48):
                # d1 = py_dt.timedelta(0)
                rs = cur.execute(ps, ( int(n * 1000),))
                t1 = py_dt.datetime.now()
                cur.fetchall()
                t2 = py_dt.datetime.now()
                con.commit()
                d1 = t2-t1
                ms_curr = d1.seconds*1000 + d1.microseconds//1000
    
                if ms_prev > 0:
                    elapsed_time_ratios.append(ms_curr / ms_prev)
                ms_prev = ms_curr
    
            if rs:
                rs.close() # <<< EXPLICITLY CLOSING CURSOR RESULTS
            if ps:
                ps.free()
    
        expected_msg = 'Expected: data dispersion is low.'
        std_deviation = stdev(elapsed_time_ratios)
        if std_deviation <= MAX_STD_DEV:
            print(expected_msg)
        else:
            print(f'UNEXPECTED: standard deviation of elapsed time ratios is {std_deviation} - greater than {MAX_STD_DEV=}')
            print(f'Elapsed time ratios: {elapsed_time_ratios}')
    
        act.expected_stdout = f"""
            {expected_msg}
        """
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - Expected: data dispersion is low.
E         + UNEXPECTED: standard deviation of elapsed time ratios is 1.0961457137935446 - greater than MAX_STD_DEV=0.5
E         + Elapsed time ratios: [4.546666666666667, 0.9648093841642229, 2.0060790273556233, 2.015151515151515, 2.006015037593985, 2.0089955022488755, 2.014179104477612]

tests\bugs\gh_8421_test.py:332: 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.1657 2025.06.26 dcb8a P P 23219 10352 2025.06.27 11:08:17.024 2025.06.27 11:08:40.243 2025.06.27 10:07:21.063 2025.06.27 10:07:31.415
2 5.0.3.1657 2025.06.20 8b4d2 F P 23628 10075 2025.06.26 11:22:44.983 2025.06.26 11:23:08.611 2025.06.26 10:21:37.782 2025.06.26 10:21:47.857
3 5.0.3.1657 2025.06.19 4bd4c P P 23250 10504 2025.06.20 05:26:59.265 2025.06.20 05:27:22.515 2025.06.20 04:25:56.002 2025.06.20 04:26:06.506
4 5.0.3.1657 2025.06.11 dae6f P P 23563 11001 2025.06.19 10:58:26.553 2025.06.19 10:58:50.116 2025.06.19 09:57:19.666 2025.06.19 09:57:30.667
5 5.0.3.1657 2025.06.10 dbc92 P P 23224 10479 2025.06.11 08:44:36.487 2025.06.11 08:44:59.711 2025.06.11 07:43:16.666 2025.06.11 07:43:27.145
6 5.0.3.1656 2025.06.05 00512 P P 23417 11374 2025.06.10 10:00:06.676 2025.06.10 10:00:30.093 2025.06.10 08:58:21.526 2025.06.10 08:58:32.900
7 5.0.3.1656 2025.05.20 c4b11 P P 23527 10792 2025.06.03 09:46:59.604 2025.06.03 09:47:23.131 2025.06.03 08:46:25.428 2025.06.03 08:46:36.220
8 5.0.3.1652 2025.05.13 f51c6 P P 22402 10664 2025.05.21 06:27:59.285 2025.05.21 06:28:21.687 2025.05.21 05:27:41.213 2025.05.21 05:27:51.877
9 5.0.3.1651 2025.05.08 ee9d2 P E 22798 2393 2025.05.13 06:40:38.475 2025.05.13 06:41:01.273 2025.05.13 05:21:56.679 2025.05.13 05:21:59.072
10 5.0.3.1651 2025.05.04 3d914 P E 23105 2396 2025.05.09 04:29:41.421 2025.05.09 04:30:04.526 2025.05.09 03:10:54.514 2025.05.09 03:10:56.910
11 5.0.3.1651 2025.04.30 141ef P E 22300 2439 2025.05.02 04:37:18.431 2025.05.02 04:37:40.731 2025.05.02 03:18:47.870 2025.05.02 03:18:50.309
12 5.0.3.1650 2025.04.30 6253f P E 23092 2385 2025.05.01 04:36:21.165 2025.05.01 04:36:44.257 2025.05.01 03:17:44.131 2025.05.01 03:17:46.516
13 5.0.3.1650 2025.04.28 4cbff P E 22523 2418 2025.04.30 04:35:22.777 2025.04.30 04:35:45.300 2025.04.30 03:16:57.156 2025.04.30 03:16:59.574
14 5.0.3.1649 2025.04.21 5b2d0 P E 25280 2394 2025.04.26 10:09:18.062 2025.04.26 10:09:43.342 2025.04.26 08:49:57.163 2025.04.26 08:49:59.557
15 5.0.3.1648 2025.04.18 2f4c5 P P 25108 12429 2025.04.20 04:20:32.166 2025.04.20 04:20:57.274 2025.04.20 03:19:12.721 2025.04.20 03:19:25.150
16 5.0.3.1635 2025.04.03 f6bd1 P E 24830 2244 2025.04.18 06:48:13.001 2025.04.18 06:48:37.831 2025.04.18 05:29:07.478 2025.04.18 05:29:09.722
17 5.0.3.1635 2025.03.31 22ec6 P E 25889 2424 2025.04.03 09:54:02.153 2025.04.03 09:54:28.042 2025.04.03 08:34:37.739 2025.04.03 08:34:40.163
18 5.0.3.1633 2025.03.28 3123a P E 24787 2417 2025.03.31 09:52:31.373 2025.03.31 09:52:56.160 2025.03.31 08:33:13.795 2025.03.31 08:33:16.212
19 5.0.3.1633 2025.03.27 e0fb8 P E 25934 2261 2025.03.28 10:24:10.279 2025.03.28 10:24:36.213 2025.03.28 09:01:08.178 2025.03.28 09:01:10.439
20 5.0.3.1631 2025.03.25 bda65 P P 25485 13246 2025.03.27 10:04:41.563 2025.03.27 10:05:07.048 2025.03.27 08:59:39.783 2025.03.27 08:59:53.029
21 5.0.3.1631 2025.03.21 1925b P P 25661 12613 2025.03.25 06:38:43.916 2025.03.25 06:39:09.577 2025.03.25 05:33:33.005 2025.03.25 05:33:45.618
22 5.0.3.1629 2025.03.18 506d7 P P 25650 12475 2025.03.20 09:39:01.290 2025.03.20 09:39:26.940 2025.03.20 08:33:40.037 2025.03.20 08:33:52.512
23 5.0.3.1628 2025.03.14 16d05 P P 25662 13118 2025.03.18 09:33:09.138 2025.03.18 09:33:34.800 2025.03.18 08:29:21.865 2025.03.18 08:29:34.983
24 5.0.3.1627 2025.02.26 4e218 P P 25625 12795 2025.03.13 09:52:27.096 2025.03.13 09:52:52.721 2025.03.13 08:46:54.120 2025.03.13 08:47:06.915
25 5.0.3.1624 2025.02.25 dc3b2 P P 25044 12676 2025.02.26 15:24:42.360 2025.02.26 15:25:07.404 2025.02.26 14:19:50.800 2025.02.26 14:20:03.476

Elapsed time, ms. Chart for last 25 runs:

Last commits information (all timestamps in UTC):