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: 45.19, more than threshold: 3.00

LOG DETAILS:

2025-02-26 14:02:03.299
2025-02-26 14:02:03.307 act = <firebird.qa.plugin.Action object at [hex]>
2025-02-26 14:02:03.318 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-02-26 14:02:03.332
2025-02-26 14:02:03.341 @pytest.mark.version('>=4.0.0')
2025-02-26 14:02:03.356 def test_1(act: Action, capsys):
2025-02-26 14:02:03.366
2025-02-26 14:02:03.374 with act.db.connect() as con:
2025-02-26 14:02:03.383
2025-02-26 14:02:03.390 sp_ddl = """
2025-02-26 14:02:03.397 create or alter procedure sp_test(
2025-02-26 14:02:03.405 """
2025-02-26 14:02:03.412 params_lst = '\n'.join( [  (',' if i else '') +f'p_{i} int' for i in range(PARAMS_COUNT) ] )
2025-02-26 14:02:03.418 sp_ddl = '\n'.join( ("create or alter procedure sp_test(", params_lst, ") returns(x int) as begin x = 1; suspend; end") )
2025-02-26 14:02:03.426 con.execute_immediate(sp_ddl)
2025-02-26 14:02:03.434 con.commit()
2025-02-26 14:02:03.443
2025-02-26 14:02:03.453 server_process = psutil.Process(get_server_pid(con))
2025-02-26 14:02:03.461
2025-02-26 14:02:03.468 params_lst = ','.join( [ f':p_{i}' for i in range(PARAMS_COUNT) ] )
2025-02-26 14:02:03.482 passed_args = ','.join( [ f'excess p_{i} := 1' for i in range(PARAMS_COUNT) ] )
2025-02-26 14:02:03.496
2025-02-26 14:02:03.506 srv_memo_rss_init = int(server_process.memory_info().rss / 1024)
2025-02-26 14:02:03.517 srv_memo_vms_init = int(server_process.memory_info().vms / 1024)
2025-02-26 14:02:03.529
2025-02-26 14:02:03.538 cur = con.cursor()
2025-02-26 14:02:03.544 for k in range(MEASURES_COUNT):
2025-02-26 14:02:03.554
2025-02-26 14:02:03.560 es_sql = f"""
2025-02-26 14:02:03.566 execute block returns(x int) as
2025-02-26 14:02:03.573 begin
2025-02-26 14:02:03.581 execute statement ('select p.x * {k} from sp_test({params_lst}) p') ({passed_args})
2025-02-26 14:02:03.587 into x;
2025-02-26 14:02:03.593 suspend;
2025-02-26 14:02:03.600 end
2025-02-26 14:02:03.608 """
2025-02-26 14:02:03.615 cur.execute(es_sql)
2025-02-26 14:02:03.622 for r in cur:
2025-02-26 14:02:03.633 pass
2025-02-26 14:02:03.640
2025-02-26 14:02:03.647 srv_memo_rss_curr = int(server_process.memory_info().rss / 1024)
2025-02-26 14:02:03.653 srv_memo_vms_curr = int(server_process.memory_info().vms / 1024)
2025-02-26 14:02:03.659
2025-02-26 14:02:03.673 memo_ratio = srv_memo_rss_curr / srv_memo_rss_init
2025-02-26 14:02:03.684
2025-02-26 14:02:03.698 SUCCESS_MSG = 'Ratio between memory values measured before and after loop: acceptable'
2025-02-26 14:02:03.714 if memo_ratio < MAX_RATIO:
2025-02-26 14:02:03.726 print(SUCCESS_MSG)
2025-02-26 14:02:03.735 else:
2025-02-26 14:02:03.750 print( 'Ratio: /* perf_issue_tag */ POOR: %s, more than threshold: %s' % ( '{:.2f}'.format(memo_ratio), '{:.2f}'.format(MAX_RATIO) ) )
2025-02-26 14:02:03.762
2025-02-26 14:02:03.771 act.expected_stdout = SUCCESS_MSG
2025-02-26 14:02:03.778 act.stdout = capsys.readouterr().out
2025-02-26 14:02:03.785 >       assert act.clean_stdout == act.clean_expected_stdout
2025-02-26 14:02:03.796 E       assert
2025-02-26 14:02:03.809 E         - Ratio between memory values measured before and after loop: acceptable
2025-02-26 14:02:03.819 E         + Ratio: /* perf_issue_tag */ POOR: 45.19, more than threshold: 3.00
2025-02-26 14:02:03.828
2025-02-26 14:02:03.836 tests/bugs/gh_6706_test.py:108: AssertionError
2025-02-26 14:02:03.846 ---------------------------- Captured stdout setup -----------------------------
2025-02-26 14:02:03.858 Creating db: localhost:/var/tmp/qa_2024/test_11422/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: 45.19, 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 49093 48021 2025.07.03 10:44:11.767 2025.07.03 10:45:00.860 2025.07.03 09:26:02.285 2025.07.03 09:26:50.306
2 5.0.3.1657 2025.06.19 4bd4c P P 49586 48025 2025.06.27 12:08:27.362 2025.06.27 12:09:16.948 2025.06.27 10:51:32.484 2025.06.27 10:52:20.509
3 5.0.3.1657 2025.06.11 dae6f P P 48881 47902 2025.06.17 07:13:13.074 2025.06.17 07:14:01.955 2025.06.17 05:55:11.074 2025.06.17 05:55:58.976
4 5.0.3.1657 2025.06.10 dbc92 P P 48059 59373 2025.06.11 12:04:41.600 2025.06.11 12:05:29.659 2025.06.11 10:34:54.027 2025.06.11 10:35:53.400
5 5.0.3.1656 2025.05.20 c4b11 P P 56275 55883 2025.06.10 11:56:45.400 2025.06.10 11:57:41.675 2025.06.10 10:34:49.033 2025.06.10 10:35:44.916
6 5.0.3.1652 2025.05.13 f51c6 P P 62265 59023 2025.05.20 04:58:38.632 2025.05.20 04:59:40.897 2025.05.20 03:25:19.650 2025.05.20 03:26:18.673
7 5.0.3.1651 2025.04.30 141ef P P 63757 63242 2025.05.13 11:57:02.711 2025.05.13 11:58:06.468 2025.05.13 10:22:12.449 2025.05.13 10:23:15.691
8 5.0.3.1650 2025.04.28 4cbff P P 61696 62755 2025.05.01 11:30:36.142 2025.05.01 11:31:37.838 2025.05.01 09:56:53.319 2025.05.01 09:57:56.074
9 5.0.3.1649 2025.04.21 5b2d0 P P 63405 61980 2025.04.28 05:28:46.233 2025.04.28 05:29:49.638 2025.04.28 03:57:07.382 2025.04.28 03:58:09.362
10 5.0.3.1648 2025.04.18 2f4c5 P P 63504 59750 2025.04.20 05:20:39.684 2025.04.20 05:21:43.188 2025.04.20 03:52:02.116 2025.04.20 03:53:01.866
11 5.0.3.1635 2025.03.31 22ec6 P P 61414 63530 2025.04.18 11:43:17.261 2025.04.18 11:44:18.675 2025.04.18 10:10:04.407 2025.04.18 10:11:07.937
12 5.0.3.1633 2025.03.28 3123a P P 55294 56087 2025.03.31 10:18:28.944 2025.03.31 10:19:24.238 2025.03.31 08:51:38.187 2025.03.31 08:52:34.274
13 5.0.3.1633 2025.03.27 e0fb8 F F 59282 60469 2025.03.28 10:52:38.127 2025.03.28 10:53:37.409 2025.03.28 09:22:40.241 2025.03.28 09:23:40.710
14 5.0.3.1631 2025.03.21 1925b F F 60419 59142 2025.03.27 10:40:36.248 2025.03.27 10:41:36.667 2025.03.27 09:11:58.599 2025.03.27 09:12:57.741
15 5.0.3.1628 2025.03.14 16d05 F F 3928 2864 2025.03.17 08:13:47.054 2025.03.17 08:13:50.982 2025.03.17 06:36:17.567 2025.03.17 06:36:20.431
16 5.0.3.1627 2025.02.26 4e218 F F 3827 2802 2025.03.14 11:28:28.631 2025.03.14 11:28:32.458 2025.03.14 09:49:37.251 2025.03.14 09:49:40.053
17 5.0.3.1624 2025.02.25 dc3b2 F F 3720 2667 2025.02.26 10:19:33.011 2025.02.26 10:19:36.731 2025.02.26 08:46:15.215 2025.02.26 08:46:17.882
18 5.0.2.1615 2025.02.20 4a726 F F 3783 2627 2025.02.25 10:46:50.029 2025.02.25 10:46:53.812 2025.02.25 09:12:15.917 2025.02.25 09:12:18.544
19 5.0.2.1615 2025.02.14 9cb76 F F 3753 2661 2025.02.20 07:36:34.777 2025.02.20 07:36:38.530 2025.02.20 06:05:26.054 2025.02.20 06:05:28.715
20 5.0.2.1577 2024.12.24 3c80e P P 3907 2686 2025.02.14 10:49:32.221 2025.02.14 10:49:36.128 2025.02.14 09:18:43.066 2025.02.14 09:18:45.752
21 5.0.2.1576 2024.12.17 646b0 P P 2886 2084 2024.12.24 20:15:52.691 2024.12.24 20:15:55.577 2024.12.24 17:06:36.185 2024.12.24 17:06:38.269
22 5.0.2.1575 2024.12.08 63d39 P P 2921 2041 2024.12.16 07:57:47.722 2024.12.16 07:57:50.643 2024.12.16 06:49:53.789 2024.12.16 06:49:55.830
23 5.0.2.1567 2024.11.26 56e63 P P 3057 2166 2024.12.04 07:38:18.230 2024.12.04 07:38:21.287 2024.12.04 06:28:47.195 2024.12.04 06:28:49.361
24 5.0.2.1567 2024.11.21 96f61 P P 2919 1975 2024.11.26 05:20:44.127 2024.11.26 05:20:47.046 2024.11.26 04:14:14.011 2024.11.26 04:14:15.986
25 5.0.2.1567 2024.11.18 e1289 P P 2944 2077 2024.11.21 07:25:13.134 2024.11.21 07:25:16.078 2024.11.21 06:19:30.485 2024.11.21 06:19:32.562
26 5.0.2.1533 2024.10.23 0ec43 P P 2877 2066 2024.11.18 07:41:08.180 2024.11.18 07:41:11.057 2024.11.18 06:33:32.446 2024.11.18 06:33:34.512
27 5.0.2.1533 2024.10.22 8af7a P P 2950 2018 2024.10.23 09:38:16.097 2024.10.23 09:38:19.047 2024.10.23 08:29:31.130 2024.10.23 08:29:33.148
28 5.0.2.1532 2024.10.15 36dc0 P P 2995 2218 2024.10.22 19:49:56.301 2024.10.22 19:49:59.296 2024.10.22 18:41:43.800 2024.10.22 18:41:46.018
29 5.0.2.1518 2024.10.04 259ba P P 3027 2199 2024.10.15 09:23:38.035 2024.10.15 09:23:41.062 2024.10.15 08:15:09.206 2024.10.15 08:15:11.405
30 5.0.2.1518 2024.09.26 703cd P P 3255 2117 2024.10.03 07:50:37.462 2024.10.03 07:50:40.717 2024.10.03 06:40:10.648 2024.10.03 06:40:12.765
31 5.0.2.1489 2024.09.05 40838 P P 3132 2209 2024.09.25 07:51:28.631 2024.09.25 07:51:31.763 2024.09.25 06:39:48.680 2024.09.25 06:39:50.889
32 5.0.2.1489 2024.08.31 994a6 P P 4483 3155 2024.09.05 11:58:08.482 2024.09.05 11:58:12.965 2024.09.05 10:21:03.325 2024.09.05 10:21:06.480
33 5.0.2.1476 2024.08.09 843ea P P 5402 4492 2024.08.31 14:28:10.262 2024.08.31 14:28:15.664 2024.08.31 12:23:13.490 2024.08.31 12:23:17.982

Elapsed time, ms. Chart for last 33 runs:

Last commits information (all timestamps in UTC):