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

AssertionError: assert   
  - Medians ratio: acceptable
  + Medians ratio: /* perf_issue_tag */ POOR:      4.75, more than threshold:       0.4
  + CPU times for each of 21 measures:
  + sp_name='hash_eval':
  + 0.25
  + 0.328125
  + 0.28125
  + 0.265625
  + 0.265625
  + 0.265625
  + 0.265625
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + 0.25
  + sp_name='udr_call':
  + 1.203125
  + 1.296875
  + 1.265625
  + 1.25
  + 1.171875
  + 1.15625
  + 1.171875
  + 1.171875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.171875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.1875
  + 1.1875

LOG DETAILS:

2025-06-24 10:33:35.950
2025-06-24 10:33:35.950 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-24 10:33:35.950 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-24 10:33:35.950
2025-06-24 10:33:35.950     @pytest.mark.version('>=6.0')
2025-06-24 10:33:35.950     def test_1(act: Action, capsys):
2025-06-24 10:33:35.951
2025-06-24 10:33:35.951         with act.db.connect() as con:
2025-06-24 10:33:35.951             cur=con.cursor()
2025-06-24 10:33:35.951             cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-24 10:33:35.951             fb_pid = int(cur.fetchone()[0])
2025-06-24 10:33:35.951
2025-06-24 10:33:35.951             times_map = {}
2025-06-24 10:33:35.951             for i in range(0, N_MEASURES):
2025-06-24 10:33:35.951                 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-24 10:33:35.951                 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-24 10:33:35.951                 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-24 10:33:35.951                 times_map[ 'hash_eval', i ]  = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-24 10:33:35.951
2025-06-24 10:33:35.951                 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-24 10:33:35.951                 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-24 10:33:35.951                 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-24 10:33:35.951                 times_map[ 'udr_call', i ]  = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-24 10:33:35.951
2025-06-24 10:33:35.951
2025-06-24 10:33:35.951         sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-24 10:33:35.951         sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-24 10:33:35.952
2025-06-24 10:33:35.952         median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-24 10:33:35.952
2025-06-24 10:33:35.952         print( 'Medians ratio: ' + ('acceptable' if median_ratio <= MAX_RATIO else '/* perf_issue_tag */ POOR: %s, more than threshold: %s' % ( '{:9g}'.format(median_ratio), '{:9g}'.format(MAX_RATIO) ) ) )
2025-06-24 10:33:35.952         if median_ratio > MAX_RATIO:
2025-06-24 10:33:35.952             print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-24 10:33:35.952             for sp_name in ('hash_eval', 'udr_call', ):
2025-06-24 10:33:35.952                 print(f'{sp_name=}:')
2025-06-24 10:33:35.952                 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-24 10:33:35.952                     print(p)
2025-06-24 10:33:35.952
2025-06-24 10:33:35.952         act.expected_stdout = expected_stdout
2025-06-24 10:33:35.952         act.stdout = capsys.readouterr().out
2025-06-24 10:33:35.952 >       assert act.clean_stdout == act.clean_expected_stdout
2025-06-24 10:33:35.952 E       AssertionError: assert
2025-06-24 10:33:35.952 E         - Medians ratio: acceptable
2025-06-24 10:33:35.952 E         + Medians ratio: /* perf_issue_tag */ POOR:      4.75, more than threshold:       0.4
2025-06-24 10:33:35.952 E         + CPU times for each of 21 measures:
2025-06-24 10:33:35.952 E         + sp_name='hash_eval':
2025-06-24 10:33:35.952 E         + 0.25
2025-06-24 10:33:35.952 E         + 0.328125
2025-06-24 10:33:35.953 E         + 0.28125
2025-06-24 10:33:35.953 E         + 0.265625
2025-06-24 10:33:35.953 E         + 0.265625
2025-06-24 10:33:35.953 E         + 0.265625
2025-06-24 10:33:35.953 E         + 0.265625
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + 0.25
2025-06-24 10:33:35.953 E         + sp_name='udr_call':
2025-06-24 10:33:35.954 E         + 1.203125
2025-06-24 10:33:35.954 E         + 1.296875
2025-06-24 10:33:35.954 E         + 1.265625
2025-06-24 10:33:35.954 E         + 1.25
2025-06-24 10:33:35.954 E         + 1.171875
2025-06-24 10:33:35.954 E         + 1.15625
2025-06-24 10:33:35.954 E         + 1.171875
2025-06-24 10:33:35.954 E         + 1.171875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.171875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.954 E         + 1.1875
2025-06-24 10:33:35.955
2025-06-24 10:33:35.955 tests\bugs\gh_7989_test.py:152: AssertionError
2025-06-24 10:33:35.955 ---------------------------- Captured stdout setup ----------------------------
2025-06-24 10:33:35.955 Creating db: localhost:H:\QA\temp\qa2024.tmp\fbqa\test_11676\test.fdb [page_size=None, sql_dialect=None, charset='ASCII', 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('>=6.0')
    def test_1(act: Action, capsys):
    
        with act.db.connect() as con:
            cur=con.cursor()
            cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
            fb_pid = int(cur.fetchone()[0])
    
            times_map = {}
            for i in range(0, N_MEASURES):
                fb_info_init = psutil.Process(fb_pid).cpu_times()
                cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
                fb_info_curr = psutil.Process(fb_pid).cpu_times()
                times_map[ 'hash_eval', i ]  = max(fb_info_curr.user - fb_info_init.user, 0.000001)
    
                fb_info_init = psutil.Process(fb_pid).cpu_times()
                cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
                fb_info_curr = psutil.Process(fb_pid).cpu_times()
                times_map[ 'udr_call', i ]  = max(fb_info_curr.user - fb_info_init.user, 0.000001)
    
    
        sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
        sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
    
        median_ratio = sp_udr_call_median / sp_gen_hash_median
    
        print( 'Medians ratio: ' + ('acceptable' if median_ratio <= MAX_RATIO else '/* perf_issue_tag */ POOR: %s, more than threshold: %s' % ( '{:9g}'.format(median_ratio), '{:9g}'.format(MAX_RATIO) ) ) )
        if median_ratio > MAX_RATIO:
            print(f'CPU times for each of {N_MEASURES} measures:')
            for sp_name in ('hash_eval', 'udr_call', ):
                print(f'{sp_name=}:')
                for p in [v for k,v in times_map.items() if k[0] == sp_name]:
                    print(p)
    
        act.expected_stdout = expected_stdout
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       AssertionError: assert   
E         - Medians ratio: acceptable
E         + Medians ratio: /* perf_issue_tag */ POOR:      4.75, more than threshold:       0.4
E         + CPU times for each of 21 measures:
E         + sp_name='hash_eval':
E         + 0.25
E         + 0.328125
E         + 0.28125
E         + 0.265625
E         + 0.265625
E         + 0.265625
E         + 0.265625
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + 0.25
E         + sp_name='udr_call':
E         + 1.203125
E         + 1.296875
E         + 1.265625
E         + 1.25
E         + 1.171875
E         + 1.15625
E         + 1.171875
E         + 1.171875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.171875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.1875
E         + 1.1875

tests\bugs\gh_7989_test.py:152: 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 6.0.0.884 2025.07.01 44e00 F F 30446 30720 2025.07.01 14:25:39.277 2025.07.01 14:26:09.723 2025.07.01 12:42:06.751 2025.07.01 12:42:37.471
2 6.0.0.881 2025.06.27 7035d F F 30963 30617 2025.07.01 03:10:25.465 2025.07.01 03:10:56.428 2025.07.01 01:28:38.244 2025.07.01 01:29:08.861
3 6.0.0.877 2025.06.26 8e38f F F 30802 29766 2025.06.27 03:11:47.188 2025.06.27 03:12:17.990 2025.06.27 01:29:24.588 2025.06.27 01:29:54.354
4 6.0.0.876 2025.06.25 b1bec F F 30483 30923 2025.06.26 03:17:05.743 2025.06.26 03:17:36.226 2025.06.26 01:35:01.774 2025.06.26 01:35:32.697
5 6.0.0.863 2025.06.24 c3c20 F F 31147 30560 2025.06.25 08:01:15.143 2025.06.25 08:01:46.290 2025.06.25 01:29:04.514 2025.06.25 01:29:35.074
6 6.0.0.858 2025.06.24 cbbbf F F 30933 30876 2025.06.24 17:43:46.773 2025.06.24 17:44:17.706 2025.06.24 16:01:01.927 2025.06.24 16:01:32.803
7 6.0.0.858 2025.06.23 d377c F F 31379 31026 2025.06.24 08:55:47.440 2025.06.24 08:56:18.819 2025.06.24 07:13:23.969 2025.06.24 07:13:54.995
8 6.0.0.854 2025.06.23 10b58 F F 30702 30402 2025.06.23 15:36:41.047 2025.06.23 15:37:11.749 2025.06.23 13:52:57.478 2025.06.23 13:53:27.880
9 6.0.0.849 2025.06.20 7b79c F F 31071 30054 2025.06.21 03:15:00.571 2025.06.21 03:15:31.642 2025.06.21 01:29:37.266 2025.06.21 01:30:07.320
10 6.0.0.848 2025.06.19 c483c F F 30499 30192 2025.06.20 03:14:38.251 2025.06.20 03:15:08.750 2025.06.20 01:29:22.017 2025.06.20 01:29:52.209
11 6.0.0.845 2025.06.18 20191 F F 31093 30796 2025.06.19 03:14:15.474 2025.06.19 03:14:46.567 2025.06.19 01:29:08.389 2025.06.19 01:29:39.185
12 6.0.0.843 2025.06.16 995f4 F F 30318 29727 2025.06.18 03:14:04.058 2025.06.18 03:14:34.376 2025.06.18 01:28:52.858 2025.06.18 01:29:22.585
13 6.0.0.840 2025.06.14 29bca F F 31148 30569 2025.06.15 03:22:32.364 2025.06.15 03:23:03.512 2025.06.15 01:31:55.016 2025.06.15 01:32:25.585
14 6.0.0.838 2025.06.13 0e28a F F 30970 30441 2025.06.14 03:20:16.260 2025.06.14 03:20:47.230 2025.06.14 01:30:14.505 2025.06.14 01:30:44.946
15 6.0.0.834 2025.06.11 e889f F F 30896 30400 2025.06.12 03:17:48.399 2025.06.12 03:18:19.295 2025.06.12 01:30:46.028 2025.06.12 01:31:16.428
16 6.0.0.800 2025.06.10 1f226 P P 7146 7185 2025.06.11 02:02:14.621 2025.06.11 02:02:21.767 2025.06.11 00:53:53.946 2025.06.11 00:54:01.131
17 6.0.0.799 2025.06.07 be644 P P 7117 6895 2025.06.10 02:01:50.306 2025.06.10 02:01:57.423 2025.06.10 00:53:31.299 2025.06.10 00:53:38.194
18 6.0.0.797 2025.06.06 303e8 P P 7111 7150 2025.06.07 02:00:43.025 2025.06.07 02:00:50.136 2025.06.07 00:53:19.498 2025.06.07 00:53:26.648
19 6.0.0.795 2025.05.29 7a71a P P 7116 6890 2025.06.06 02:00:33.834 2025.06.06 02:00:40.950 2025.06.06 00:53:17.639 2025.06.06 00:53:24.529
20 6.0.0.792 2025.05.28 ee5a8 P P 7009 7069 2025.05.29 01:59:39.753 2025.05.29 01:59:46.762 2025.05.29 00:53:23.799 2025.05.29 00:53:30.868
21 6.0.0.791 2025.05.27 02db8 P P 6989 6837 2025.05.28 02:00:08.477 2025.05.28 02:00:15.466 2025.05.28 00:53:07.028 2025.05.28 00:53:13.865
22 6.0.0.789 2025.05.21 64051 P P 6995 7054 2025.05.25 01:59:52.001 2025.05.25 01:59:58.996 2025.05.25 00:53:31.689 2025.05.25 00:53:38.743
23 6.0.0.787 2025.05.20 230ad P P 7001 6797 2025.05.21 01:58:47.419 2025.05.21 01:58:54.420 2025.05.21 00:52:40.452 2025.05.21 00:52:47.249
24 6.0.0.783 2025.05.12 37320 P P 7040 6818 2025.05.19 01:58:34.929 2025.05.19 01:58:41.969 2025.05.19 00:52:49.537 2025.05.19 00:52:56.355

Elapsed time, ms. Chart for last 24 runs:

Last commits information (all timestamps in UTC):