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
Performance problem

assert   
  - Ratio between memory values measured before and after loop: acceptable
  + Ratio: /* perf_issue_tag */ POOR: 62.53, more than threshold: 3.00

LOG DETAILS:

2025-03-13 13:11:09.710
2025-03-13 13:11:09.710 act = <firebird.qa.plugin.Action object at [hex]>
2025-03-13 13:11:09.710 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-03-13 13:11:09.710
2025-03-13 13:11:09.710     @pytest.mark.version('>=4.0.0')
2025-03-13 13:11:09.710     def test_1(act: Action, capsys):
2025-03-13 13:11:09.710
2025-03-13 13:11:09.710         with act.db.connect() as con:
2025-03-13 13:11:09.710
2025-03-13 13:11:09.710             sp_ddl = """
2025-03-13 13:11:09.710                 create or alter procedure sp_test(
2025-03-13 13:11:09.710             """
2025-03-13 13:11:09.710             params_lst = '\n'.join( [  (',' if i else '') +f'p_{i} int' for i in range(PARAMS_COUNT) ] )
2025-03-13 13:11:09.710             sp_ddl = '\n'.join( ("create or alter procedure sp_test(", params_lst, ") returns(x int) as begin x = 1; suspend; end") )
2025-03-13 13:11:09.710             con.execute_immediate(sp_ddl)
2025-03-13 13:11:09.710             con.commit()
2025-03-13 13:11:09.711
2025-03-13 13:11:09.711             server_process = psutil.Process(get_server_pid(con))
2025-03-13 13:11:09.711
2025-03-13 13:11:09.711             params_lst = ','.join( [ f':p_{i}' for i in range(PARAMS_COUNT) ] )
2025-03-13 13:11:09.711             passed_args = ','.join( [ f'excess p_{i} := 1' for i in range(PARAMS_COUNT) ] )
2025-03-13 13:11:09.711
2025-03-13 13:11:09.711             srv_memo_rss_init = int(server_process.memory_info().rss / 1024)
2025-03-13 13:11:09.711             srv_memo_vms_init = int(server_process.memory_info().vms / 1024)
2025-03-13 13:11:09.711
2025-03-13 13:11:09.711             cur = con.cursor()
2025-03-13 13:11:09.711             for k in range(MEASURES_COUNT):
2025-03-13 13:11:09.711
2025-03-13 13:11:09.711                 es_sql = f"""
2025-03-13 13:11:09.711                     execute block returns(x int) as
2025-03-13 13:11:09.711                     begin
2025-03-13 13:11:09.711                         execute statement ('select p.x * {k} from sp_test({params_lst}) p') ({passed_args})
2025-03-13 13:11:09.711                         into x;
2025-03-13 13:11:09.711                         suspend;
2025-03-13 13:11:09.711                     end
2025-03-13 13:11:09.711                 """
2025-03-13 13:11:09.712                 cur.execute(es_sql)
2025-03-13 13:11:09.712                 for r in cur:
2025-03-13 13:11:09.712                     pass
2025-03-13 13:11:09.712
2025-03-13 13:11:09.712             srv_memo_rss_curr = int(server_process.memory_info().rss / 1024)
2025-03-13 13:11:09.712             srv_memo_vms_curr = int(server_process.memory_info().vms / 1024)
2025-03-13 13:11:09.712
2025-03-13 13:11:09.712         memo_ratio = srv_memo_rss_curr / srv_memo_rss_init
2025-03-13 13:11:09.712
2025-03-13 13:11:09.712         SUCCESS_MSG = 'Ratio between memory values measured before and after loop: acceptable'
2025-03-13 13:11:09.712         if memo_ratio < MAX_RATIO:
2025-03-13 13:11:09.712             print(SUCCESS_MSG)
2025-03-13 13:11:09.712         else:
2025-03-13 13:11:09.712             print( 'Ratio: /* perf_issue_tag */ POOR: %s, more than threshold: %s' % ( '{:.2f}'.format(memo_ratio), '{:.2f}'.format(MAX_RATIO) ) )
2025-03-13 13:11:09.712
2025-03-13 13:11:09.712         act.expected_stdout = SUCCESS_MSG
2025-03-13 13:11:09.712         act.stdout = capsys.readouterr().out
2025-03-13 13:11:09.712 >       assert act.clean_stdout == act.clean_expected_stdout
2025-03-13 13:11:09.712 E       assert
2025-03-13 13:11:09.712 E         - Ratio between memory values measured before and after loop: acceptable
2025-03-13 13:11:09.713 E         + Ratio: /* perf_issue_tag */ POOR: 62.53, more than threshold: 3.00
2025-03-13 13:11:09.713
2025-03-13 13:11:09.713 tests\bugs\gh_6706_test.py:108: AssertionError
2025-03-13 13:11:09.713 ---------------------------- Captured stdout setup ----------------------------
2025-03-13 13:11:09.713 Creating db: localhost:H:\QA\temp\qa2024.tmp\fbqa\test_11441\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('>=4.0.0')
    def test_1(act: Action, capsys):
    
        with act.db.connect() as con:
    
            sp_ddl = """
                create or alter procedure sp_test(
            """
            params_lst = '\n'.join( [  (',' if i else '') +f'p_{i} int' for i in range(PARAMS_COUNT) ] )
            sp_ddl = '\n'.join( ("create or alter procedure sp_test(", params_lst, ") returns(x int) as begin x = 1; suspend; end") )
            con.execute_immediate(sp_ddl)
            con.commit()
    
            server_process = psutil.Process(get_server_pid(con))
    
            params_lst = ','.join( [ f':p_{i}' for i in range(PARAMS_COUNT) ] )
            passed_args = ','.join( [ f'excess p_{i} := 1' for i in range(PARAMS_COUNT) ] )
    
            srv_memo_rss_init = int(server_process.memory_info().rss / 1024)
            srv_memo_vms_init = int(server_process.memory_info().vms / 1024)
    
            cur = con.cursor()
            for k in range(MEASURES_COUNT):
    
                es_sql = f"""
                    execute block returns(x int) as
                    begin
                        execute statement ('select p.x * {k} from sp_test({params_lst}) p') ({passed_args})
                        into x;
                        suspend;
                    end
                """
                cur.execute(es_sql)
                for r in cur:
                    pass
    
            srv_memo_rss_curr = int(server_process.memory_info().rss / 1024)
            srv_memo_vms_curr = int(server_process.memory_info().vms / 1024)
    
        memo_ratio = srv_memo_rss_curr / srv_memo_rss_init
    
        SUCCESS_MSG = 'Ratio between memory values measured before and after loop: acceptable'
        if memo_ratio < MAX_RATIO:
            print(SUCCESS_MSG)
        else:
            print( 'Ratio: /* perf_issue_tag */ POOR: %s, more than threshold: %s' % ( '{:.2f}'.format(memo_ratio), '{:.2f}'.format(MAX_RATIO) ) )
    
        act.expected_stdout = SUCCESS_MSG
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - Ratio between memory values measured before and after loop: acceptable
E         + Ratio: /* perf_issue_tag */ POOR: 62.53, more than threshold: 3.00

