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.38000000000010914
+ 0.3500000000003638
+ 0.3600000000005821
+ 0.3900000000003274
+ 0.339999999999236
+ 0.3600000000005821
+ 0.3500000000003638
+ 0.3500000000003638
+ 0.38000000000010914
+ 0.3400000000001455
+ 0.3499999999994543
+ 0.339999999999236
+ 0.3500000000003638
+ 0.3400000000001455
+ 0.3499999999994543
+ 0.3499999999994543
+ 0.339999999999236
+ 0.3599999999996726
+ 0.36999999999989086
+ 0.3400000000001455
+ 0.3600000000005821
+ sp_name='udr_call':
+ 1.7100000000000364
+ 1.8099999999994907
+ 1.8099999999994907
+ 1.8400000000001455
+ 1.6300000000001091
+ 1.6799999999993815
+ 1.7399999999997817
+ 1.6700000000000728
+ 1.6499999999996362
+ 1.6700000000000728
+ 1.7000000000007276
+ 1.7200000000002547
+ 1.7599999999993088
+ 1.7400000000006912
+ 1.730000000000473
+ 1.6900000000005093
+ 1.8100000000004002
+ 1.7700000000004366
+ 1.6700000000000728
+ 1.7299999999995634
+ 1.7299999999995634
LOG DETAILS:
2025-06-12 02:55:36.606
2025-06-12 02:55:36.611 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-12 02:55:36.616 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-12 02:55:36.620
2025-06-12 02:55:36.625 @pytest.mark.version('>=6.0')
2025-06-12 02:55:36.629 def test_1(act: Action, capsys):
2025-06-12 02:55:36.634
2025-06-12 02:55:36.639 with act.db.connect() as con:
2025-06-12 02:55:36.643 cur=con.cursor()
2025-06-12 02:55:36.648 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-12 02:55:36.653 fb_pid = int(cur.fetchone()[0])
2025-06-12 02:55:36.657
2025-06-12 02:55:36.662 times_map = {}
2025-06-12 02:55:36.666 for i in range(0, N_MEASURES):
2025-06-12 02:55:36.671 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-12 02:55:36.676 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-12 02:55:36.680 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-12 02:55:36.685 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-12 02:55:36.690
2025-06-12 02:55:36.694 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-12 02:55:36.699 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-12 02:55:36.703 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-12 02:55:36.707 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-12 02:55:36.712
2025-06-12 02:55:36.717
2025-06-12 02:55:36.722 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-12 02:55:36.727 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-12 02:55:36.732
2025-06-12 02:55:36.736 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-12 02:55:36.741
2025-06-12 02:55:36.750 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-12 02:55:36.758 if median_ratio > MAX_RATIO:
2025-06-12 02:55:36.770 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-12 02:55:36.776 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-12 02:55:36.781 print(f'{sp_name=}:')
2025-06-12 02:55:36.786 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-12 02:55:36.791 print(p)
2025-06-12 02:55:36.795
2025-06-12 02:55:36.800 act.expected_stdout = expected_stdout
2025-06-12 02:55:36.804 act.stdout = capsys.readouterr().out
2025-06-12 02:55:36.809 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-12 02:55:36.814 E AssertionError: assert
2025-06-12 02:55:36.819 E - Medians ratio: acceptable
2025-06-12 02:55:36.823 E + Medians ratio: /* perf_issue_tag */ POOR: 4.94286, more than threshold: 0.4
2025-06-12 02:55:36.828 E + CPU times for each of 21 measures:
2025-06-12 02:55:36.832 E + sp_name='hash_eval':
2025-06-12 02:55:36.837 E + 0.38000000000010914
2025-06-12 02:55:36.841 E + 0.3500000000003638
2025-06-12 02:55:36.846 E + 0.3600000000005821
2025-06-12 02:55:36.851 E + 0.3900000000003274
2025-06-12 02:55:36.855 E + 0.339999999999236
2025-06-12 02:55:36.860 E + 0.3600000000005821
2025-06-12 02:55:36.865 E + 0.3500000000003638
2025-06-12 02:55:36.870 E + 0.3500000000003638
2025-06-12 02:55:36.875 E + 0.38000000000010914
2025-06-12 02:55:36.879 E + 0.3400000000001455
2025-06-12 02:55:36.885 E + 0.3499999999994543
2025-06-12 02:55:36.890 E + 0.339999999999236
2025-06-12 02:55:36.894 E + 0.3500000000003638
2025-06-12 02:55:36.899 E + 0.3400000000001455
2025-06-12 02:55:36.903 E + 0.3499999999994543
2025-06-12 02:55:36.908 E + 0.3499999999994543
2025-06-12 02:55:36.913 E + 0.339999999999236
2025-06-12 02:55:36.917 E + 0.3599999999996726
2025-06-12 02:55:36.922 E + 0.36999999999989086
2025-06-12 02:55:36.926 E + 0.3400000000001455
2025-06-12 02:55:36.931 E + 0.3600000000005821
2025-06-12 02:55:36.935 E + sp_name='udr_call':
2025-06-12 02:55:36.940 E + 1.7100000000000364
2025-06-12 02:55:36.945 E + 1.8099999999994907
2025-06-12 02:55:36.949 E + 1.8099999999994907
2025-06-12 02:55:36.954 E + 1.8400000000001455
2025-06-12 02:55:36.958 E + 1.6300000000001091
2025-06-12 02:55:36.964 E + 1.6799999999993815
2025-06-12 02:55:36.968 E + 1.7399999999997817
2025-06-12 02:55:36.973 E + 1.6700000000000728
2025-06-12 02:55:36.978 E + 1.6499999999996362
2025-06-12 02:55:36.982 E + 1.6700000000000728
2025-06-12 02:55:36.987 E + 1.7000000000007276
2025-06-12 02:55:36.992 E + 1.7200000000002547
2025-06-12 02:55:36.998 E + 1.7599999999993088
2025-06-12 02:55:37.002 E + 1.7400000000006912
2025-06-12 02:55:37.007 E + 1.730000000000473
2025-06-12 02:55:37.011 E + 1.6900000000005093
2025-06-12 02:55:37.016 E + 1.8100000000004002
2025-06-12 02:55:37.021 E + 1.7700000000004366
2025-06-12 02:55:37.026 E + 1.6700000000000728
2025-06-12 02:55:37.030 E + 1.7299999999995634
2025-06-12 02:55:37.035 E + 1.7299999999995634
2025-06-12 02:55:37.040
2025-06-12 02:55:37.045 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-12 02:55:37.049 ---------------------------- Captured stdout setup -----------------------------
2025-06-12 02:55:37.054 Creating db: localhost:/var/tmp/qa_2024/test_11654/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.38000000000010914
E + 0.3500000000003638
E + 0.3600000000005821
E + 0.3900000000003274
E + 0.339999999999236
E + 0.3600000000005821
E + 0.3500000000003638
E + 0.3500000000003638
E + 0.38000000000010914
E + 0.3400000000001455
E + 0.3499999999994543
E + 0.339999999999236
E + 0.3500000000003638
E + 0.3400000000001455
E + 0.3499999999994543
E + 0.3499999999994543
E + 0.339999999999236
E + 0.3599999999996726
E + 0.36999999999989086
E + 0.3400000000001455
E + 0.3600000000005821
E + sp_name='udr_call':
E + 1.7100000000000364
E + 1.8099999999994907
E + 1.8099999999994907
E + 1.8400000000001455
E + 1.6300000000001091
E + 1.6799999999993815
E + 1.7399999999997817
E + 1.6700000000000728
E + 1.6499999999996362
E + 1.6700000000000728
E + 1.7000000000007276
E + 1.7200000000002547
E + 1.7599999999993088
E + 1.7400000000006912
E + 1.730000000000473
E + 1.6900000000005093
E + 1.8100000000004002
E + 1.7700000000004366
E + 1.6700000000000728
E + 1.7299999999995634
E + 1.7299999999995634
tests/bugs/gh_7989_test.py:152: AssertionError
|