2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.55556, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.38
+ 0.3599999999999999
+ 0.3600000000000003
+ 0.33999999999999986
+ 0.3699999999999992
+ 0.3600000000000012
+ 0.34999999999999964
+ 0.3699999999999992
+ 0.360000000000003
+ 0.35999999999999943
+ 0.33999999999999986
+ 0.379999999999999
+ 0.34999999999999787
+ 0.39000000000000057
+ 0.36999999999999744
+ 0.35999999999999943
+ 0.3500000000000014
+ 0.36999999999999744
+ 0.3500000000000014
+ 0.36999999999999744
+ 0.35999999999999943
+ sp_name='udr_call':
+ 1.71
+ 1.71
+ 1.62
+ 1.63
+ 1.6600000000000001
+ 1.6099999999999994
+ 1.7800000000000011
+ 1.6399999999999988
+ 1.6099999999999994
+ 1.620000000000001
+ 1.629999999999999
+ 1.6000000000000014
+ 1.620000000000001
+ 1.6400000000000006
+ 1.6700000000000017
+ 1.7999999999999972
+ 1.6700000000000017
+ 1.740000000000002
+ 1.6499999999999986
+ 1.5800000000000054
+ 1.6499999999999986
LOG DETAILS:
2025-06-24 05:22:55.744
2025-06-24 05:22:55.749 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-24 05:22:55.754 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-24 05:22:55.759
2025-06-24 05:22:55.764 @pytest.mark.version('>=6.0')
2025-06-24 05:22:55.768 def test_1(act: Action, capsys):
2025-06-24 05:22:55.773
2025-06-24 05:22:55.778 with act.db.connect() as con:
2025-06-24 05:22:55.783 cur=con.cursor()
2025-06-24 05:22:55.794 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-24 05:22:55.801 fb_pid = int(cur.fetchone()[0])
2025-06-24 05:22:55.808
2025-06-24 05:22:55.812 times_map = {}
2025-06-24 05:22:55.818 for i in range(0, N_MEASURES):
2025-06-24 05:22:55.828 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-24 05:22:55.839 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-24 05:22:55.849 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-24 05:22:55.858 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-24 05:22:55.865
2025-06-24 05:22:55.877 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-24 05:22:55.887 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-24 05:22:55.899 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-24 05:22:55.909 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-24 05:22:55.920
2025-06-24 05:22:55.930
2025-06-24 05:22:55.939 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-24 05:22:55.950 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-24 05:22:55.961
2025-06-24 05:22:55.973 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-24 05:22:55.983
2025-06-24 05:22:55.992 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 05:22:55.999 if median_ratio > MAX_RATIO:
2025-06-24 05:22:56.007 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-24 05:22:56.018 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-24 05:22:56.027 print(f'{sp_name=}:')
2025-06-24 05:22:56.034 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-24 05:22:56.041 print(p)
2025-06-24 05:22:56.048
2025-06-24 05:22:56.054 act.expected_stdout = expected_stdout
2025-06-24 05:22:56.063 act.stdout = capsys.readouterr().out
2025-06-24 05:22:56.075 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-24 05:22:56.083 E AssertionError: assert
2025-06-24 05:22:56.090 E - Medians ratio: acceptable
2025-06-24 05:22:56.099 E + Medians ratio: /* perf_issue_tag */ POOR: 4.55556, more than threshold: 0.4
2025-06-24 05:22:56.111 E + CPU times for each of 21 measures:
2025-06-24 05:22:56.120 E + sp_name='hash_eval':
2025-06-24 05:22:56.127 E + 0.38
2025-06-24 05:22:56.134 E + 0.3599999999999999
2025-06-24 05:22:56.144 E + 0.3600000000000003
2025-06-24 05:22:56.151 E + 0.33999999999999986
2025-06-24 05:22:56.156 E + 0.3699999999999992
2025-06-24 05:22:56.162 E + 0.3600000000000012
2025-06-24 05:22:56.169 E + 0.34999999999999964
2025-06-24 05:22:56.175 E + 0.3699999999999992
2025-06-24 05:22:56.181 E + 0.360000000000003
2025-06-24 05:22:56.187 E + 0.35999999999999943
2025-06-24 05:22:56.194 E + 0.33999999999999986
2025-06-24 05:22:56.202 E + 0.379999999999999
2025-06-24 05:22:56.209 E + 0.34999999999999787
2025-06-24 05:22:56.214 E + 0.39000000000000057
2025-06-24 05:22:56.222 E + 0.36999999999999744
2025-06-24 05:22:56.229 E + 0.35999999999999943
2025-06-24 05:22:56.236 E + 0.3500000000000014
2025-06-24 05:22:56.242 E + 0.36999999999999744
2025-06-24 05:22:56.252 E + 0.3500000000000014
2025-06-24 05:22:56.261 E + 0.36999999999999744
2025-06-24 05:22:56.269 E + 0.35999999999999943
2025-06-24 05:22:56.276 E + sp_name='udr_call':
2025-06-24 05:22:56.281 E + 1.71
2025-06-24 05:22:56.287 E + 1.71
2025-06-24 05:22:56.293 E + 1.62
2025-06-24 05:22:56.304 E + 1.63
2025-06-24 05:22:56.316 E + 1.6600000000000001
2025-06-24 05:22:56.328 E + 1.6099999999999994
2025-06-24 05:22:56.337 E + 1.7800000000000011
2025-06-24 05:22:56.343 E + 1.6399999999999988
2025-06-24 05:22:56.349 E + 1.6099999999999994
2025-06-24 05:22:56.355 E + 1.620000000000001
2025-06-24 05:22:56.362 E + 1.629999999999999
2025-06-24 05:22:56.370 E + 1.6000000000000014
2025-06-24 05:22:56.377 E + 1.620000000000001
2025-06-24 05:22:56.385 E + 1.6400000000000006
2025-06-24 05:22:56.392 E + 1.6700000000000017
2025-06-24 05:22:56.398 E + 1.7999999999999972
2025-06-24 05:22:56.408 E + 1.6700000000000017
2025-06-24 05:22:56.420 E + 1.740000000000002
2025-06-24 05:22:56.430 E + 1.6499999999999986
2025-06-24 05:22:56.441 E + 1.5800000000000054
2025-06-24 05:22:56.451 E + 1.6499999999999986
2025-06-24 05:22:56.460
2025-06-24 05:22:56.468 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-24 05:22:56.475 ---------------------------- Captured stdout setup -----------------------------
2025-06-24 05:22:56.483 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.55556, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.38
E + 0.3599999999999999
E + 0.3600000000000003
E + 0.33999999999999986
E + 0.3699999999999992
E + 0.3600000000000012
E + 0.34999999999999964
E + 0.3699999999999992
E + 0.360000000000003
E + 0.35999999999999943
E + 0.33999999999999986
E + 0.379999999999999
E + 0.34999999999999787
E + 0.39000000000000057
E + 0.36999999999999744
E + 0.35999999999999943
E + 0.3500000000000014
E + 0.36999999999999744
E + 0.3500000000000014
E + 0.36999999999999744
E + 0.35999999999999943
E + sp_name='udr_call':
E + 1.71
E + 1.71
E + 1.62
E + 1.63
E + 1.6600000000000001
E + 1.6099999999999994
E + 1.7800000000000011
E + 1.6399999999999988
E + 1.6099999999999994
E + 1.620000000000001
E + 1.629999999999999
E + 1.6000000000000014
E + 1.620000000000001
E + 1.6400000000000006
E + 1.6700000000000017
E + 1.7999999999999972
E + 1.6700000000000017
E + 1.740000000000002
E + 1.6499999999999986
E + 1.5800000000000054
E + 1.6499999999999986
tests/bugs/gh_7989_test.py:152: AssertionError
|