Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
1 @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.58 -- greater than threshold =         0.55
  + Check result of 21 measures:
  + 0 :         0.55
  + 1 :         0.59
  + 2 :         0.58
  + 3 :         0.60
  + 4 :         0.58
  + 5 :         0.58
  + 6 :         0.54
  + 7 :         0.58
  + 8 :         0.58
  + 9 :         0.60
  + 10 :         0.58
  + 11 :         0.57
  + 12 :         0.61
  + 13 :         0.60
  + 14 :         0.58
  + 15 :         0.55
  + 16 :         0.58
  + 17 :         0.57
  + 18 :         0.58
  + 19 :         0.59
  + 20 :         0.58
    Median value for 21 ratios of commit_time/compile_time when create 1500 standalone PSQL objects: acceptable

LOG DETAILS:

2024-05-11 10:32:24.657
2024-05-11 10:32:24.657 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-11 10:32:24.657 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657     @pytest.mark.version('>=3.0')
2024-05-11 10:32:24.657     def test_1(act: Action, capsys):
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         act.db.set_async_write() # just to be sure, although this is by default
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         expected_stdout = f"""
2024-05-11 10:32:24.657             Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} packaged PSQL objects: acceptable
2024-05-11 10:32:24.657             Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} standalone PSQL objects: acceptable
2024-05-11 10:32:24.657         """
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         func_headers_ddl = ''.join( [ '\n  function fn_%d returns int;' % i for i in range(N_LIMIT) ] )
2024-05-11 10:32:24.657         func_bodies_ddl = ''.join( [ '\n  function fn_%d returns int as begin return %d; end' % (i,i) for i in range(N_LIMIT) ] )
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         pkg_header_ddl = '\n'.join( ('create or alter package huge as\nbegin', func_headers_ddl, 'end') )
2024-05-11 10:32:24.657         pkg_body_ddl = '\n'.join( ('recreate package body huge as\nbegin', func_bodies_ddl, 'end') )
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         sp_time = {}
2024-05-11 10:32:24.657         with act.db.connect() as con:
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657             with con.cursor() as cur:
2024-05-11 10:32:24.657                 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-05-11 10:32:24.657                 fb_pid = int(cur.fetchone()[0])
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657             for i in range(0, N_MEASURES):
2024-05-11 10:32:24.657                 for ftype in ('packaged', 'standalone'):
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657                     fb_info_a = psutil.Process(fb_pid).cpu_times()
2024-05-11 10:32:24.657                     if ftype == 'packaged':
2024-05-11 10:32:24.657                         con.execute_immediate(pkg_header_ddl)
2024-05-11 10:32:24.657                         con.execute_immediate(pkg_body_ddl)
2024-05-11 10:32:24.657                     else:
2024-05-11 10:32:24.657                         for k in range(0,N_LIMIT):
2024-05-11 10:32:24.657                             con.execute_immediate( 'create or alter function sf_%d returns int as begin return %d; end' % (k,k)  )
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657                     fb_info_b = psutil.Process(fb_pid).cpu_times()
2024-05-11 10:32:24.657                     con.commit()
2024-05-11 10:32:24.657                     fb_info_c = psutil.Process(fb_pid).cpu_times()
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657                     cpu_time_for_compile = max(fb_info_b.user - fb_info_a.user, 0.000001)
2024-05-11 10:32:24.657                     cpu_time_for_commit = fb_info_c.user - fb_info_b.user
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657                     sp_time[ ftype, i ]  = cpu_time_for_commit / cpu_time_for_compile
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         commit_2_compile_ratio_for_package = [round(v,2) for k,v in sp_time.items() if k[0] == 'packaged']
2024-05-11 10:32:24.657         commit_2_compile_ratio_for_standal = [round(v,2) for k,v in sp_time.items() if k[0] == 'standalone']
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         actual_time_ratios_commit2compile = { 'packaged' : median(commit_2_compile_ratio_for_package), 'standalone': median(commit_2_compile_ratio_for_standal) }
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         for ftype in ('packaged', 'standalone'):
2024-05-11 10:32:24.657             msg = f"Median value for {N_MEASURES} ratios of commit_time/compile_time when create {N_LIMIT} {ftype} PSQL objects: "
2024-05-11 10:32:24.657             if actual_time_ratios_commit2compile[ ftype ] < MAX_TIME_RATIOS_COMMIT_TO_COMPILE[ ftype ]:
2024-05-11 10:32:24.657                 print( msg + 'acceptable')
2024-05-11 10:32:24.657             else:
2024-05-11 10:32:24.657                 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 ]) )
2024-05-11 10:32:24.657                 print( 'Check result of %d measures:' % N_MEASURES )
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657                 # List with concrete values (source for median evaluation):
2024-05-11 10:32:24.657                 lst = commit_2_compile_ratio_for_package if ftype == 'packaged' else commit_2_compile_ratio_for_standal
2024-05-11 10:32:24.657                 for i,p in enumerate(lst):
2024-05-11 10:32:24.657                     print('%3d' % i, ':', '%12.2f' % p)
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657         act.expected_stdout = expected_stdout
2024-05-11 10:32:24.657         act.stdout = capsys.readouterr().out
2024-05-11 10:32:24.657 >       assert act.clean_stdout == act.clean_expected_stdout
2024-05-11 10:32:24.657 E       assert
2024-05-11 10:32:24.657 E         - Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: acceptable
2024-05-11 10:32:24.657 E         + Median value for 21 ratios of commit_time/compile_time when create 1500 packaged PSQL objects: /* perf_issue_tag */ UNACCEPTABLE:         0.58 -- greater than threshold =         0.55
2024-05-11 10:32:24.657 E         + Check result of 21 measures:
2024-05-11 10:32:24.657 E         + 0 :         0.55
2024-05-11 10:32:24.657 E         + 1 :         0.59
2024-05-11 10:32:24.657 E         + 2 :         0.58
2024-05-11 10:32:24.657 E         + 3 :         0.60
2024-05-11 10:32:24.657 E         + 4 :         0.58
2024-05-11 10:32:24.657 E         + 5 :         0.58
2024-05-11 10:32:24.657 E         + 6 :         0.54
2024-05-11 10:32:24.657 E         + 7 :         0.58
2024-05-11 10:32:24.657 E         + 8 :         0.58
2024-05-11 10:32:24.657 E         + 9 :         0.60
2024-05-11 10:32:24.657 E         + 10 :         0.58
2024-05-11 10:32:24.657 E         + 11 :         0.57
2024-05-11 10:32:24.657 E         + 12 :         0.61
2024-05-11 10:32:24.657 E         + 13 :         0.60
2024-05-11 10:32:24.657 E         + 14 :         0.58
2024-05-11 10:32:24.657 E         + 15 :         0.55
2024-05-11 10:32:24.657 E         + 16 :         0.58
2024-05-11 10:32:24.657 E         + 17 :         0.57
2024-05-11 10:32:24.657 E         + 18 :         0.58
2024-05-11 10:32:24.657 E         + 19 :         0.59
2024-05-11 10:32:24.657 E         + 20 :         0.58
2024-05-11 10:32:24.657 E           Median value for 21 ratios of commit_time/compile_time when create 1500 standalone PSQL objects: acceptable
2024-05-11 10:32:24.657
2024-05-11 10:32:24.657 tests\bugs\core_4880_test.py:164: AssertionError
2024-05-11 10:32:24.657 ---------------------------- Captured stdout setup ----------------------------
2024-05-11 10:32:24.657 Cached db: db-12.0-None-None-NONE.fdb [page_size=None, sql_dialect=None, charset='NONE'
2 #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.58 -- greater than threshold =         0.55
E         + Check result of 21 measures:
E         + 0 :         0.55
E         + 1 :         0.59
E         + 2 :         0.58
E         + 3 :         0.60
E         + 4 :         0.58
E         + 5 :         0.58
E         + 6 :         0.54
E         + 7 :         0.58
E         + 8 :         0.58
E         + 9 :         0.60
E         + 10 :         0.58
E         + 11 :         0.57
E         + 12 :         0.61
E         + 13 :         0.60
E         + 14 :         0.58
E         + 15 :         0.55
E         + 16 :         0.58
E         + 17 :         0.57
E         + 18 :         0.58
E         + 19 :         0.59
E         + 20 :         0.58
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.14 6638e P P 145060 82411 2025.06.27 14:32:30.579 2025.06.27 14:34:55.639 2025.06.27 13:59:07.038 2025.06.27 14:00:29.449
2 3.0.13.33809 2025.05.06 28ad0 P P 149012 84205 2025.05.14 08:13:09.656 2025.05.14 08:15:38.668 2025.05.14 07:38:26.345 2025.05.14 07:39:50.550
3 3.0.13.33808 2025.04.25 28426 P P 149056 85610 2025.05.06 13:24:02.596 2025.05.06 13:26:31.652 2025.05.06 12:51:07.094 2025.05.06 12:52:32.704
4 3.0.13.33803 2025.04.23 307b8 P P 146672 84613 2025.04.25 13:32:38.453 2025.04.25 13:35:05.125 2025.04.25 12:59:33.445 2025.04.25 13:00:58.058
5 3.0.13.33803 2025.03.25 ea22a P P 144922 83435 2025.04.20 08:03:59.593 2025.04.20 08:06:24.515 2025.04.20 07:09:09.069 2025.04.20 07:10:32.504
6 3.0.13.33803 2025.02.25 08ebd P P 145225 84184 2025.03.25 10:19:28.741 2025.03.25 10:21:53.966 2025.03.25 09:23:29.857 2025.03.25 09:24:54.041
7 3.0.13.33796 2025.01.29 0ab85 P P 145930 81927 2025.02.25 12:10:08.531 2025.02.25 12:12:34.461 2025.02.25 11:36:51.936 2025.02.25 11:38:13.863
8 3.0.13.33796 2025.01.14 99b3b P P 145785 82294 2025.01.24 11:14:45.104 2025.01.24 11:17:10.889 2025.01.24 10:41:35.283 2025.01.24 10:42:57.577
9 3.0.13.33795 2024.12.13 fbbd9 P P 145773 83292 2025.01.01 12:25:47.499 2025.01.01 12:28:13.272 2025.01.01 11:52:08.295 2025.01.01 11:53:31.587
10 3.0.13.33795 2024.11.24 b8847 P P 146077 82924 2024.12.11 12:23:28.701 2024.12.11 12:25:54.778 2024.12.11 11:50:05.631 2024.12.11 11:51:28.555
11 3.0.13.33794 2024.10.15 abe09 P P 145837 82923 2024.11.22 11:59:53.128 2024.11.22 12:02:18.965 2024.11.22 11:26:19.049 2024.11.22 11:27:41.972
12 3.0.13.33793 2024.10.14 f831a P P 145856 83853 2024.10.15 12:27:28.472 2024.10.15 12:29:54.328 2024.10.15 11:53:47.591 2024.10.15 11:55:11.444
13 3.0.13.33793 2024.10.04 82ccc P P 147248 83857 2024.10.12 12:26:28.824 2024.10.12 12:28:56.072 2024.10.12 11:53:04.396 2024.10.12 11:54:28.253
14 3.0.13.33792 2024.08.31 d8791 P P 144532 82488 2024.10.03 12:34:46.946 2024.10.03 12:37:11.478 2024.10.03 12:00:23.019 2024.10.03 12:01:45.507
15 3.0.13.33787 2024.08.23 8ee81 P P 149780 85027 2024.09.01 12:44:45.121 2024.09.01 12:47:14.901 2024.09.01 12:07:23.474 2024.09.01 12:08:48.501
16 3.0.13.33787 2024.08.09 df740 P P 149820 84089 2024.08.23 12:40:24.890 2024.08.23 12:42:54.710 2024.08.23 12:03:19.629 2024.08.23 12:04:43.718
17 3.0.12.33746 2024.07.15 11dd4 P P 151486 84671 2024.08.09 12:00:39.315 2024.08.09 12:03:10.801 2024.08.09 11:23:54.789 2024.08.09 11:25:19.460
18 3.0.12.33746 2024.06.11 8a5eb P P 151545 85087 2024.07.15 10:54:19.935 2024.07.15 10:56:51.480 2024.07.15 10:22:17.974 2024.07.15 10:23:43.061
19 3.0.12.33745 2024.05.21 301a7 P F 140406 79289 2024.05.25 07:52:24.949 2024.05.25 07:54:45.355 2024.05.25 07:22:56.348 2024.05.25 07:24:15.637
20 3.0.12.33745 2024.05.09 9cf37 P F 139733 82884 2024.05.21 07:52:42.563 2024.05.21 07:55:02.296 2024.05.21 07:23:02.840 2024.05.21 07:24:25.724
21 3.0.12.33744 2024.04.20 af6b2 P F 140265 78821 2024.05.11 07:49:12.219 2024.05.11 07:51:32.484 2024.05.11 07:20:24.169 2024.05.11 07:21:42.990
22 3.0.12.33740 2024.04.06 c6cdd P F 133405 76305 2024.04.21 02:03:33.741 2024.04.21 02:05:47.146 2024.04.21 01:35:05.166 2024.04.21 01:36:21.471
23 3.0.12.33726 2024.03.29 1fac6 P F 138006 78133 2024.04.05 06:59:16.495 2024.04.05 07:01:34.501 2024.04.05 06:31:17.502 2024.04.05 06:32:35.635
24 3.0.12.33726 2024.03.11 456ca P F 138701 78648 2024.03.29 12:40:18.547 2024.03.29 12:42:37.248 2024.03.29 12:13:34.221 2024.03.29 12:14:52.869

Elapsed time, ms. Chart for last 24 runs:

Last commits information (all timestamps in UTC):