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

LOG DETAILS:

2024-05-09 00:16:57.593
2024-05-09 00:16:57.599 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-09 00:16:57.606 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-09 00:16:57.613
2024-05-09 00:16:57.618 @pytest.mark.version('>=4.0.5')
2024-05-09 00:16:57.623 def test_1(act: Action, capsys):
2024-05-09 00:16:57.629
2024-05-09 00:16:57.637 get_last_pp_for_table = f"""
2024-05-09 00:16:57.641 select p.rdb$relation_id, p.rdb$page_sequence
2024-05-09 00:16:57.646 from rdb$pages p join rdb$relations r on p.rdb$relation_id = r.rdb$relation_id
2024-05-09 00:16:57.651 where r.rdb$relation_name = '{TAB_NAME}' and p.rdb$page_type = 4
2024-05-09 00:16:57.656 order by 2 desc
2024-05-09 00:16:57.660 rows 1
2024-05-09 00:16:57.666 """
2024-05-09 00:16:57.674 rel_id, max_pp = -1, -1
2024-05-09 00:16:57.680 with act.db.connect(no_gc = True) as con:
2024-05-09 00:16:57.685 cur = con.cursor()
2024-05-09 00:16:57.690 cur.execute(get_last_pp_for_table)
2024-05-09 00:16:57.694 for r in cur:
2024-05-09 00:16:57.702 rel_id, max_pp = r[:2]
2024-05-09 00:16:57.708 assert rel_id > 0 and max_pp > 0
2024-05-09 00:16:57.714 #--------------------------------
2024-05-09 00:16:57.721
2024-05-09 00:16:57.727 # Subsequent number of PP that we want to check ('20' in the ticket):
2024-05-09 00:16:57.732 ##########
2024-05-09 00:16:57.737 chk_pp = 0
2024-05-09 00:16:57.742 ##########
2024-05-09 00:16:57.747
2024-05-09 00:16:57.752 read_records_for_chk_pp = f"""
2024-05-09 00:16:57.757 select count(*), min(id), max(id)
2024-05-09 00:16:57.762 from t1
2024-05-09 00:16:57.768 where
2024-05-09 00:16:57.773 rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
2024-05-09 00:16:57.778 and rdb$db_key < make_dbkey({rel_id}, 0, 0, {chk_pp+1})
2024-05-09 00:16:57.784 """
2024-05-09 00:16:57.790
2024-05-09 00:16:57.795 fetches_ini = con.info.fetches
2024-05-09 00:16:57.802 # read records from selected PP only -- FIRST TIME
2024-05-09 00:16:57.807 cur.execute(read_records_for_chk_pp)
2024-05-09 00:16:57.814 cur.fetchall()
2024-05-09 00:16:57.820 fetches_1 = con.info.fetches - fetches_ini
2024-05-09 00:16:57.825
2024-05-09 00:16:57.830 #----------------------------------
2024-05-09 00:16:57.835
2024-05-09 00:16:57.840 # delete records from selected PP and up to the end
2024-05-09 00:16:57.845 del_rows_starting_from_chk_pp = f"""
2024-05-09 00:16:57.850 delete from t1
2024-05-09 00:16:57.854 where rdb$db_key >= make_dbkey({rel_id}, 0, 0, {chk_pp})
2024-05-09 00:16:57.861 """
2024-05-09 00:16:57.866 con.execute_immediate(del_rows_starting_from_chk_pp)
2024-05-09 00:16:57.870
2024-05-09 00:16:57.875 #----------------------------------
2024-05-09 00:16:57.879
2024-05-09 00:16:57.887 fetches_ini = con.info.fetches
2024-05-09 00:16:57.898 # read records from selected PP only -- SECOND TIME
2024-05-09 00:16:57.907 cur.execute(read_records_for_chk_pp)
2024-05-09 00:16:57.915 cur.fetchall()
2024-05-09 00:16:57.922 fetches_2 = con.info.fetches - fetches_ini
2024-05-09 00:16:57.930
2024-05-09 00:16:57.936 expected_msg = 'Fetches ratio expected.'
2024-05-09 00:16:57.942
2024-05-09 00:16:57.948 if fetches_2 <= fetches_1:
2024-05-09 00:16:57.954 print(expected_msg)
2024-05-09 00:16:57.960 else:
2024-05-09 00:16:57.966 print(f'Fetches ratio between 1st and 2nd requests to PP = {chk_pp} - UNEXPECTED:')
2024-05-09 00:16:57.971 print('Request #1:', fetches_1)
2024-05-09 00:16:57.977 print('Request #2:', fetches_2)
2024-05-09 00:16:57.984
2024-05-09 00:16:57.990 act.expected_stdout = f"""
2024-05-09 00:16:57.996 {expected_msg}
2024-05-09 00:16:58.002 """
2024-05-09 00:16:58.008 act.stdout = capsys.readouterr().out
2024-05-09 00:16:58.013 >       assert act.clean_stdout == act.clean_expected_stdout
2024-05-09 00:16:58.019 E       assert
2024-05-09 00:16:58.023 E         - Fetches ratio expected.
2024-05-09 00:16:58.028 E         + Fetches ratio between 1st and 2nd requests to PP = 0 - UNEXPECTED:
2024-05-09 00:16:58.033 E         + Request #1: 47645
2024-05-09 00:16:58.037 E         + Request #2: 115943
2024-05-09 00:16:58.042
2024-05-09 00:16:58.046 tests/bugs/gh_8104_test.py:116: AssertionError
2024-05-09 00:16:58.051 ---------------------------- Captured stdout setup -----------------------------
2024-05-09 00:16:58.056 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: 47645
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 2036 1965 2025.06.26 14:48:51.020 2025.06.26 14:48:53.056 2025.06.26 13:39:12.419 2025.06.26 13:39:14.384
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):