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.36
+ 0.3700000000000001
+ 0.33999999999999986
+ 0.3700000000000001
+ 0.33999999999999986
+ 0.3600000000000012
+ 0.3899999999999988
+ 0.35999999999999943
+ 0.46999999999999886
+ 0.33999999999999986
+ 0.39000000000000057
+ 0.35999999999999943
+ 0.360000000000003
+ 0.33999999999999986
+ 0.3500000000000014
+ 0.33999999999999986
+ 0.36000000000000654
+ 0.3500000000000014
+ 0.38000000000000256
+ 0.35999999999999943
+ 0.39000000000000057
+ sp_name='udr_call':
+ 1.68
+ 1.63
+ 1.6000000000000005
+ 1.6099999999999994
+ 1.6799999999999997
+ 1.6600000000000001
+ 1.6300000000000008
+ 1.6799999999999997
+ 1.8000000000000007
+ 1.6900000000000013
+ 1.6400000000000006
+ 1.6899999999999977
+ 1.6699999999999982
+ 1.6600000000000001
+ 1.8299999999999983
+ 1.6899999999999977
+ 1.6699999999999946
+ 1.6000000000000014
+ 1.7299999999999969
+ 1.6300000000000026
+ 1.6299999999999955
LOG DETAILS:
2025-06-27 05:17:56.523
2025-06-27 05:17:56.532 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-27 05:17:56.541 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-27 05:17:56.548
2025-06-27 05:17:56.554 @pytest.mark.version('>=6.0')
2025-06-27 05:17:56.560 def test_1(act: Action, capsys):
2025-06-27 05:17:56.566
2025-06-27 05:17:56.571 with act.db.connect() as con:
2025-06-27 05:17:56.577 cur=con.cursor()
2025-06-27 05:17:56.583 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-27 05:17:56.588 fb_pid = int(cur.fetchone()[0])
2025-06-27 05:17:56.594
2025-06-27 05:17:56.599 times_map = {}
2025-06-27 05:17:56.606 for i in range(0, N_MEASURES):
2025-06-27 05:17:56.611 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-27 05:17:56.617 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-27 05:17:56.622 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-27 05:17:56.629 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-27 05:17:56.634
2025-06-27 05:17:56.644 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-27 05:17:56.653 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-27 05:17:56.660 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-27 05:17:56.667 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-27 05:17:56.674
2025-06-27 05:17:56.685
2025-06-27 05:17:56.693 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-27 05:17:56.698 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-27 05:17:56.703
2025-06-27 05:17:56.711 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-27 05:17:56.721
2025-06-27 05:17:56.730 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-27 05:17:56.736 if median_ratio > MAX_RATIO:
2025-06-27 05:17:56.742 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-27 05:17:56.747 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-27 05:17:56.753 print(f'{sp_name=}:')
2025-06-27 05:17:56.758 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-27 05:17:56.762 print(p)
2025-06-27 05:17:56.768
2025-06-27 05:17:56.775 act.expected_stdout = expected_stdout
2025-06-27 05:17:56.785 act.stdout = capsys.readouterr().out
2025-06-27 05:17:56.793 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-27 05:17:56.807 E AssertionError: assert
2025-06-27 05:17:56.817 E - Medians ratio: acceptable
2025-06-27 05:17:56.829 E + Medians ratio: /* perf_issue_tag */ POOR: 4.63889, more than threshold: 0.4
2025-06-27 05:17:56.839 E + CPU times for each of 21 measures:
2025-06-27 05:17:56.850 E + sp_name='hash_eval':
2025-06-27 05:17:56.862 E + 0.36
2025-06-27 05:17:56.870 E + 0.3700000000000001
2025-06-27 05:17:56.880 E + 0.33999999999999986
2025-06-27 05:17:56.892 E + 0.3700000000000001
2025-06-27 05:17:56.902 E + 0.33999999999999986
2025-06-27 05:17:56.913 E + 0.3600000000000012
2025-06-27 05:17:56.925 E + 0.3899999999999988
2025-06-27 05:17:56.935 E + 0.35999999999999943
2025-06-27 05:17:56.943 E + 0.46999999999999886
2025-06-27 05:17:56.950 E + 0.33999999999999986
2025-06-27 05:17:56.960 E + 0.39000000000000057
2025-06-27 05:17:56.969 E + 0.35999999999999943
2025-06-27 05:17:56.977 E + 0.360000000000003
2025-06-27 05:17:56.984 E + 0.33999999999999986
2025-06-27 05:17:56.996 E + 0.3500000000000014
2025-06-27 05:17:57.005 E + 0.33999999999999986
2025-06-27 05:17:57.016 E + 0.36000000000000654
2025-06-27 05:17:57.025 E + 0.3500000000000014
2025-06-27 05:17:57.032 E + 0.38000000000000256
2025-06-27 05:17:57.040 E + 0.35999999999999943
2025-06-27 05:17:57.048 E + 0.39000000000000057
2025-06-27 05:17:57.056 E + sp_name='udr_call':
2025-06-27 05:17:57.062 E + 1.68
2025-06-27 05:17:57.072 E + 1.63
2025-06-27 05:17:57.081 E + 1.6000000000000005
2025-06-27 05:17:57.093 E + 1.6099999999999994
2025-06-27 05:17:57.105 E + 1.6799999999999997
2025-06-27 05:17:57.117 E + 1.6600000000000001
2025-06-27 05:17:57.128 E + 1.6300000000000008
2025-06-27 05:17:57.138 E + 1.6799999999999997
2025-06-27 05:17:57.147 E + 1.8000000000000007
2025-06-27 05:17:57.155 E + 1.6900000000000013
2025-06-27 05:17:57.161 E + 1.6400000000000006
2025-06-27 05:17:57.168 E + 1.6899999999999977
2025-06-27 05:17:57.173 E + 1.6699999999999982
2025-06-27 05:17:57.179 E + 1.6600000000000001
2025-06-27 05:17:57.184 E + 1.8299999999999983
2025-06-27 05:17:57.191 E + 1.6899999999999977
2025-06-27 05:17:57.198 E + 1.6699999999999946
2025-06-27 05:17:57.205 E + 1.6000000000000014
2025-06-27 05:17:57.213 E + 1.7299999999999969
2025-06-27 05:17:57.221 E + 1.6300000000000026
2025-06-27 05:17:57.227 E + 1.6299999999999955
2025-06-27 05:17:57.233
2025-06-27 05:17:57.239 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-27 05:17:57.245 ---------------------------- Captured stdout setup -----------------------------
2025-06-27 05:17:57.251 Creating db: localhost:/var/tmp/qa_2024/test_11655/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.36
E + 0.3700000000000001
E + 0.33999999999999986
E + 0.3700000000000001
E + 0.33999999999999986
E + 0.3600000000000012
E + 0.3899999999999988
E + 0.35999999999999943
E + 0.46999999999999886
E + 0.33999999999999986
E + 0.39000000000000057
E + 0.35999999999999943
E + 0.360000000000003
E + 0.33999999999999986
E + 0.3500000000000014
E + 0.33999999999999986
E + 0.36000000000000654
E + 0.3500000000000014
E + 0.38000000000000256
E + 0.35999999999999943
E + 0.39000000000000057
E + sp_name='udr_call':
E + 1.68
E + 1.63
E + 1.6000000000000005
E + 1.6099999999999994
E + 1.6799999999999997
E + 1.6600000000000001
E + 1.6300000000000008
E + 1.6799999999999997
E + 1.8000000000000007
E + 1.6900000000000013
E + 1.6400000000000006
E + 1.6899999999999977
E + 1.6699999999999982
E + 1.6600000000000001
E + 1.8299999999999983
E + 1.6899999999999977
E + 1.6699999999999946
E + 1.6000000000000014
E + 1.7299999999999969
E + 1.6300000000000026
E + 1.6299999999999955
tests/bugs/gh_7989_test.py:152: AssertionError
|