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.94286, more than threshold:       0.4
  + CPU times for each of 21 measures:
  + sp_name='hash_eval':
  + 0.33999999999969077
  + 0.38999999999987267
  + 0.36999999999989086
  + 0.32999999999992724
  + 0.33999999999969077
  + 0.32999999999992724
  + 0.34999999999990905
  + 0.3599999999996726
  + 0.3400000000001455
  + 0.32999999999992724
  + 0.3400000000001455
  + 0.34999999999990905
  + 0.3400000000001455
  + 0.36999999999989086
  + 0.34999999999990905
  + 0.36000000000012733
  + 0.34999999999990905
  + 0.32999999999992724
  + 0.32999999999992724
  + 0.36000000000012733
  + 0.34999999999990905
  + sp_name='udr_call':
  + 1.800000000000182
  + 1.7300000000000182
  + 1.7400000000002365
  + 1.6900000000000546
  + 1.7000000000002728
  + 1.7300000000000182
  + 1.7400000000002365
  + 1.6700000000000728
  + 1.699999999999818
  + 1.7600000000002183
  + 1.7300000000000182
  + 1.7399999999997817
  + 1.849999999999909
  + 1.7000000000002728
  + 1.7100000000000364
  + 1.699999999999818
  + 1.7000000000002728
  + 1.7300000000000182
  + 1.7100000000000364
  + 1.7799999999997453
  + 1.6900000000000546

LOG DETAILS:

