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   
  - Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: acceptable
  + Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: /* perf_issue_tag */ UNACCEPTABLE:         0.55 -- greater than threshold =         0.55
  + Check result of 21 measures:
  + 0 :         0.65
  + 1 :         0.58
  + 2 :         0.56
  + 3 :         0.46
  + 4 :         0.51
  + 5 :         0.62
  + 6 :         0.55
  + 7 :         0.56
  + 8 :         0.57
  + 9 :         0.56
  + 10 :         0.64
  + 11 :         0.53
  + 12 :         0.51
  + 13 :         0.58
  + 14 :         0.51
  + 15 :         0.50
  + 16 :         0.49
  + 17 :         0.52
  + 18 :         0.56
  + 19 :         0.52
  + 20 :         0.54
    Median value for 21 ratios of commit_time/compile_time when create 1500 standalone PSQL objects: acceptable

LOG DETAILS:

2025-07-02 17:46:18.272
2025-07-02 17:46:18.278 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-02 17:46:18.288 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-02 17:46:18.298
2025-07-02 17:46:18.306 @pytest.mark.version('>=3.0')
2025-07-02 17:46:18.314 def test_1(act: Action, capsys):
2025-07-02 17:46:18.326
2025-07-02 17:46:18.336 act.db.set_async_write() # just to be sure, although this is by default
2025-07-02 17:46:18.344
2025-07-02 17:46:18.351 expected_stdout = f"""
2025-07-02 17:46:18.359 Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} packaged PSQL objects: acceptable
2025-07-02 17:46:18.367 Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} standalone PSQL objects: acceptable
2025-07-02 17:46:18.379 """
2025-07-02 17:46:18.391
2025-07-02 17:46:18.401 func_headers_ddl = ''.join( [ '\n  function fn_%d returns int;' % i for i in range(N_LIMIT) ] )
2025-07-02 17:46:18.408 func_bodies_ddl = ''.join( [ '\n  function fn_%d returns int as begin return %d; end' % (i,i) for i in range(N_LIMIT) ] )
2025-07-02 17:46:18.415
2025-07-02 17:46:18.423 pkg_header_ddl = '\n'.join( ('create or alter package huge as\nbegin', func_headers_ddl, 'end') )
2025-07-02 17:46:18.435 pkg_body_ddl = '\n'.join( ('recreate package body huge as\nbegin', func_bodies_ddl, 'end') )
2025-07-02 17:46:18.443
2025-07-02 17:46:18.452 sp_time = {}
2025-07-02 17:46:18.459 with act.db.connect() as con:
2025-07-02 17:46:18.471
2025-07-02 17:46:18.479 with con.cursor() as cur:
2025-07-02 17:46:18.484 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-07-02 17:46:18.490 fb_pid = int(cur.fetchone()[0])
2025-07-02 17:46:18.496
2025-07-02 17:46:18.502 for i in range(0, N_MEASURES):
2025-07-02 17:46:18.514 for ftype in ('packaged', 'standalone'):
2025-07-02 17:46:18.525
2025-07-02 17:46:18.533 fb_info_a = psutil.Process(fb_pid).cpu_times()
2025-07-02 17:46:18.540 if ftype == 'packaged':
2025-07-02 17:46:18.547 con.execute_immediate(pkg_header_ddl)
2025-07-02 17:46:18.556 con.execute_immediate(pkg_body_ddl)
2025-07-02 17:46:18.567 else:
2025-07-02 17:46:18.575 for k in range(0,N_LIMIT):
2025-07-02 17:46:18.584 con.execute_immediate( 'create or alter function sf_%d returns int as begin return %d; end' % (k,k)  )
2025-07-02 17:46:18.590
2025-07-02 17:46:18.597 fb_info_b = psutil.Process(fb_pid).cpu_times()
2025-07-02 17:46:18.605 con.commit()
2025-07-02 17:46:18.613 fb_info_c = psutil.Process(fb_pid).cpu_times()
2025-07-02 17:46:18.620
2025-07-02 17:46:18.626 cpu_time_for_compile = max(fb_info_b.user - fb_info_a.user, 0.000001)
2025-07-02 17:46:18.634 cpu_time_for_commit = fb_info_c.user - fb_info_b.user
2025-07-02 17:46:18.647
2025-07-02 17:46:18.656 sp_time[ ftype, i ]  = cpu_time_for_commit / cpu_time_for_compile
2025-07-02 17:46:18.665
2025-07-02 17:46:18.673 commit_2_compile_ratio_for_package = [round(v,2) for k,v in sp_time.items() if k[0] == 'packaged']
2025-07-02 17:46:18.679 commit_2_compile_ratio_for_standal = [round(v,2) for k,v in sp_time.items() if k[0] == 'standalone']
2025-07-02 17:46:18.684
2025-07-02 17:46:18.688 actual_time_ratios_commit2compile = { 'packaged' : median(commit_2_compile_ratio_for_package), 'standalone': median(commit_2_compile_ratio_for_standal) }
2025-07-02 17:46:18.695
2025-07-02 17:46:18.708 for ftype in ('packaged', 'standalone'):
2025-07-02 17:46:18.717 msg = f"Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} {ftype} PSQL objects: "
2025-07-02 17:46:18.726 if actual_time_ratios_commit2compile[ ftype ] < MAX_TIME_RATIOS_COMMIT_TO_COMPILE[ ftype ]:
2025-07-02 17:46:18.738 print( msg + 'acceptable')
2025-07-02 17:46:18.751 else:
2025-07-02 17:46:18.764 print( msg + '/* perf_issue_tag */ UNACCEPTABLE: %12.2f -- greater than threshold = %12.2f' % (actual_time_ratios_commit2compile[ ftype ],  MAX_TIME_RATIOS_COMMIT_TO_COMPILE[ ftype ]) )
2025-07-02 17:46:18.775 print( 'Check result of %d measures:' % N_MEASURES )
2025-07-02 17:46:18.784
2025-07-02 17:46:18.791 # List with concrete values (source for median evaluation):
2025-07-02 17:46:18.797 lst = commit_2_compile_ratio_for_package if ftype == 'packaged' else commit_2_compile_ratio_for_standal
2025-07-02 17:46:18.803 for i,p in enumerate(lst):
2025-07-02 17:46:18.808 print('%3d' % i, ':', '%12.2f' % p)
2025-07-02 17:46:18.814
2025-07-02 17:46:18.824
2025-07-02 17:46:18.834 act.expected_stdout = expected_stdout
2025-07-02 17:46:18.842 act.stdout = capsys.readouterr().out
2025-07-02 17:46:18.851 >       assert act.clean_stdout == act.clean_expected_stdout
2025-07-02 17:46:18.857 E       assert
2025-07-02 17:46:18.868 E         - Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: acceptable
2025-07-02 17:46:18.878 E         + Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: /* perf_issue_tag */ UNACCEPTABLE:         0.55 -- greater than threshold =         0.55
2025-07-02 17:46:18.890 E         + Check result of 21 measures:
2025-07-02 17:46:18.899 E         + 0 :         0.65
2025-07-02 17:46:18.907 E         + 1 :         0.58
2025-07-02 17:46:18.914 E         + 2 :         0.56
2025-07-02 17:46:18.924 E         + 3 :         0.46
2025-07-02 17:46:18.934 E         + 4 :         0.51
2025-07-02 17:46:18.944 E         + 5 :         0.62
2025-07-02 17:46:18.955 E         + 6 :         0.55
2025-07-02 17:46:18.964 E         + 7 :         0.56
2025-07-02 17:46:18.971 E         + 8 :         0.57
2025-07-02 17:46:18.980 E         + 9 :         0.56
2025-07-02 17:46:18.988 E         + 10 :         0.64
2025-07-02 17:46:18.996 E         + 11 :         0.53
2025-07-02 17:46:19.007 E         + 12 :         0.51
2025-07-02 17:46:19.014 E         + 13 :         0.58
2025-07-02 17:46:19.020 E         + 14 :         0.51
2025-07-02 17:46:19.026 E         + 15 :         0.50
2025-07-02 17:46:19.032 E         + 16 :         0.49
2025-07-02 17:46:19.038 E         + 17 :         0.52
2025-07-02 17:46:19.048 E         + 18 :         0.56
2025-07-02 17:46:19.057 E         + 19 :         0.52
2025-07-02 17:46:19.065 E         + 20 :         0.54
2025-07-02 17:46:19.071 E           Median value for 21 ratios of commit_time/compile_time when create 1500 standalone PSQL objects: acceptable
2025-07-02 17:46:19.077
2025-07-02 17:46:19.082 tests/bugs/core_4880_test.py:164: AssertionError
2025-07-02 17:46:19.090 ---------------------------- Captured stdout setup -----------------------------
2025-07-02 17:46:19.097 Creating db: localhost:/var/tmp/qa_2024/test_1965/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('>=3.0')
    def test_1(act: Action, capsys):
    
        act.db.set_async_write() # just to be sure, although this is by default
    
        expected_stdout = f"""
            Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} packaged PSQL objects: acceptable
            Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} standalone PSQL objects: acceptable
        """
    
        func_headers_ddl = ''.join( [ '\n  function fn_%d returns int;' % i for i in range(N_LIMIT) ] )
        func_bodies_ddl = ''.join( [ '\n  function fn_%d returns int as begin return %d; end' % (i,i) for i in range(N_LIMIT) ] )
    
        pkg_header_ddl = '\n'.join( ('create or alter package huge as\nbegin', func_headers_ddl, 'end') )
        pkg_body_ddl = '\n'.join( ('recreate package body huge as\nbegin', func_bodies_ddl, 'end') )
    
        sp_time = {}
        with act.db.connect() as con:
    
            with con.cursor() as cur:
                cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
                fb_pid = int(cur.fetchone()[0])
    
            for i in range(0, N_MEASURES):
                for ftype in ('packaged', 'standalone'):
    
                    fb_info_a = psutil.Process(fb_pid).cpu_times()
                    if ftype == 'packaged':
                        con.execute_immediate(pkg_header_ddl)
                        con.execute_immediate(pkg_body_ddl)
                    else:
                        for k in range(0,N_LIMIT):
                            con.execute_immediate( 'create or alter function sf_%d returns int as begin return %d; end' % (k,k)  )
    
                    fb_info_b = psutil.Process(fb_pid).cpu_times()
                    con.commit()
                    fb_info_c = psutil.Process(fb_pid).cpu_times()
    
                    cpu_time_for_compile = max(fb_info_b.user - fb_info_a.user, 0.000001)
                    cpu_time_for_commit = fb_info_c.user - fb_info_b.user
    
                    sp_time[ ftype, i ]  = cpu_time_for_commit / cpu_time_for_compile
    
        commit_2_compile_ratio_for_package = [round(v,2) for k,v in sp_time.items() if k[0] == 'packaged']
        commit_2_compile_ratio_for_standal = [round(v,2) for k,v in sp_time.items() if k[0] == 'standalone']
    
        actual_time_ratios_commit2compile = { 'packaged' : median(commit_2_compile_ratio_for_package), 'standalone': median(commit_2_compile_ratio_for_standal) }
    
        for ftype in ('packaged', 'standalone'):
            msg = f"Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} {ftype} PSQL objects: "
            if actual_time_ratios_commit2compile[ ftype ] < MAX_TIME_RATIOS_COMMIT_TO_COMPILE[ ftype ]:
                print( msg + 'acceptable')
            else:
                print( msg + '/* perf_issue_tag */ UNACCEPTABLE: %12.2f -- greater than threshold = %12.2f' % (actual_time_ratios_commit2compile[ ftype ],  MAX_TIME_RATIOS_COMMIT_TO_COMPILE[ ftype ]) )
                print( 'Check result of %d measures:' % N_MEASURES )
    
                # List with concrete values (source for median evaluation):
                lst = commit_2_compile_ratio_for_package if ftype == 'packaged' else commit_2_compile_ratio_for_standal
                for i,p in enumerate(lst):
                    print('%3d' % i, ':', '%12.2f' % p)
    
    
        act.expected_stdout = expected_stdout
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: acceptable
E         + Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: /* perf_issue_tag */ UNACCEPTABLE:         0.55 -- greater than threshold =         0.55
E         + Check result of 21 measures:
E         + 0 :         0.65
E         + 1 :         0.58
E         + 2 :         0.56
E         + 3 :         0.46
E         + 4 :         0.51
E         + 5 :         0.62
E         + 6 :         0.55
E         + 7 :         0.56
E         + 8 :         0.57
E         + 9 :         0.56
E         + 10 :         0.64
E         + 11 :         0.53
E         + 12 :         0.51
E         + 13 :         0.58
E         + 14 :         0.51
E         + 15 :         0.50
E         + 16 :         0.49
E         + 17 :         0.52
E         + 18 :         0.56
E         + 19 :         0.52
E         + 20 :         0.54
E           Median value for 21 ratios of commit_time/compile_time when create 1500 standalone PSQL objects: acceptable

