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: 47670
  + Request #2: 115943

LOG DETAILS:

2024-05-08 23:21:30.904
2024-05-08 23:21:30.910 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-08 23:21:30.915 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-08 23:21:30.920
2024-05-08 23:21:30.926 @pytest.mark.version('>=4.0.5')
2024-05-08 23:21:30.931 def test_1(act: Action, capsys):
2024-05-08 23:21:30.936
2024-05-08 23:21:30.942 get_last_pp_for_table = f"""
2024-05-08 23:21:30.947 select p.rdb$relation_id, p.rdb$page_sequence
2024-05-08 23:21:30.951 from rdb$pages p join rdb$relations r on p.rdb$relation_id = r.rdb$relation_id
2024-05-08 23:21:30.956 where r.rdb$relation_name = '{TAB_NAME}' and p.rdb$page_type = 4
2024-05-08 23:21:30.961 order by 2 desc
2024-05-08 23:21:30.967 rows 1
2024-05-08 23:21:30.971 """
2024-05-08 23:21:30.976 rel_id, max_pp = -1, -1
2024-05-08 23:21:30.982 with act.db.connect(no_gc = True) as con:
2024-05-08 23:21:30.988 cur = con.cursor()
2024-05-08 23:21:30.994 cur.execute(get_last_pp_for_table)
2024-05-08 23:21:31.000 for r in cur:
2024-05-08 23:21:31.006 rel_id, max_pp = r[:2]
2024-05-08 23:21:31.011 assert rel_id > 0 and max_pp > 0
2024-05-08 23:21:31.016 #--------------------------------
2024-05-08 23:21:31.021
2024-05-08 23:21:31.026 # Subsequent number of PP that we want to check ('20' in the ticket):
2024-05-08 23:21:31.031 ##########
2024-05-08 23:21:31.036 chk_pp = 0
2024-05-08 23:21:31.041 ##########
2024-05-08 23:21:31.047
2024-05-08 23:21:31.053 read_records_for_chk_pp = f"""
2024-05-08 23:21:31.060 select count(*), min(id), max(id)
2024-05-08 23:21:31.067 from t1
2024-05-08 23:21:31.073 where
2024-05-08 23:21:31.080 rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
2024-05-08 23:21:31.086 and rdb$db_key < make_dbkey({rel_id}, 0, 0, {chk_pp+1})
2024-05-08 23:21:31.093 """
2024-05-08 23:21:31.099
2024-05-08 23:21:31.106 fetches_ini = con.info.fetches
2024-05-08 23:21:31.117 # read records from selected PP only -- FIRST TIME
2024-05-08 23:21:31.124 cur.execute(read_records_for_chk_pp)
2024-05-08 23:21:31.130 cur.fetchall()
2024-05-08 23:21:31.135 fetches_1 = con.info.fetches - fetches_ini
2024-05-08 23:21:31.140
2024-05-08 23:21:31.145 #----------------------------------
2024-05-08 23:21:31.150
2024-05-08 23:21:31.156 # delete records from selected PP and up to the end
2024-05-08 23:21:31.161 del_rows_starting_from_chk_pp = f"""
2024-05-08 23:21:31.167 delete from t1
2024-05-08 23:21:31.172 where rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
2024-05-08 23:21:31.177 """
2024-05-08 23:21:31.182 con.execute_immediate(del_rows_starting_from_chk_pp)
2024-05-08 23:21:31.187
2024-05-08 23:21:31.192 #----------------------------------
2024-05-08 23:21:31.197
2024-05-08 23:21:31.202 fetches_ini = con.info.fetches
2024-05-08 23:21:31.207 # read records from selected PP only -- SECOND TIME
2024-05-08 23:21:31.212 cur.execute(read_records_for_chk_pp)
2024-05-08 23:21:31.217 cur.fetchall()
2024-05-08 23:21:31.223 fetches_2 = con.info.fetches - fetches_ini
2024-05-08 23:21:31.229
2024-05-08 23:21:31.235 expected_msg = 'Fetches ratio expected.'
2024-05-08 23:21:31.240
2024-05-08 23:21:31.245 if fetches_2 <= fetches_1:
2024-05-08 23:21:31.249 print(expected_msg)
2024-05-08 23:21:31.254 else:
2024-05-08 23:21:31.259 print(f'Fetches ratio between 1st and 2nd requests to PP = {chk_pp} - UNEXPECTED:')
2024-05-08 23:21:31.265 print('Request #1:', fetches_1)
2024-05-08 23:21:31.270 print('Request #2:', fetches_2)
2024-05-08 23:21:31.277
2024-05-08 23:21:31.285 act.expected_stdout = f"""
2024-05-08 23:21:31.292 {expected_msg}
2024-05-08 23:21:31.297 """
2024-05-08 23:21:31.302 act.stdout = capsys.readouterr().out
2024-05-08 23:21:31.306 >       assert act.clean_stdout == act.clean_expected_stdout
2024-05-08 23:21:31.311 E       assert
2024-05-08 23:21:31.316 E         - Fetches ratio expected.
2024-05-08 23:21:31.323 E         + Fetches ratio between 1st and 2nd requests to PP = 0 - UNEXPECTED:
2024-05-08 23:21:31.328 E         + Request #1: 47670
2024-05-08 23:21:31.332 E         + Request #2: 115943
2024-05-08 23:21:31.337
2024-05-08 23:21:31.342 tests/bugs/gh_8104_test.py:116: AssertionError
2024-05-08 23:21:31.348 ---------------------------- Captured stdout setup -----------------------------
2024-05-08 23:21:31.353 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: 47670
E         + Request #2: 115943