2025-07-01 03:08:16.444
2025-07-01 03:08:16.449 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-01 03:08:16.453 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-01 03:08:16.458
2025-07-01 03:08:16.462 @pytest.mark.version('>=6.0')
2025-07-01 03:08:16.467 def test_1(act: Action, capsys):
2025-07-01 03:08:16.471
2025-07-01 03:08:16.476 with act.db.connect() as con:
2025-07-01 03:08:16.480 cur=con.cursor()
2025-07-01 03:08:16.485 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-07-01 03:08:16.489 fb_pid = int(cur.fetchone()[0])
2025-07-01 03:08:16.494
2025-07-01 03:08:16.498 times_map = {}
2025-07-01 03:08:16.503 for i in range(0, N_MEASURES):
2025-07-01 03:08:16.507 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-07-01 03:08:16.512 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-07-01 03:08:16.516 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-07-01 03:08:16.521 times_map[ 'hash_eval', i ]  = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-07-01 03:08:16.525
2025-07-01 03:08:16.530 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-07-01 03:08:16.536 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-07-01 03:08:16.542 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-07-01 03:08:16.548 times_map[ 'udr_call', i ]  = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-07-01 03:08:16.554
2025-07-01 03:08:16.559
2025-07-01 03:08:16.564 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-07-01 03:08:16.569 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-07-01 03:08:16.573
2025-07-01 03:08:16.578 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-07-01 03:08:16.582
2025-07-01 03:08:16.587 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-07-01 03:08:16.591 if median_ratio > MAX_RATIO:
2025-07-01 03:08:16.597 print(f'CPU times for each of {N_MEASURES} measures:')
2025-07-01 03:08:16.602 for sp_name in ('hash_eval', 'udr_call', ):
2025-07-01 03:08:16.607 print(f'{sp_name=}:')
2025-07-01 03:08:16.613 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-07-01 03:08:16.619 print(p)
2025-07-01 03:08:16.625
2025-07-01 03:08:16.631 act.expected_stdout = expected_stdout
2025-07-01 03:08:16.637 act.stdout = capsys.readouterr().out
2025-07-01 03:08:16.644 >       assert act.clean_stdout == act.clean_expected_stdout
2025-07-01 03:08:16.650 E       AssertionError: assert
2025-07-01 03:08:16.656 E         - Medians ratio: acceptable
2025-07-01 03:08:16.667 E         + Medians ratio: /* perf_issue_tag */ POOR:   4.94286, more than threshold:       0.4
2025-07-01 03:08:16.680 E         + CPU times for each of 21 measures:
2025-07-01 03:08:16.686 E         + sp_name='hash_eval':
2025-07-01 03:08:16.693 E         + 0.33999999999969077
2025-07-01 03:08:16.699 E         + 0.38999999999987267
2025-07-01 03:08:16.705 E         + 0.36999999999989086
2025-07-01 03:08:16.710 E         + 0.32999999999992724
2025-07-01 03:08:16.716 E         + 0.33999999999969077
2025-07-01 03:08:16.722 E         + 0.32999999999992724
2025-07-01 03:08:16.728 E         + 0.34999999999990905
2025-07-01 03:08:16.734 E         + 0.3599999999996726
2025-07-01 03:08:16.741 E         + 0.3400000000001455
2025-07-01 03:08:16.748 E         + 0.32999999999992724
2025-07-01 03:08:16.754 E         + 0.3400000000001455
2025-07-01 03:08:16.759 E         + 0.34999999999990905
2025-07-01 03:08:16.763 E         + 0.3400000000001455
2025-07-01 03:08:16.768 E         + 0.36999999999989086
2025-07-01 03:08:16.772 E         + 0.34999999999990905
2025-07-01 03:08:16.776 E         + 0.36000000000012733
2025-07-01 03:08:16.781 E         + 0.34999999999990905
2025-07-01 03:08:16.785 E         + 0.32999999999992724
2025-07-01 03:08:16.789 E         + 0.32999999999992724
2025-07-01 03:08:16.794 E         + 0.36000000000012733
2025-07-01 03:08:16.798 E         + 0.34999999999990905
2025-07-01 03:08:16.803 E         + sp_name='udr_call':
2025-07-01 03:08:16.809 E         + 1.800000000000182
2025-07-01 03:08:16.816 E         + 1.7300000000000182
2025-07-01 03:08:16.822 E         + 1.7400000000002365
2025-07-01 03:08:16.829 E         + 1.6900000000000546
2025-07-01 03:08:16.836 E         + 1.7000000000002728
2025-07-01 03:08:16.841 E         + 1.7300000000000182
2025-07-01 03:08:16.846 E         + 1.7400000000002365
2025-07-01 03:08:16.851 E         + 1.6700000000000728
2025-07-01 03:08:16.855 E         + 1.699999999999818
2025-07-01 03:08:16.861 E         + 1.7600000000002183
2025-07-01 03:08:16.865 E         + 1.7300000000000182
2025-07-01 03:08:16.870 E         + 1.7399999999997817
2025-07-01 03:08:16.875 E         + 1.849999999999909
2025-07-01 03:08:16.880 E         + 1.7000000000002728
2025-07-01 03:08:16.885 E         + 1.7100000000000364
2025-07-01 03:08:16.890 E         + 1.699999999999818
2025-07-01 03:08:16.896 E         + 1.7000000000002728
2025-07-01 03:08:16.900 E         + 1.7300000000000182
2025-07-01 03:08:16.906 E         + 1.7100000000000364
2025-07-01 03:08:16.910 E         + 1.7799999999997453
2025-07-01 03:08:16.915 E         + 1.6900000000000546
2025-07-01 03:08:16.919
2025-07-01 03:08:16.925 tests/bugs/gh_7989_test.py:152: AssertionError
2025-07-01 03:08:16.929 ---------------------------- Captured stdout setup -----------------------------
2025-07-01 03:08:16.934 Creating db: localhost:/var/tmp/qa_2024/test_11662/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.94286, more than threshold:       0.4
E         + CPU times for each of 21 measures:
E         + sp_name='hash_eval':
E         + 0.33999999999969077
E         + 0.38999999999987267
E         + 0.36999999999989086
E         + 0.32999999999992724
E         + 0.33999999999969077
E         + 0.32999999999992724
E         + 0.34999999999990905
E         + 0.3599999999996726
E         + 0.3400000000001455
E         + 0.32999999999992724
E         + 0.3400000000001455
E         + 0.34999999999990905
E         + 0.3400000000001455
E         + 0.36999999999989086
E         + 0.34999999999990905
E         + 0.36000000000012733
E         + 0.34999999999990905
E         + 0.32999999999992724
E         + 0.32999999999992724
E         + 0.36000000000012733
E         + 0.34999999999990905
E         + sp_name='udr_call':
E         + 1.800000000000182
E         + 1.7300000000000182
E         + 1.7400000000002365
E         + 1.6900000000000546
E         + 1.7000000000002728
E         + 1.7300000000000182
E         + 1.7400000000002365
E         + 1.6700000000000728
E         + 1.699999999999818
E         + 1.7600000000002183
E         + 1.7300000000000182
E         + 1.7399999999997817
E         + 1.849999999999909
E         + 1.7000000000002728
E         + 1.7100000000000364
E         + 1.699999999999818
E         + 1.7000000000002728
E         + 1.7300000000000182
E         + 1.7100000000000364
E         + 1.7799999999997453
E         + 1.6900000000000546

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.892 2025.07.02 10f7d F F 43382 71837 2025.07.03 01:44:13.646 2025.07.03 01:44:57.028 2025.07.02 23:08:46.558 2025.07.02 23:09:58.395
2 6.0.0.889 2025.07.01 969ac F F 44883 69557 2025.07.02 02:12:09.130 2025.07.02 02:12:54.013 2025.07.01 23:22:06.242 2025.07.01 23:23:15.799
3 6.0.0.884 2025.06.30 f7e5f F F 43751 71832 2025.07.01 02:12:28.116 2025.07.01 02:13:11.867 2025.06.30 23:30:41.486 2025.06.30 23:31:53.318
4 6.0.0.881 2025.06.27 7035d F F 45814 71314 2025.06.30 02:02:38.833 2025.06.30 02:03:24.647 2025.06.29 23:17:47.961 2025.06.29 23:18:59.275
5 6.0.0.877 2025.06.26 8e38f F F 43660 71977 2025.06.27 01:41:44.664 2025.06.27 01:42:28.324 2025.06.26 23:08:49.005 2025.06.26 23:10:00.982
6 6.0.0.876 2025.06.25 b1bec F F 43711 71334 2025.06.26 01:45:34.639 2025.06.26 01:46:18.350 2025.06.25 23:10:44.100 2025.06.25 23:11:55.434
7 6.0.0.863 2025.06.24 c3c20 F F 43676 72162 2025.06.25 01:45:52.900 2025.06.25 01:46:36.576 2025.06.24 23:10:28.039 2025.06.24 23:11:40.201
8 6.0.0.858 2025.06.23 8d6f7 F F 43322 71268 2025.06.24 01:46:14.604 2025.06.24 01:46:57.926 2025.06.23 23:10:37.716 2025.06.23 23:11:48.984
9 6.0.0.849 2025.06.20 7b79c F F 44099 74560 2025.06.21 01:57:46.613 2025.06.21 01:58:30.712 2025.06.20 23:19:45.054 2025.06.20 23:20:59.614
10 6.0.0.848 2025.06.19 c483c F F 44101 74992 2025.06.20 01:54:07.334 2025.06.20 01:54:51.435 2025.06.19 23:16:33.089 2025.06.19 23:17:48.081
11 6.0.0.845 2025.06.18 22b12 F F 44567 75830 2025.06.19 02:02:46.191 2025.06.19 02:03:30.758 2025.06.18 23:19:38.338 2025.06.18 23:20:54.168
12 6.0.0.843 2025.06.16 995f4 F F 45113 65901 2025.06.18 02:01:00.606 2025.06.18 02:01:45.719 2025.06.17 23:22:10.514 2025.06.17 23:23:16.415
13 6.0.0.840 2025.06.14 29bca F F 44087 74125 2025.06.16 01:52:49.635 2025.06.16 01:53:33.722 2025.06.15 23:13:59.417 2025.06.15 23:15:13.542
14 6.0.0.838 2025.06.13 0e28a F F 44852 73947 2025.06.14 02:05:51.294 2025.06.14 02:06:36.146 2025.06.13 23:21:36.802 2025.06.13 23:22:50.749
15 6.0.0.835 2025.06.12 2cf29 F F 44171 53393 2025.06.13 02:05:51.089 2025.06.13 02:06:35.260 2025.06.12 23:26:05.609 2025.06.12 23:26:59.002
16 6.0.0.834 2025.06.11 e889f F F 44731 62345 2025.06.12 02:01:01.832 2025.06.12 02:01:46.563 2025.06.11 23:22:03.011 2025.06.11 23:23:05.356
17 6.0.0.800 2025.06.10 1f226 P P 18838 17502 2025.06.11 00:28:03.820 2025.06.11 00:28:22.658 2025.06.10 22:20:49.071 2025.06.10 22:21:06.573
18 6.0.0.799 2025.06.07 be644 P P 10911 17546 2025.06.10 00:29:59.535 2025.06.10 00:30:10.446 2025.06.09 22:20:24.118 2025.06.09 22:20:41.664
19 6.0.0.797 2025.06.06 303e8 P P 17599 20083 2025.06.07 00:33:35.559 2025.06.07 00:33:53.158 2025.06.06 22:19:51.915 2025.06.06 22:20:11.998
20 6.0.0.795 2025.05.29 7a71a P P 11527 17832 2025.06.06 00:28:33.911 2025.06.06 00:28:45.438 2025.06.05 22:19:05.843 2025.06.05 22:19:23.675
21 6.0.0.792 2025.05.28 b4327 P P 18904 22202 2025.05.29 00:42:07.794 2025.05.29 00:42:26.698 2025.05.28 22:21:51.132 2025.05.28 22:22:13.334
22 6.0.0.791 2025.05.27 02db8 P P 12334 17373 2025.05.28 00:39:39.530 2025.05.28 00:39:51.864 2025.05.27 22:21:05.661 2025.05.27 22:21:23.034
23 6.0.0.789 2025.05.21 64051 P P 14321 18803 2025.05.25 00:32:20.551 2025.05.25 00:32:34.872 2025.05.24 22:20:17.295 2025.05.24 22:20:36.098
24 6.0.0.787 2025.05.20 230ad P P 11777 18421 2025.05.21 00:29:31.165 2025.05.21 00:29:42.942 2025.05.20 22:18:41.638 2025.05.20 22:19:00.059
25 6.0.0.783 2025.05.12 37320 P P 12264 12381 2025.05.19 12:02:51.633 2025.05.19 12:03:03.897 2025.05.19 10:07:38.231 2025.05.19 10:07:50.612

Elapsed time, ms. Chart for last 25 runs:

Last commits information (all timestamps in UTC):