2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.94444, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.3600000000005821
+ 0.3599999999996726
+ 0.3599999999996726
+ 0.3600000000005821
+ 0.3400000000001455
+ 0.3499999999994543
+ 0.38000000000010914
+ 0.4399999999995998
+ 0.3599999999996726
+ 0.3599999999996726
+ 0.3400000000001455
+ 0.3499999999994543
+ 0.36999999999989086
+ 0.37000000000080036
+ 0.3499999999994543
+ 0.3899999999994179
+ 0.38000000000010914
+ 0.3500000000003638
+ 0.3499999999994543
+ 0.3499999999994543
+ 0.3999999999996362
+ sp_name='udr_call':
+ 1.8699999999998909
+ 1.7400000000006912
+ 1.769999999999527
+ 1.949999999999818
+ 1.7600000000002183
+ 1.8299999999999272
+ 1.930000000000291
+ 1.8200000000006185
+ 1.7600000000002183
+ 1.7600000000002183
+ 1.8699999999998909
+ 1.7600000000002183
+ 1.9899999999997817
+ 1.75
+ 1.8100000000004002
+ 1.75
+ 1.7200000000002547
+ 1.8699999999998909
+ 1.7700000000004366
+ 1.8200000000006185
+ 1.7799999999997453
LOG DETAILS:
2025-06-19 02:53:51.416
2025-06-19 02:53:51.421 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-19 02:53:51.426 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-19 02:53:51.430
2025-06-19 02:53:51.435 @pytest.mark.version('>=6.0')
2025-06-19 02:53:51.439 def test_1(act: Action, capsys):
2025-06-19 02:53:51.443
2025-06-19 02:53:51.449 with act.db.connect() as con:
2025-06-19 02:53:51.454 cur=con.cursor()
2025-06-19 02:53:51.458 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-19 02:53:51.463 fb_pid = int(cur.fetchone()[0])
2025-06-19 02:53:51.468
2025-06-19 02:53:51.472 times_map = {}
2025-06-19 02:53:51.477 for i in range(0, N_MEASURES):
2025-06-19 02:53:51.482 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-19 02:53:51.487 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-19 02:53:51.491 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-19 02:53:51.496 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-19 02:53:51.501
2025-06-19 02:53:51.506 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-19 02:53:51.511 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-19 02:53:51.516 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-19 02:53:51.521 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-19 02:53:51.525
2025-06-19 02:53:51.530
2025-06-19 02:53:51.535 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-19 02:53:51.540 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-19 02:53:51.545
2025-06-19 02:53:51.550 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-19 02:53:51.554
2025-06-19 02:53:51.559 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-19 02:53:51.564 if median_ratio > MAX_RATIO:
2025-06-19 02:53:51.569 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-19 02:53:51.574 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-19 02:53:51.578 print(f'{sp_name=}:')
2025-06-19 02:53:51.583 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-19 02:53:51.588 print(p)
2025-06-19 02:53:51.592
2025-06-19 02:53:51.597 act.expected_stdout = expected_stdout
2025-06-19 02:53:51.601 act.stdout = capsys.readouterr().out
2025-06-19 02:53:51.606 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-19 02:53:51.610 E AssertionError: assert
2025-06-19 02:53:51.615 E - Medians ratio: acceptable
2025-06-19 02:53:51.620 E + Medians ratio: /* perf_issue_tag */ POOR: 4.94444, more than threshold: 0.4
2025-06-19 02:53:51.624 E + CPU times for each of 21 measures:
2025-06-19 02:53:51.629 E + sp_name='hash_eval':
2025-06-19 02:53:51.634 E + 0.3600000000005821
2025-06-19 02:53:51.638 E + 0.3599999999996726
2025-06-19 02:53:51.643 E + 0.3599999999996726
2025-06-19 02:53:51.649 E + 0.3600000000005821
2025-06-19 02:53:51.654 E + 0.3400000000001455
2025-06-19 02:53:51.659 E + 0.3499999999994543
2025-06-19 02:53:51.663 E + 0.38000000000010914
2025-06-19 02:53:51.668 E + 0.4399999999995998
2025-06-19 02:53:51.672 E + 0.3599999999996726
2025-06-19 02:53:51.677 E + 0.3599999999996726
2025-06-19 02:53:51.681 E + 0.3400000000001455
2025-06-19 02:53:51.686 E + 0.3499999999994543
2025-06-19 02:53:51.690 E + 0.36999999999989086
2025-06-19 02:53:51.695 E + 0.37000000000080036
2025-06-19 02:53:51.700 E + 0.3499999999994543
2025-06-19 02:53:51.705 E + 0.3899999999994179
2025-06-19 02:53:51.710 E + 0.38000000000010914
2025-06-19 02:53:51.715 E + 0.3500000000003638
2025-06-19 02:53:51.720 E + 0.3499999999994543
2025-06-19 02:53:51.725 E + 0.3499999999994543
2025-06-19 02:53:51.730 E + 0.3999999999996362
2025-06-19 02:53:51.736 E + sp_name='udr_call':
2025-06-19 02:53:51.741 E + 1.8699999999998909
2025-06-19 02:53:51.745 E + 1.7400000000006912
2025-06-19 02:53:51.750 E + 1.769999999999527
2025-06-19 02:53:51.755 E + 1.949999999999818
2025-06-19 02:53:51.760 E + 1.7600000000002183
2025-06-19 02:53:51.765 E + 1.8299999999999272
2025-06-19 02:53:51.770 E + 1.930000000000291
2025-06-19 02:53:51.774 E + 1.8200000000006185
2025-06-19 02:53:51.779 E + 1.7600000000002183
2025-06-19 02:53:51.784 E + 1.7600000000002183
2025-06-19 02:53:51.789 E + 1.8699999999998909
2025-06-19 02:53:51.794 E + 1.7600000000002183
2025-06-19 02:53:51.799 E + 1.9899999999997817
2025-06-19 02:53:51.804 E + 1.75
2025-06-19 02:53:51.809 E + 1.8100000000004002
2025-06-19 02:53:51.814 E + 1.75
2025-06-19 02:53:51.819 E + 1.7200000000002547
2025-06-19 02:53:51.824 E + 1.8699999999998909
2025-06-19 02:53:51.829 E + 1.7700000000004366
2025-06-19 02:53:51.834 E + 1.8200000000006185
2025-06-19 02:53:51.839 E + 1.7799999999997453
2025-06-19 02:53:51.844
2025-06-19 02:53:51.849 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-19 02:53:51.854 ---------------------------- Captured stdout setup -----------------------------
2025-06-19 02:53:51.859 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.94444, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.3600000000005821
E + 0.3599999999996726
E + 0.3599999999996726
E + 0.3600000000005821
E + 0.3400000000001455
E + 0.3499999999994543
E + 0.38000000000010914
E + 0.4399999999995998
E + 0.3599999999996726
E + 0.3599999999996726
E + 0.3400000000001455
E + 0.3499999999994543
E + 0.36999999999989086
E + 0.37000000000080036
E + 0.3499999999994543
E + 0.3899999999994179
E + 0.38000000000010914
E + 0.3500000000003638
E + 0.3499999999994543
E + 0.3499999999994543
E + 0.3999999999996362
E + sp_name='udr_call':
E + 1.8699999999998909
E + 1.7400000000006912
E + 1.769999999999527
E + 1.949999999999818
E + 1.7600000000002183
E + 1.8299999999999272
E + 1.930000000000291
E + 1.8200000000006185
E + 1.7600000000002183
E + 1.7600000000002183
E + 1.8699999999998909
E + 1.7600000000002183
E + 1.9899999999997817
E + 1.75
E + 1.8100000000004002
E + 1.75
E + 1.7200000000002547
E + 1.8699999999998909
E + 1.7700000000004366
E + 1.8200000000006185
E + 1.7799999999997453
tests/bugs/gh_7989_test.py:152: AssertionError
|