tests/bugs/core_4880_test.py:164: 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 3.0.13.33809 2025.05.06 28ad0 P F 312822 166410 2025.07.02 15:12:24.799 2025.07.02 15:17:37.621 2025.07.02 14:23:25.880 2025.07.02 14:26:12.290
2 3.0.13.33808 2025.04.25 28426 P P 382656 209281 2025.05.06 13:44:17.637 2025.05.06 13:50:40.293 2025.05.06 12:45:53.078 2025.05.06 12:49:22.359
3 3.0.13.33803 2025.02.25 08ebd P P 389495 214526 2025.04.25 16:59:13.535 2025.04.25 17:05:43.030 2025.04.25 16:01:19.104 2025.04.25 16:04:53.630
4 3.0.13.33796 2025.01.29 0ab85 P P 1599 1095 2025.02.25 15:38:20.044 2025.02.25 15:38:21.643 2025.02.25 14:37:36.246 2025.02.25 14:37:37.341
5 3.0.13.33796 2025.01.14 99b3b P P 1489 1058 2025.01.28 17:52:47.336 2025.01.28 17:52:48.825 2025.01.28 16:50:19.091 2025.01.28 16:50:20.149
6 3.0.13.33795 2024.11.24 b8847 P P 1504 1003 2025.01.13 15:30:06.609 2025.01.13 15:30:08.113 2025.01.13 14:28:37.945 2025.01.13 14:28:38.948
7 3.0.13.33794 2024.10.15 abe09 P F 1174 836 2024.11.23 06:35:08.227 2024.11.23 06:35:09.401 2024.11.23 05:49:01.126 2024.11.23 05:49:01.962
8 3.0.13.33793 2024.10.04 82ccc P F 1467 819 2024.10.14 04:31:06.509 2024.10.14 04:31:07.976 2024.10.14 03:40:36.571 2024.10.14 03:40:37.390
9 3.0.13.33792 2024.08.31 d8791 P P 1375 940 2024.10.03 09:38:07.659 2024.10.03 09:38:09.034 2024.10.03 08:44:00.794 2024.10.03 08:44:01.734
10 3.0.13.33787 2024.08.17 2e0d6 P P 3515 1796 2024.08.25 15:30:37.577 2024.08.25 15:30:41.092 2024.08.25 13:32:59.556 2024.08.25 13:33:01.352
11 3.0.13.33787 2024.08.09 df740 P P 1521 929 2024.08.16 12:54:10.713 2024.08.16 12:54:12.234 2024.08.16 11:52:54.266 2024.08.16 11:52:55.195
12 3.0.12.33746 2024.07.15 11dd4 P F 2349 1503 2024.08.09 12:49:36.076 2024.08.09 12:49:38.425 2024.08.09 11:47:28.816 2024.08.09 11:47:30.319
13 3.0.12.33746 2024.06.11 8a5eb P P 1154 801 2024.07.15 10:41:35.376 2024.07.15 10:41:36.530 2024.07.15 09:49:16.331 2024.07.15 09:49:17.132
14 3.0.12.33744 2024.05.09 9cf37 P F 1689 1115 2024.05.12 15:47:52.209 2024.05.12 15:47:53.898 2024.05.12 15:00:50.465 2024.05.12 15:00:51.580
15 3.0.12.33744 2024.04.20 af6b2 P F 1099 818 2024.05.08 17:03:26.457 2024.05.08 17:03:27.556 2024.05.08 16:18:31.096 2024.05.08 16:18:31.914

Elapsed time, ms. Chart for last 15 runs:

Last commits information (all timestamps in UTC):