Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
2 @message
assert   
  - Fetches ratio expected.
  + Fetches ratio between 1st and 2nd requests to PP = 0 - UNEXPECTED:
  + Request #1: 47631
  + Request #2: 115943

LOG DETAILS:

2024-05-09 21:54:22.853
2024-05-09 21:54:22.853 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-09 21:54:22.853 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-09 21:54:22.853
2024-05-09 21:54:22.853     @pytest.mark.version('>=4.0.5')
2024-05-09 21:54:22.853     def test_1(act: Action, capsys):
2024-05-09 21:54:22.853
2024-05-09 21:54:22.853         get_last_pp_for_table = f"""
2024-05-09 21:54:22.853             select p.rdb$relation_id, p.rdb$page_sequence
2024-05-09 21:54:22.853             from rdb$pages p join rdb$relations r on p.rdb$relation_id = r.rdb$relation_id
2024-05-09 21:54:22.853             where r.rdb$relation_name = '{TAB_NAME}' and p.rdb$page_type = 4
2024-05-09 21:54:22.853             order by 2 desc
2024-05-09 21:54:22.853             rows 1
2024-05-09 21:54:22.853         """
2024-05-09 21:54:22.853         rel_id, max_pp = -1, -1
2024-05-09 21:54:22.853         with act.db.connect(no_gc = True) as con:
2024-05-09 21:54:22.853             cur = con.cursor()
2024-05-09 21:54:22.853             cur.execute(get_last_pp_for_table)
2024-05-09 21:54:22.853             for r in cur:
2024-05-09 21:54:22.853                 rel_id, max_pp = r[:2]
2024-05-09 21:54:22.853             assert rel_id > 0 and max_pp > 0
2024-05-09 21:54:22.853             #--------------------------------
2024-05-09 21:54:22.853
2024-05-09 21:54:22.853             # Subsequent number of PP that we want to check ('20' in the ticket):
2024-05-09 21:54:22.854             ##########
2024-05-09 21:54:22.854             chk_pp = 0
2024-05-09 21:54:22.854             ##########
2024-05-09 21:54:22.854
2024-05-09 21:54:22.854             read_records_for_chk_pp = f"""
2024-05-09 21:54:22.854                 select count(*), min(id), max(id)
2024-05-09 21:54:22.854                 from t1
2024-05-09 21:54:22.854                 where
2024-05-09 21:54:22.854                     rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
2024-05-09 21:54:22.854                     and rdb$db_key < make_dbkey({rel_id}, 0, 0, {chk_pp+1})
2024-05-09 21:54:22.854             """
2024-05-09 21:54:22.854
2024-05-09 21:54:22.854             fetches_ini = con.info.fetches
2024-05-09 21:54:22.854             # read records from selected PP only -- FIRST TIME
2024-05-09 21:54:22.854             cur.execute(read_records_for_chk_pp)
2024-05-09 21:54:22.854             cur.fetchall()
2024-05-09 21:54:22.854             fetches_1 = con.info.fetches - fetches_ini
2024-05-09 21:54:22.854
2024-05-09 21:54:22.854             #----------------------------------
2024-05-09 21:54:22.854
2024-05-09 21:54:22.854             # delete records from selected PP and up to the end
2024-05-09 21:54:22.854             del_rows_starting_from_chk_pp = f"""
2024-05-09 21:54:22.854                 delete from t1
2024-05-09 21:54:22.854                 where rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
2024-05-09 21:54:22.854             """
2024-05-09 21:54:22.854             con.execute_immediate(del_rows_starting_from_chk_pp)
2024-05-09 21:54:22.854
2024-05-09 21:54:22.855             #----------------------------------
2024-05-09 21:54:22.855
2024-05-09 21:54:22.855             fetches_ini = con.info.fetches
2024-05-09 21:54:22.855             # read records from selected PP only -- SECOND TIME
2024-05-09 21:54:22.855             cur.execute(read_records_for_chk_pp)
2024-05-09 21:54:22.855             cur.fetchall()
2024-05-09 21:54:22.855             fetches_2 = con.info.fetches - fetches_ini
2024-05-09 21:54:22.855
2024-05-09 21:54:22.855         expected_msg = 'Fetches ratio expected.'
2024-05-09 21:54:22.855
2024-05-09 21:54:22.855         if fetches_2 <= fetches_1:
2024-05-09 21:54:22.855             print(expected_msg)
2024-05-09 21:54:22.855         else:
2024-05-09 21:54:22.855             print(f'Fetches ratio between 1st and 2nd requests to PP = {chk_pp} - UNEXPECTED:')
2024-05-09 21:54:22.855             print('Request #1:', fetches_1)
2024-05-09 21:54:22.855             print('Request #2:', fetches_2)
2024-05-09 21:54:22.855
2024-05-09 21:54:22.855         act.expected_stdout = f"""
2024-05-09 21:54:22.855             {expected_msg}
2024-05-09 21:54:22.855         """
2024-05-09 21:54:22.855         act.stdout = capsys.readouterr().out
2024-05-09 21:54:22.855 >       assert act.clean_stdout == act.clean_expected_stdout
2024-05-09 21:54:22.855 E       assert
2024-05-09 21:54:22.855 E         - Fetches ratio expected.
2024-05-09 21:54:22.855 E         + Fetches ratio between 1st and 2nd requests to PP = 0 - UNEXPECTED:
2024-05-09 21:54:22.855 E         + Request #1: 47631
2024-05-09 21:54:22.855 E         + Request #2: 115943
2024-05-09 21:54:22.855
2024-05-09 21:54:22.855 tests\bugs\gh_8104_test.py:128: AssertionError
2024-05-09 21:54:22.855 ---------------------------- Captured stdout setup ----------------------------
2024-05-09 21:54:22.855 Cached db: db-13.0-None-None-NONE.fdb [page_size=None, sql_dialect=None, charset='NONE'
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.version('>=4.0.5')
    def test_1(act: Action, capsys):
    
        get_last_pp_for_table = f"""
            select p.rdb$relation_id, p.rdb$page_sequence
            from rdb$pages p join rdb$relations r on p.rdb$relation_id = r.rdb$relation_id
            where r.rdb$relation_name = '{TAB_NAME}' and p.rdb$page_type = 4
            order by 2 desc
            rows 1
        """
        rel_id, max_pp = -1, -1
        with act.db.connect(no_gc = True) as con:
            cur = con.cursor()
            cur.execute(get_last_pp_for_table)
            for r in cur:
                rel_id, max_pp = r[:2]
            assert rel_id > 0 and max_pp > 0
            #--------------------------------
    
            # Subsequent number of PP that we want to check ('20' in the ticket):
            ##########
            chk_pp = 0
            ##########
    
            read_records_for_chk_pp = f"""
                select count(*), min(id), max(id)
                from t1
                where
                    rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
                    and rdb$db_key < make_dbkey({rel_id}, 0, 0, {chk_pp+1})
            """
    
            fetches_ini = con.info.fetches
            # read records from selected PP only -- FIRST TIME
            cur.execute(read_records_for_chk_pp)
            cur.fetchall()
            fetches_1 = con.info.fetches - fetches_ini
    
            #----------------------------------
    
            # delete records from selected PP and up to the end
            del_rows_starting_from_chk_pp = f"""
                delete from t1
                where rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
            """
            con.execute_immediate(del_rows_starting_from_chk_pp)
    
            #----------------------------------
    
            fetches_ini = con.info.fetches
            # read records from selected PP only -- SECOND TIME
            cur.execute(read_records_for_chk_pp)
            cur.fetchall()
            fetches_2 = con.info.fetches - fetches_ini
    
        expected_msg = 'Fetches ratio expected.'
    
        if fetches_2 <= fetches_1:
            print(expected_msg)
        else:
            print(f'Fetches ratio between 1st and 2nd requests to PP = {chk_pp} - UNEXPECTED:')
            print('Request #1:', fetches_1)
            print('Request #2:', fetches_2)
    
        act.expected_stdout = f"""
            {expected_msg}
        """
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - Fetches ratio expected.
E         + Fetches ratio between 1st and 2nd requests to PP = 0 - UNEXPECTED:
E         + Request #1: 47631
E         + Request #2: 115943

tests\bugs\gh_8104_test.py:128: 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 4.0.6.3189 2025.02.25 1a1a5 P P 1256 1022 2025.06.26 13:31:41.404 2025.06.26 13:31:42.660 2025.06.26 12:32:52.159 2025.06.26 12:32:53.181
2 4.0.6.3184 2025.02.24 9388c P P 1321 1061 2025.02.25 10:58:44.350 2025.02.25 10:58:45.671 2025.02.25 09:41:23.692 2025.02.25 09:41:24.753
3 4.0.6.3183 2025.02.17 e4762 P P 1335 1085 2025.02.24 11:30:49.539 2025.02.24 11:30:50.874 2025.02.24 10:31:45.966 2025.02.24 10:31:47.051
4 4.0.6.3169 2024.12.13 42cc1 P P 1279 1045 2025.02.14 08:18:39.056 2025.02.14 08:18:40.335 2025.02.14 07:19:36.477 2025.02.14 07:19:37.522
5 4.0.6.3169 2024.12.08 50eb6 P P 1274 1067 2024.12.11 11:15:12.453 2024.12.11 11:15:13.727 2024.12.11 10:16:33.218 2024.12.11 10:16:34.285
6 4.0.6.3168 2024.12.07 98d69 P P 1268 1073 2024.12.08 03:58:46.183 2024.12.08 03:58:47.451 2024.12.08 02:58:15.803 2024.12.08 02:58:16.876
7 4.0.6.3168 2024.12.05 cee43 P P 1308 1092 2024.12.06 04:01:58.355 2024.12.06 04:01:59.663 2024.12.06 03:02:50.219 2024.12.06 03:02:51.311
8 4.0.6.3168 2024.11.28 48149 P P 1289 1065 2024.12.03 10:55:12.227 2024.12.03 10:55:13.516 2024.12.03 09:57:13.855 2024.12.03 09:57:14.920
9 4.0.6.3163 2024.10.30 832db P P 1311 1049 2024.11.28 10:53:53.251 2024.11.28 10:53:54.562 2024.11.28 09:56:06.738 2024.11.28 09:56:07.787
10 4.0.6.3163 2024.10.16 2bb10 P P 1300 1056 2024.10.30 11:02:54.092 2024.10.30 11:02:55.392 2024.10.30 10:04:59.514 2024.10.30 10:05:00.570
11 4.0.6.3147 2024.09.10 a4d11 P P 1302 1040 2024.10.16 04:10:21.722 2024.10.16 04:10:23.024 2024.10.16 02:53:22.522 2024.10.16 02:53:23.562
12 4.0.6.3147 2024.08.31 4655b P P 1361 1041 2024.09.10 11:08:19.067 2024.09.10 11:08:20.428 2024.09.10 10:06:21.642 2024.09.10 10:06:22.683
13 4.0.6.3140 2024.08.16 1dd8b P P 1355 1102 2024.09.01 11:30:39.267 2024.09.01 11:30:40.622 2024.09.01 10:11:18.608 2024.09.01 10:11:19.710
14 4.0.6.3140 2024.08.09 34747 P P 1364 1091 2024.08.16 11:10:42.403 2024.08.16 11:10:43.767 2024.08.16 10:09:26.740 2024.08.16 10:09:27.831
15 4.0.5.3110 2024.08.06 f851c P P 1429 1128 2024.08.09 10:49:32.621 2024.08.09 10:49:34.050 2024.08.09 09:48:57.821 2024.08.09 09:48:58.949
16 4.0.5.3110 2024.07.30 c6527 P P 1196 989 2024.08.06 06:26:27.660 2024.08.06 06:26:28.856 2024.08.06 05:31:21.965 2024.08.06 05:31:22.954
17 4.0.5.3109 2024.06.11 6addf P P 1185 963 2024.07.30 09:44:10.272 2024.07.30 09:44:11.457 2024.07.30 08:51:06.651 2024.07.30 08:51:07.614
18 4.0.5.3097 2024.05.09 27fa6 P P 1141 906 2024.06.11 06:02:13.842 2024.06.11 06:02:14.983 2024.06.11 05:13:09.642 2024.06.11 05:13:10.548
19 4.0.5.3091 2024.04.29 bd0aa F F 1172 922 2024.05.09 18:41:16.299 2024.05.09 18:41:17.471 2024.05.09 17:52:41.883 2024.05.09 17:52:42.805

Elapsed time, ms. Chart for last 19 runs:

Last commits information (all timestamps in UTC):