2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.64865, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.35000000000000003
+ 0.3599999999999999
+ 0.40000000000000036
+ 0.3700000000000001
+ 0.39000000000000057
+ 0.39000000000000057
+ 0.4399999999999995
+ 0.3999999999999986
+ 0.370000000000001
+ 0.35999999999999943
+ 0.36999999999999744
+ 0.38000000000000256
+ 0.35999999999999943
+ 0.379999999999999
+ 0.370000000000001
+ 0.36999999999999744
+ 0.3499999999999943
+ 0.35999999999999943
+ 0.4100000000000037
+ 0.3500000000000014
+ 0.35999999999999943
+ sp_name='udr_call':
+ 1.85
+ 2.1
+ 1.7299999999999995
+ 1.7199999999999998
+ 1.6799999999999997
+ 1.67
+ 1.7100000000000009
+ 1.7300000000000004
+ 1.7100000000000009
+ 1.75
+ 1.7300000000000004
+ 1.6899999999999977
+ 1.7100000000000009
+ 1.7800000000000011
+ 1.6600000000000001
+ 1.6900000000000048
+ 1.730000000000004
+ 1.7199999999999989
+ 1.7099999999999937
+ 1.730000000000004
+ 1.7100000000000009
LOG DETAILS:
2025-06-30 05:40:56.692
2025-06-30 05:40:56.706 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-30 05:40:56.716 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-30 05:40:56.725
2025-06-30 05:40:56.732 @pytest.mark.version('>=6.0')
2025-06-30 05:40:56.740 def test_1(act: Action, capsys):
2025-06-30 05:40:56.745
2025-06-30 05:40:56.751 with act.db.connect() as con:
2025-06-30 05:40:56.756 cur=con.cursor()
2025-06-30 05:40:56.762 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-30 05:40:56.767 fb_pid = int(cur.fetchone()[0])
2025-06-30 05:40:56.773
2025-06-30 05:40:56.778 times_map = {}
2025-06-30 05:40:56.783 for i in range(0, N_MEASURES):
2025-06-30 05:40:56.788 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-30 05:40:56.793 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-30 05:40:56.798 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-30 05:40:56.804 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-30 05:40:56.817
2025-06-30 05:40:56.827 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-30 05:40:56.836 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-30 05:40:56.845 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-30 05:40:56.857 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-30 05:40:56.867
2025-06-30 05:40:56.874
2025-06-30 05:40:56.885 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-30 05:40:56.895 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-30 05:40:56.902
2025-06-30 05:40:56.912 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-30 05:40:56.922
2025-06-30 05:40:56.932 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-30 05:40:56.943 if median_ratio > MAX_RATIO:
2025-06-30 05:40:56.953 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-30 05:40:56.963 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-30 05:40:56.975 print(f'{sp_name=}:')
2025-06-30 05:40:56.985 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-30 05:40:56.996 print(p)
2025-06-30 05:40:57.004
2025-06-30 05:40:57.011 act.expected_stdout = expected_stdout
2025-06-30 05:40:57.017 act.stdout = capsys.readouterr().out
2025-06-30 05:40:57.024 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-30 05:40:57.030 E AssertionError: assert
2025-06-30 05:40:57.035 E - Medians ratio: acceptable
2025-06-30 05:40:57.041 E + Medians ratio: /* perf_issue_tag */ POOR: 4.64865, more than threshold: 0.4
2025-06-30 05:40:57.047 E + CPU times for each of 21 measures:
2025-06-30 05:40:57.052 E + sp_name='hash_eval':
2025-06-30 05:40:57.058 E + 0.35000000000000003
2025-06-30 05:40:57.064 E + 0.3599999999999999
2025-06-30 05:40:57.071 E + 0.40000000000000036
2025-06-30 05:40:57.077 E + 0.3700000000000001
2025-06-30 05:40:57.083 E + 0.39000000000000057
2025-06-30 05:40:57.091 E + 0.39000000000000057
2025-06-30 05:40:57.098 E + 0.4399999999999995
2025-06-30 05:40:57.107 E + 0.3999999999999986
2025-06-30 05:40:57.119 E + 0.370000000000001
2025-06-30 05:40:57.129 E + 0.35999999999999943
2025-06-30 05:40:57.137 E + 0.36999999999999744
2025-06-30 05:40:57.144 E + 0.38000000000000256
2025-06-30 05:40:57.151 E + 0.35999999999999943
2025-06-30 05:40:57.164 E + 0.379999999999999
2025-06-30 05:40:57.173 E + 0.370000000000001
2025-06-30 05:40:57.182 E + 0.36999999999999744
2025-06-30 05:40:57.190 E + 0.3499999999999943
2025-06-30 05:40:57.197 E + 0.35999999999999943
2025-06-30 05:40:57.203 E + 0.4100000000000037
2025-06-30 05:40:57.208 E + 0.3500000000000014
2025-06-30 05:40:57.213 E + 0.35999999999999943
2025-06-30 05:40:57.219 E + sp_name='udr_call':
2025-06-30 05:40:57.226 E + 1.85
2025-06-30 05:40:57.236 E + 2.1
2025-06-30 05:40:57.245 E + 1.7299999999999995
2025-06-30 05:40:57.255 E + 1.7199999999999998
2025-06-30 05:40:57.263 E + 1.6799999999999997
2025-06-30 05:40:57.271 E + 1.67
2025-06-30 05:40:57.280 E + 1.7100000000000009
2025-06-30 05:40:57.288 E + 1.7300000000000004
2025-06-30 05:40:57.295 E + 1.7100000000000009
2025-06-30 05:40:57.302 E + 1.75
2025-06-30 05:40:57.313 E + 1.7300000000000004
2025-06-30 05:40:57.323 E + 1.6899999999999977
2025-06-30 05:40:57.331 E + 1.7100000000000009
2025-06-30 05:40:57.338 E + 1.7800000000000011
2025-06-30 05:40:57.351 E + 1.6600000000000001
2025-06-30 05:40:57.361 E + 1.6900000000000048
2025-06-30 05:40:57.368 E + 1.730000000000004
2025-06-30 05:40:57.375 E + 1.7199999999999989
2025-06-30 05:40:57.384 E + 1.7099999999999937
2025-06-30 05:40:57.395 E + 1.730000000000004
2025-06-30 05:40:57.404 E + 1.7100000000000009
2025-06-30 05:40:57.417
2025-06-30 05:40:57.428 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-30 05:40:57.438 ---------------------------- Captured stdout setup -----------------------------
2025-06-30 05:40:57.451 Creating db: localhost:/var/tmp/qa_2024/test_11662/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.64865, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.35000000000000003
E + 0.3599999999999999
E + 0.40000000000000036
E + 0.3700000000000001
E + 0.39000000000000057
E + 0.39000000000000057
E + 0.4399999999999995
E + 0.3999999999999986
E + 0.370000000000001
E + 0.35999999999999943
E + 0.36999999999999744
E + 0.38000000000000256
E + 0.35999999999999943
E + 0.379999999999999
E + 0.370000000000001
E + 0.36999999999999744
E + 0.3499999999999943
E + 0.35999999999999943
E + 0.4100000000000037
E + 0.3500000000000014
E + 0.35999999999999943
E + sp_name='udr_call':
E + 1.85
E + 2.1
E + 1.7299999999999995
E + 1.7199999999999998
E + 1.6799999999999997
E + 1.67
E + 1.7100000000000009
E + 1.7300000000000004
E + 1.7100000000000009
E + 1.75
E + 1.7300000000000004
E + 1.6899999999999977
E + 1.7100000000000009
E + 1.7800000000000011
E + 1.6600000000000001
E + 1.6900000000000048
E + 1.730000000000004
E + 1.7199999999999989
E + 1.7099999999999937
E + 1.730000000000004
E + 1.7100000000000009
tests/bugs/gh_7989_test.py:152: AssertionError
|