2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.56757, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.37
+ 0.3600000000000003
+ 0.40000000000000036
+ 0.3700000000000001
+ 0.379999999999999
+ 0.35999999999999943
+ 0.3600000000000012
+ 0.41000000000000014
+ 0.370000000000001
+ 0.35999999999999943
+ 0.41999999999999815
+ 0.35999999999999943
+ 0.33999999999999986
+ 0.379999999999999
+ 0.360000000000003
+ 0.5
+ 0.37000000000000455
+ 0.37000000000000455
+ 0.37000000000000455
+ 0.37000000000000455
+ 0.37000000000000455
+ sp_name='udr_call':
+ 1.8399999999999999
+ 1.7199999999999998
+ 1.6899999999999995
+ 1.6800000000000006
+ 1.6900000000000013
+ 1.709999999999999
+ 1.7599999999999998
+ 1.6899999999999995
+ 1.7100000000000009
+ 1.6600000000000001
+ 1.6600000000000001
+ 1.6600000000000001
+ 1.6900000000000013
+ 1.629999999999999
+ 1.7699999999999996
+ 1.6999999999999957
+ 1.6599999999999966
+ 1.5999999999999943
+ 1.6999999999999957
+ 1.8799999999999955
+ 1.6799999999999997
LOG DETAILS:
2025-06-12 05:39:16.680
2025-06-12 05:39:16.687 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-12 05:39:16.694 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-12 05:39:16.702
2025-06-12 05:39:16.707 @pytest.mark.version('>=6.0')
2025-06-12 05:39:16.713 def test_1(act: Action, capsys):
2025-06-12 05:39:16.719
2025-06-12 05:39:16.725 with act.db.connect() as con:
2025-06-12 05:39:16.730 cur=con.cursor()
2025-06-12 05:39:16.736 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-12 05:39:16.743 fb_pid = int(cur.fetchone()[0])
2025-06-12 05:39:16.749
2025-06-12 05:39:16.761 times_map = {}
2025-06-12 05:39:16.775 for i in range(0, N_MEASURES):
2025-06-12 05:39:16.789 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-12 05:39:16.800 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-12 05:39:16.815 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-12 05:39:16.828 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-12 05:39:16.840
2025-06-12 05:39:16.852 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-12 05:39:16.867 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-12 05:39:16.875 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-12 05:39:16.883 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-12 05:39:16.891
2025-06-12 05:39:16.901
2025-06-12 05:39:16.910 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-12 05:39:16.918 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-12 05:39:16.929
2025-06-12 05:39:16.939 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-12 05:39:16.947
2025-06-12 05:39:16.955 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-12 05:39:16.967 if median_ratio > MAX_RATIO:
2025-06-12 05:39:16.977 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-12 05:39:16.985 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-12 05:39:16.991 print(f'{sp_name=}:')
2025-06-12 05:39:16.998 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-12 05:39:17.003 print(p)
2025-06-12 05:39:17.011
2025-06-12 05:39:17.023 act.expected_stdout = expected_stdout
2025-06-12 05:39:17.033 act.stdout = capsys.readouterr().out
2025-06-12 05:39:17.045 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-12 05:39:17.058 E AssertionError: assert
2025-06-12 05:39:17.066 E - Medians ratio: acceptable
2025-06-12 05:39:17.074 E + Medians ratio: /* perf_issue_tag */ POOR: 4.56757, more than threshold: 0.4
2025-06-12 05:39:17.081 E + CPU times for each of 21 measures:
2025-06-12 05:39:17.087 E + sp_name='hash_eval':
2025-06-12 05:39:17.094 E + 0.37
2025-06-12 05:39:17.100 E + 0.3600000000000003
2025-06-12 05:39:17.106 E + 0.40000000000000036
2025-06-12 05:39:17.111 E + 0.3700000000000001
2025-06-12 05:39:17.119 E + 0.379999999999999
2025-06-12 05:39:17.131 E + 0.35999999999999943
2025-06-12 05:39:17.140 E + 0.3600000000000012
2025-06-12 05:39:17.148 E + 0.41000000000000014
2025-06-12 05:39:17.160 E + 0.370000000000001
2025-06-12 05:39:17.172 E + 0.35999999999999943
2025-06-12 05:39:17.185 E + 0.41999999999999815
2025-06-12 05:39:17.194 E + 0.35999999999999943
2025-06-12 05:39:17.202 E + 0.33999999999999986
2025-06-12 05:39:17.212 E + 0.379999999999999
2025-06-12 05:39:17.222 E + 0.360000000000003
2025-06-12 05:39:17.230 E + 0.5
2025-06-12 05:39:17.241 E + 0.37000000000000455
2025-06-12 05:39:17.250 E + 0.37000000000000455
2025-06-12 05:39:17.260 E + 0.37000000000000455
2025-06-12 05:39:17.271 E + 0.37000000000000455
2025-06-12 05:39:17.285 E + 0.37000000000000455
2025-06-12 05:39:17.298 E + sp_name='udr_call':
2025-06-12 05:39:17.306 E + 1.8399999999999999
2025-06-12 05:39:17.317 E + 1.7199999999999998
2025-06-12 05:39:17.327 E + 1.6899999999999995
2025-06-12 05:39:17.335 E + 1.6800000000000006
2025-06-12 05:39:17.347 E + 1.6900000000000013
2025-06-12 05:39:17.359 E + 1.709999999999999
2025-06-12 05:39:17.372 E + 1.7599999999999998
2025-06-12 05:39:17.383 E + 1.6899999999999995
2025-06-12 05:39:17.392 E + 1.7100000000000009
2025-06-12 05:39:17.405 E + 1.6600000000000001
2025-06-12 05:39:17.414 E + 1.6600000000000001
2025-06-12 05:39:17.426 E + 1.6600000000000001
2025-06-12 05:39:17.437 E + 1.6900000000000013
2025-06-12 05:39:17.446 E + 1.629999999999999
2025-06-12 05:39:17.457 E + 1.7699999999999996
2025-06-12 05:39:17.467 E + 1.6999999999999957
2025-06-12 05:39:17.475 E + 1.6599999999999966
2025-06-12 05:39:17.482 E + 1.5999999999999943
2025-06-12 05:39:17.492 E + 1.6999999999999957
2025-06-12 05:39:17.501 E + 1.8799999999999955
2025-06-12 05:39:17.508 E + 1.6799999999999997
2025-06-12 05:39:17.514
2025-06-12 05:39:17.526 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-12 05:39:17.534 ---------------------------- Captured stdout setup -----------------------------
2025-06-12 05:39:17.543 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.56757, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.37
E + 0.3600000000000003
E + 0.40000000000000036
E + 0.3700000000000001
E + 0.379999999999999
E + 0.35999999999999943
E + 0.3600000000000012
E + 0.41000000000000014
E + 0.370000000000001
E + 0.35999999999999943
E + 0.41999999999999815
E + 0.35999999999999943
E + 0.33999999999999986
E + 0.379999999999999
E + 0.360000000000003
E + 0.5
E + 0.37000000000000455
E + 0.37000000000000455
E + 0.37000000000000455
E + 0.37000000000000455
E + 0.37000000000000455
E + sp_name='udr_call':
E + 1.8399999999999999
E + 1.7199999999999998
E + 1.6899999999999995
E + 1.6800000000000006
E + 1.6900000000000013
E + 1.709999999999999
E + 1.7599999999999998
E + 1.6899999999999995
E + 1.7100000000000009
E + 1.6600000000000001
E + 1.6600000000000001
E + 1.6600000000000001
E + 1.6900000000000013
E + 1.629999999999999
E + 1.7699999999999996
E + 1.6999999999999957
E + 1.6599999999999966
E + 1.5999999999999943
E + 1.6999999999999957
E + 1.8799999999999955
E + 1.6799999999999997
tests/bugs/gh_7989_test.py:152: AssertionError
|