tests/bugs/gh_8104_test.py:116: 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 2466 2046 2025.07.02 13:37:08.525 2025.07.02 13:37:10.991 2025.07.02 12:21:42.498 2025.07.02 12:21:44.544
2 4.0.6.3184 2025.02.24 9388c P P 684 476 2025.02.25 13:49:39.774 2025.02.25 13:49:40.458 2025.02.25 12:30:12.219 2025.02.25 12:30:12.695
3 4.0.6.3183 2025.02.16 cf6ca P P 700 440 2025.02.17 07:43:52.645 2025.02.17 07:43:53.345 2025.02.17 06:23:46.862 2025.02.17 06:23:47.302
4 4.0.6.3169 2024.12.13 42cc1 P P 718 495 2025.02.16 04:40:59.656 2025.02.16 04:41:00.374 2025.02.16 03:23:04.240 2025.02.16 03:23:04.735
5 4.0.6.3169 2024.12.08 50eb6 P P 519 364 2024.12.12 18:57:50.578 2024.12.12 18:57:51.097 2024.12.12 17:55:28.146 2024.12.12 17:55:28.510
6 4.0.6.3168 2024.11.28 48149 P P 491 369 2024.12.06 03:18:42.792 2024.12.06 03:18:43.283 2024.12.06 02:18:02.674 2024.12.06 02:18:03.043
7 4.0.6.3163 2024.10.16 2bb10 P P 524 361 2024.11.27 13:43:23.246 2024.11.27 13:43:23.770 2024.11.27 10:41:44.685 2024.11.27 10:41:45.046
8 4.0.6.3163 2024.10.15 f387e P P 496 378 2024.10.16 04:48:43.293 2024.10.16 04:48:43.789 2024.10.16 03:51:01.831 2024.10.16 03:51:02.209
9 4.0.6.3147 2024.08.31 4655b P P 551 358 2024.09.30 12:04:59.123 2024.09.30 12:04:59.674 2024.09.30 11:00:30.385 2024.09.30 11:00:30.743
10 4.0.6.3140 2024.08.16 1dd8b P P 1337 649 2024.08.31 18:37:16.662 2024.08.31 18:37:17.999 2024.08.31 16:41:23.548 2024.08.31 16:41:24.197
11 4.0.6.3140 2024.08.09 34747 P P 677 478 2024.08.16 11:09:51.056 2024.08.16 11:09:51.733 2024.08.16 09:59:44.598 2024.08.16 09:59:45.076
12 4.0.5.3110 2024.07.30 c6527 P P 771 505 2024.08.09 11:00:20.366 2024.08.09 11:00:21.137 2024.08.09 09:50:26.929 2024.08.09 09:50:27.434
13 4.0.5.3109 2024.06.11 6addf P P 419 333 2024.07.30 09:18:48.338 2024.07.30 09:18:48.757 2024.07.30 08:17:35.375 2024.07.30 08:17:35.708
14 4.0.5.3097 2024.05.09 27fa6 P P 775 560 2024.05.14 10:03:15.412 2024.05.14 10:03:16.187 2024.05.14 09:00:52.254 2024.05.14 09:00:52.814
15 4.0.5.3091 2024.04.29 bd0aa F F 520 364 2024.05.08 21:04:41.371 2024.05.08 21:04:41.891 2024.05.08 20:11:23.916 2024.05.08 20:11:24.280

Elapsed time, ms. Chart for last 15 runs:

Last commits information (all timestamps in UTC):