tests\bugs\gh_6706_test.py:108: 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 17411 17788 2025.06.29 10:57:33.088 2025.06.29 10:57:50.499 2025.06.29 09:58:36.001 2025.06.29 09:58:53.789
2 5.0.3.1657 2025.06.26 dcb8a P P 17352 17227 2025.06.27 10:58:20.204 2025.06.27 10:58:37.556 2025.06.27 09:59:18.223 2025.06.27 09:59:35.450
3 5.0.3.1657 2025.06.20 8b4d2 P P 17391 17282 2025.06.26 11:12:46.611 2025.06.26 11:13:04.002 2025.06.26 10:13:37.179 2025.06.26 10:13:54.461
4 5.0.3.1657 2025.06.19 4bd4c P P 17649 17683 2025.06.20 05:16:51.705 2025.06.20 05:17:09.354 2025.06.20 04:17:48.968 2025.06.20 04:18:06.651
5 5.0.3.1657 2025.06.11 dae6f P P 17528 17548 2025.06.19 10:48:28.024 2025.06.19 10:48:45.552 2025.06.19 09:49:13.905 2025.06.19 09:49:31.453
6 5.0.3.1657 2025.06.10 dbc92 P P 17693 17570 2025.06.11 08:34:36.373 2025.06.11 08:34:54.066 2025.06.11 07:35:10.601 2025.06.11 07:35:28.171
7 5.0.3.1656 2025.06.05 00512 P P 17993 17863 2025.06.10 09:50:03.784 2025.06.10 09:50:21.777 2025.06.10 08:50:13.799 2025.06.10 08:50:31.662
8 5.0.3.1656 2025.05.20 c4b11 P P 17746 17311 2025.06.03 09:37:01.480 2025.06.03 09:37:19.226 2025.06.03 08:38:24.005 2025.06.03 08:38:41.316
9 5.0.3.1652 2025.05.13 f51c6 P P 17501 17410 2025.05.21 06:18:06.460 2025.05.21 06:18:23.961 2025.05.21 05:19:38.490 2025.05.21 05:19:55.900
10 5.0.3.1651 2025.05.08 ee9d2 P P 17473 17817 2025.05.13 06:30:38.062 2025.05.13 06:30:55.535 2025.05.13 05:13:43.432 2025.05.13 05:14:01.249
11 5.0.3.1651 2025.05.04 3d914 P P 17440 17394 2025.05.09 04:19:45.093 2025.05.09 04:20:02.533 2025.05.09 03:02:45.538 2025.05.09 03:03:02.932
12 5.0.3.1651 2025.04.30 141ef P P 17384 17486 2025.05.02 04:27:25.348 2025.05.02 04:27:42.732 2025.05.02 03:10:34.234 2025.05.02 03:10:51.720
13 5.0.3.1650 2025.04.30 6253f P P 17385 18016 2025.05.01 04:26:28.980 2025.05.01 04:26:46.365 2025.05.01 03:09:24.089 2025.05.01 03:09:42.105
14 5.0.3.1650 2025.04.28 4cbff P P 17457 17643 2025.04.30 04:25:28.631 2025.04.30 04:25:46.088 2025.04.30 03:08:47.423 2025.04.30 03:09:05.066
15 5.0.3.1649 2025.04.21 5b2d0 P P 17665 17523 2025.04.26 09:59:01.863 2025.04.26 09:59:19.528 2025.04.26 08:41:26.775 2025.04.26 08:41:44.298
16 5.0.3.1648 2025.04.18 2f4c5 P P 17785 17558 2025.04.20 04:10:15.726 2025.04.20 04:10:33.511 2025.04.20 03:10:51.794 2025.04.20 03:11:09.352
17 5.0.3.1635 2025.04.03 f6bd1 P P 17814 17699 2025.04.18 06:37:56.807 2025.04.18 06:38:14.621 2025.04.18 05:20:07.369 2025.04.18 05:20:25.068
18 5.0.3.1635 2025.03.31 22ec6 P P 17604 17551 2025.04.03 09:43:46.591 2025.04.03 09:44:04.195 2025.04.03 08:25:26.967 2025.04.03 08:25:44.518
19 5.0.3.1633 2025.03.28 3123a P P 17901 17608 2025.03.31 09:42:16.073 2025.03.31 09:42:33.974 2025.03.31 08:24:03.949 2025.03.31 08:24:21.557
20 5.0.3.1633 2025.03.27 e0fb8 F F 18623 19629 2025.03.28 10:13:33.755 2025.03.28 10:13:52.378 2025.03.28 08:51:32.818 2025.03.28 08:51:52.447
21 5.0.3.1631 2025.03.25 bda65 F F 19247 18782 2025.03.27 09:54:04.600 2025.03.27 09:54:23.847 2025.03.27 08:50:53.206 2025.03.27 08:51:11.988
22 5.0.3.1631 2025.03.21 1925b F F 18842 18818 2025.03.25 06:28:04.409 2025.03.25 06:28:23.251 2025.03.25 05:24:50.933 2025.03.25 05:25:09.751
23 5.0.3.1629 2025.03.18 506d7 F F 18861 18790 2025.03.20 09:28:34.685 2025.03.20 09:28:53.546 2025.03.20 08:25:10.392 2025.03.20 08:25:29.182
24 5.0.3.1628 2025.03.14 16d05 F F 18974 18849 2025.03.18 09:22:47.719 2025.03.18 09:23:06.693 2025.03.18 08:20:44.596 2025.03.18 08:21:03.445
25 5.0.3.1627 2025.02.26 4e218 F F 18645 18777 2025.03.13 09:41:53.540 2025.03.13 09:42:12.185 2025.03.13 08:38:16.678 2025.03.13 08:38:35.455
26 5.0.3.1624 2025.02.25 dc3b2 F F 18534 18706 2025.02.26 15:14:07.982 2025.02.26 15:14:26.516 2025.02.26 14:11:06.946 2025.02.26 14:11:25.652
27 5.0.2.1615 2025.02.20 4a726 F F 18494 18344 2025.02.25 08:28:41.100 2025.02.25 08:28:59.594 2025.02.25 07:09:03.302 2025.02.25 07:09:21.646
28 5.0.2.1615 2025.02.14 9cb76 F F 18221 18300 2025.02.15 03:56:31.807 2025.02.15 03:56:50.028 2025.02.15 02:55:15.947 2025.02.15 02:55:34.247
29 5.0.2.1577 2025.02.07 f50a2 P P 17644 17653 2025.02.14 06:09:13.274 2025.02.14 06:09:30.918 2025.02.14 05:09:12.397 2025.02.14 05:09:30.050
30 5.0.2.1577 2024.12.24 3c80e P P 17945 17881 2025.02.06 09:22:42.370 2025.02.06 09:23:00.315 2025.02.06 08:22:40.649 2025.02.06 08:22:58.530
31 5.0.2.1576 2024.12.17 646b0 P P 18416 18391 2024.12.24 09:05:56.966 2024.12.24 09:06:15.382 2024.12.24 08:06:10.628 2024.12.24 08:06:29.019
32 5.0.2.1575 2024.12.09 9af52 P P 17954 18331 2024.12.16 09:02:56.539 2024.12.16 09:03:14.493 2024.12.16 08:03:12.629 2024.12.16 08:03:30.960
33 5.0.2.1575 2024.12.08 63d39 P P 17833 17789 2024.12.09 14:53:36.885 2024.12.09 14:53:54.718 2024.12.09 13:58:50.124 2024.12.09 13:59:07.913
34 5.0.2.1571 2024.12.08 8d11a P P 17984 17586 2024.12.09 06:07:02.271 2024.12.09 06:07:20.255 2024.12.09 05:10:18.039 2024.12.09 05:10:35.625
35 5.0.2.1567 2024.12.07 b01a2 P P 17644 17862 2024.12.08 01:44:10.310 2024.12.08 01:44:27.954 2024.12.08 00:46:11.941 2024.12.08 00:46:29.803
36 5.0.2.1567 2024.12.02 6ae74 P P 17862 17491 2024.12.04 08:49:10.296 2024.12.04 08:49:28.158 2024.12.04 07:54:14.164 2024.12.04 07:54:31.655
37 5.0.2.1567 2024.11.26 56e63 P P 25910 17763 2024.11.30 08:53:45.905 2024.11.30 08:54:11.815 2024.11.30 07:54:46.558 2024.11.30 07:55:04.321
38 5.0.2.1567 2024.11.21 96f61 P P 17823 17902 2024.11.27 08:50:43.336 2024.11.27 08:51:01.159 2024.11.27 07:52:08.213 2024.11.27 07:52:26.115
39 5.0.2.1567 2024.11.18 e1289 P E 17805 2252 2024.11.21 09:09:05.466 2024.11.21 09:09:23.271 2024.11.21 07:49:55.280 2024.11.21 07:49:57.532
40 5.0.2.1533 2024.10.23 0ec43 P P 17789 18058 2024.11.18 08:44:54.120 2024.11.18 08:45:11.909 2024.11.18 07:45:38.574 2024.11.18 07:45:56.632
41 5.0.2.1533 2024.10.22 8af7a P P 17864 17826 2024.10.23 08:52:14.105 2024.10.23 08:52:31.969 2024.10.23 07:53:33.170 2024.10.23 07:53:50.996
42 5.0.2.1532 2024.10.15 36dc0 P P 17586 17551 2024.10.22 14:54:20.775 2024.10.22 14:54:38.361 2024.10.22 13:55:37.103 2024.10.22 13:55:54.654
43 5.0.2.1518 2024.10.04 259ba P P 17417 17336 2024.10.15 08:48:26.297 2024.10.15 08:48:43.714 2024.10.15 07:49:53.385 2024.10.15 07:50:10.721
44 5.0.2.1518 2024.09.26 703cd P P 17688 17912 2024.10.03 08:53:20.450 2024.10.03 08:53:38.138 2024.10.03 07:54:31.058 2024.10.03 07:54:48.970
45 5.0.2.1489 2024.08.31 994a6 P P 17562 17507 2024.09.26 09:12:00.139 2024.09.26 09:12:17.701 2024.09.26 07:54:30.348 2024.09.26 07:54:47.855
46 5.0.2.1476 2024.08.09 843ea P P 17737 17654 2024.09.01 09:00:39.465 2024.09.01 09:00:57.202 2024.09.01 07:41:34.152 2024.09.01 07:41:51.806

Elapsed time, ms. Chart for last 46 runs:

Last commits information (all timestamps in UTC):