2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.63889, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.37
+ 0.3999999999999999
+ 0.34000000000000075
+ 0.33999999999999986
+ 0.35999999999999943
+ 0.40000000000000036
+ 0.35999999999999943
+ 0.3899999999999988
+ 0.379999999999999
+ 0.3500000000000014
+ 0.33999999999999986
+ 0.46000000000000085
+ 0.370000000000001
+ 0.4499999999999993
+ 0.370000000000001
+ 0.33999999999999986
+ 0.35999999999999943
+ 0.35999999999999943
+ 0.3399999999999963
+ 0.37999999999999545
+ 0.35999999999999943
+ sp_name='udr_call':
+ 1.62
+ 1.6199999999999997
+ 1.67
+ 1.67
+ 1.6500000000000004
+ 1.6799999999999997
+ 1.6800000000000015
+ 1.6100000000000012
+ 1.6499999999999986
+ 1.6900000000000013
+ 1.629999999999999
+ 1.6899999999999977
+ 1.6700000000000017
+ 1.6999999999999993
+ 1.6799999999999997
+ 1.8000000000000007
+ 1.8100000000000023
+ 1.6499999999999986
+ 1.8000000000000043
+ 1.6100000000000065
+ 1.8200000000000003
LOG DETAILS:
2025-06-13 05:42:48.329
2025-06-13 05:42:48.335 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-13 05:42:48.341 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-13 05:42:48.346
2025-06-13 05:42:48.352 @pytest.mark.version('>=6.0')
2025-06-13 05:42:48.357 def test_1(act: Action, capsys):
2025-06-13 05:42:48.363
2025-06-13 05:42:48.369 with act.db.connect() as con:
2025-06-13 05:42:48.374 cur=con.cursor()
2025-06-13 05:42:48.382 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-13 05:42:48.393 fb_pid = int(cur.fetchone()[0])
2025-06-13 05:42:48.404
2025-06-13 05:42:48.410 times_map = {}
2025-06-13 05:42:48.418 for i in range(0, N_MEASURES):
2025-06-13 05:42:48.427 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-13 05:42:48.437 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-13 05:42:48.446 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-13 05:42:48.455 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-13 05:42:48.462
2025-06-13 05:42:48.473 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-13 05:42:48.484 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-13 05:42:48.492 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-13 05:42:48.500 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-13 05:42:48.506
2025-06-13 05:42:48.511
2025-06-13 05:42:48.520 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-13 05:42:48.526 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-13 05:42:48.531
2025-06-13 05:42:48.537 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-13 05:42:48.543
2025-06-13 05:42:48.551 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-13 05:42:48.563 if median_ratio > MAX_RATIO:
2025-06-13 05:42:48.570 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-13 05:42:48.576 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-13 05:42:48.583 print(f'{sp_name=}:')
2025-06-13 05:42:48.588 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-13 05:42:48.594 print(p)
2025-06-13 05:42:48.599
2025-06-13 05:42:48.606 act.expected_stdout = expected_stdout
2025-06-13 05:42:48.613 act.stdout = capsys.readouterr().out
2025-06-13 05:42:48.620 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-13 05:42:48.627 E AssertionError: assert
2025-06-13 05:42:48.634 E - Medians ratio: acceptable
2025-06-13 05:42:48.641 E + Medians ratio: /* perf_issue_tag */ POOR: 4.63889, more than threshold: 0.4
2025-06-13 05:42:48.648 E + CPU times for each of 21 measures:
2025-06-13 05:42:48.654 E + sp_name='hash_eval':
2025-06-13 05:42:48.661 E + 0.37
2025-06-13 05:42:48.667 E + 0.3999999999999999
2025-06-13 05:42:48.674 E + 0.34000000000000075
2025-06-13 05:42:48.684 E + 0.33999999999999986
2025-06-13 05:42:48.694 E + 0.35999999999999943
2025-06-13 05:42:48.700 E + 0.40000000000000036
2025-06-13 05:42:48.706 E + 0.35999999999999943
2025-06-13 05:42:48.712 E + 0.3899999999999988
2025-06-13 05:42:48.719 E + 0.379999999999999
2025-06-13 05:42:48.727 E + 0.3500000000000014
2025-06-13 05:42:48.739 E + 0.33999999999999986
2025-06-13 05:42:48.749 E + 0.46000000000000085
2025-06-13 05:42:48.758 E + 0.370000000000001
2025-06-13 05:42:48.765 E + 0.4499999999999993
2025-06-13 05:42:48.771 E + 0.370000000000001
2025-06-13 05:42:48.777 E + 0.33999999999999986
2025-06-13 05:42:48.783 E + 0.35999999999999943
2025-06-13 05:42:48.790 E + 0.35999999999999943
2025-06-13 05:42:48.795 E + 0.3399999999999963
2025-06-13 05:42:48.801 E + 0.37999999999999545
2025-06-13 05:42:48.807 E + 0.35999999999999943
2025-06-13 05:42:48.816 E + sp_name='udr_call':
2025-06-13 05:42:48.826 E + 1.62
2025-06-13 05:42:48.832 E + 1.6199999999999997
2025-06-13 05:42:48.838 E + 1.67
2025-06-13 05:42:48.844 E + 1.67
2025-06-13 05:42:48.850 E + 1.6500000000000004
2025-06-13 05:42:48.856 E + 1.6799999999999997
2025-06-13 05:42:48.862 E + 1.6800000000000015
2025-06-13 05:42:48.868 E + 1.6100000000000012
2025-06-13 05:42:48.874 E + 1.6499999999999986
2025-06-13 05:42:48.880 E + 1.6900000000000013
2025-06-13 05:42:48.886 E + 1.629999999999999
2025-06-13 05:42:48.893 E + 1.6899999999999977
2025-06-13 05:42:48.899 E + 1.6700000000000017
2025-06-13 05:42:48.905 E + 1.6999999999999993
2025-06-13 05:42:48.911 E + 1.6799999999999997
2025-06-13 05:42:48.917 E + 1.8000000000000007
2025-06-13 05:42:48.922 E + 1.8100000000000023
2025-06-13 05:42:48.928 E + 1.6499999999999986
2025-06-13 05:42:48.934 E + 1.8000000000000043
2025-06-13 05:42:48.939 E + 1.6100000000000065
2025-06-13 05:42:48.945 E + 1.8200000000000003
2025-06-13 05:42:48.951
2025-06-13 05:42:48.956 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-13 05:42:48.962 ---------------------------- Captured stdout setup -----------------------------
2025-06-13 05:42:48.968 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.63889, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.37
E + 0.3999999999999999
E + 0.34000000000000075
E + 0.33999999999999986
E + 0.35999999999999943
E + 0.40000000000000036
E + 0.35999999999999943
E + 0.3899999999999988
E + 0.379999999999999
E + 0.3500000000000014
E + 0.33999999999999986
E + 0.46000000000000085
E + 0.370000000000001
E + 0.4499999999999993
E + 0.370000000000001
E + 0.33999999999999986
E + 0.35999999999999943
E + 0.35999999999999943
E + 0.3399999999999963
E + 0.37999999999999545
E + 0.35999999999999943
E + sp_name='udr_call':
E + 1.62
E + 1.6199999999999997
E + 1.67
E + 1.67
E + 1.6500000000000004
E + 1.6799999999999997
E + 1.6800000000000015
E + 1.6100000000000012
E + 1.6499999999999986
E + 1.6900000000000013
E + 1.629999999999999
E + 1.6899999999999977
E + 1.6700000000000017
E + 1.6999999999999993
E + 1.6799999999999997
E + 1.8000000000000007
E + 1.8100000000000023
E + 1.6499999999999986
E + 1.8000000000000043
E + 1.6100000000000065
E + 1.8200000000000003
tests/bugs/gh_7989_test.py:152: AssertionError
|