2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 5.02857, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.38000000000010914
+ 0.36999999999989086
+ 0.36000000000012733
+ 0.33999999999969077
+ 0.3400000000001455
+ 0.34999999999990905
+ 0.34999999999990905
+ 0.3400000000001455
+ 0.34999999999990905
+ 0.3400000000001455
+ 0.3400000000001455
+ 0.34999999999990905
+ 0.34999999999990905
+ 0.33999999999969077
+ 0.34999999999990905
+ 0.3400000000001455
+ 0.36000000000012733
+ 0.3400000000001455
+ 0.34999999999990905
+ 0.36999999999989086
+ 0.3499999999994543
+ sp_name='udr_call':
+ 1.849999999999909
+ 1.7600000000002183
+ 1.8699999999998909
+ 1.7400000000002365
+ 1.7300000000000182
+ 1.7399999999997817
+ 1.7100000000000364
+ 1.7200000000002547
+ 1.8099999999999454
+ 1.7199999999998
+ 1.7999999999997272
+ 1.8700000000003456
+ 1.7100000000000364
+ 1.7800000000002
+ 1.6900000000000546
+ 1.699999999999818
+ 1.7199999999998
+ 1.8699999999998909
+ 1.8400000000001455
+ 1.8200000000006185
+ 1.7600000000002183
LOG DETAILS:
2025-06-16 02:46:59.849
2025-06-16 02:46:59.854 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-16 02:46:59.858 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-16 02:46:59.863
2025-06-16 02:46:59.868 @pytest.mark.version('>=6.0')
2025-06-16 02:46:59.873 def test_1(act: Action, capsys):
2025-06-16 02:46:59.877
2025-06-16 02:46:59.882 with act.db.connect() as con:
2025-06-16 02:46:59.886 cur=con.cursor()
2025-06-16 02:46:59.891 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-16 02:46:59.895 fb_pid = int(cur.fetchone()[0])
2025-06-16 02:46:59.900
2025-06-16 02:46:59.904 times_map = {}
2025-06-16 02:46:59.908 for i in range(0, N_MEASURES):
2025-06-16 02:46:59.913 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-16 02:46:59.917 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-16 02:46:59.922 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-16 02:46:59.927 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-16 02:46:59.931
2025-06-16 02:46:59.936 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-16 02:46:59.941 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-16 02:46:59.945 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-16 02:46:59.950 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-16 02:46:59.954
2025-06-16 02:46:59.959
2025-06-16 02:46:59.964 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-16 02:46:59.968 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-16 02:46:59.973
2025-06-16 02:46:59.977 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-16 02:46:59.982
2025-06-16 02:46:59.986 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-16 02:46:59.991 if median_ratio > MAX_RATIO:
2025-06-16 02:46:59.996 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-16 02:47:00.000 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-16 02:47:00.005 print(f'{sp_name=}:')
2025-06-16 02:47:00.010 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-16 02:47:00.015 print(p)
2025-06-16 02:47:00.020
2025-06-16 02:47:00.025 act.expected_stdout = expected_stdout
2025-06-16 02:47:00.030 act.stdout = capsys.readouterr().out
2025-06-16 02:47:00.035 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-16 02:47:00.041 E AssertionError: assert
2025-06-16 02:47:00.046 E - Medians ratio: acceptable
2025-06-16 02:47:00.052 E + Medians ratio: /* perf_issue_tag */ POOR: 5.02857, more than threshold: 0.4
2025-06-16 02:47:00.057 E + CPU times for each of 21 measures:
2025-06-16 02:47:00.063 E + sp_name='hash_eval':
2025-06-16 02:47:00.069 E + 0.38000000000010914
2025-06-16 02:47:00.074 E + 0.36999999999989086
2025-06-16 02:47:00.079 E + 0.36000000000012733
2025-06-16 02:47:00.084 E + 0.33999999999969077
2025-06-16 02:47:00.089 E + 0.3400000000001455
2025-06-16 02:47:00.093 E + 0.34999999999990905
2025-06-16 02:47:00.098 E + 0.34999999999990905
2025-06-16 02:47:00.103 E + 0.3400000000001455
2025-06-16 02:47:00.108 E + 0.34999999999990905
2025-06-16 02:47:00.112 E + 0.3400000000001455
2025-06-16 02:47:00.117 E + 0.3400000000001455
2025-06-16 02:47:00.122 E + 0.34999999999990905
2025-06-16 02:47:00.127 E + 0.34999999999990905
2025-06-16 02:47:00.131 E + 0.33999999999969077
2025-06-16 02:47:00.135 E + 0.34999999999990905
2025-06-16 02:47:00.140 E + 0.3400000000001455
2025-06-16 02:47:00.144 E + 0.36000000000012733
2025-06-16 02:47:00.149 E + 0.3400000000001455
2025-06-16 02:47:00.153 E + 0.34999999999990905
2025-06-16 02:47:00.157 E + 0.36999999999989086
2025-06-16 02:47:00.162 E + 0.3499999999994543
2025-06-16 02:47:00.167 E + sp_name='udr_call':
2025-06-16 02:47:00.171 E + 1.849999999999909
2025-06-16 02:47:00.176 E + 1.7600000000002183
2025-06-16 02:47:00.181 E + 1.8699999999998909
2025-06-16 02:47:00.186 E + 1.7400000000002365
2025-06-16 02:47:00.190 E + 1.7300000000000182
2025-06-16 02:47:00.194 E + 1.7399999999997817
2025-06-16 02:47:00.200 E + 1.7100000000000364
2025-06-16 02:47:00.204 E + 1.7200000000002547
2025-06-16 02:47:00.209 E + 1.8099999999999454
2025-06-16 02:47:00.213 E + 1.7199999999998
2025-06-16 02:47:00.218 E + 1.7999999999997272
2025-06-16 02:47:00.222 E + 1.8700000000003456
2025-06-16 02:47:00.228 E + 1.7100000000000364
2025-06-16 02:47:00.234 E + 1.7800000000002
2025-06-16 02:47:00.240 E + 1.6900000000000546
2025-06-16 02:47:00.245 E + 1.699999999999818
2025-06-16 02:47:00.250 E + 1.7199999999998
2025-06-16 02:47:00.255 E + 1.8699999999998909
2025-06-16 02:47:00.259 E + 1.8400000000001455
2025-06-16 02:47:00.264 E + 1.8200000000006185
2025-06-16 02:47:00.268 E + 1.7600000000002183
2025-06-16 02:47:00.273
2025-06-16 02:47:00.278 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-16 02:47:00.282 ---------------------------- Captured stdout setup -----------------------------
2025-06-16 02:47:00.288 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: 5.02857, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.38000000000010914
E + 0.36999999999989086
E + 0.36000000000012733
E + 0.33999999999969077
E + 0.3400000000001455
E + 0.34999999999990905
E + 0.34999999999990905
E + 0.3400000000001455
E + 0.34999999999990905
E + 0.3400000000001455
E + 0.3400000000001455
E + 0.34999999999990905
E + 0.34999999999990905
E + 0.33999999999969077
E + 0.34999999999990905
E + 0.3400000000001455
E + 0.36000000000012733
E + 0.3400000000001455
E + 0.34999999999990905
E + 0.36999999999989086
E + 0.3499999999994543
E + sp_name='udr_call':
E + 1.849999999999909
E + 1.7600000000002183
E + 1.8699999999998909
E + 1.7400000000002365
E + 1.7300000000000182
E + 1.7399999999997817
E + 1.7100000000000364
E + 1.7200000000002547
E + 1.8099999999999454
E + 1.7199999999998
E + 1.7999999999997272
E + 1.8700000000003456
E + 1.7100000000000364
E + 1.7800000000002
E + 1.6900000000000546
E + 1.699999999999818
E + 1.7199999999998
E + 1.8699999999998909
E + 1.8400000000001455
E + 1.8200000000006185
E + 1.7600000000002183
tests/bugs/gh_7989_test.py:152: AssertionError
|