2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.85714, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.34999999999990905
+ 0.32999999999992724
+ 0.3400000000001455
+ 0.36000000000012733
+ 0.3500000000003638
+ 0.3400000000001455
+ 0.34999999999990905
+ 0.33999999999969077
+ 0.36000000000012733
+ 0.34999999999990905
+ 0.34999999999990905
+ 0.36000000000012733
+ 0.3500000000003638
+ 0.3400000000001455
+ 0.36000000000012733
+ 0.3400000000001455
+ 0.34999999999990905
+ 0.34999999999990905
+ 0.33999999999969077
+ 0.3400000000001455
+ 0.33999999999969077
+ sp_name='udr_call':
+ 1.7100000000000364
+ 1.6399999999998727
+ 1.699999999999818
+ 1.699999999999818
+ 1.7399999999997817
+ 1.7199999999998
+ 1.7000000000002728
+ 1.6600000000003092
+ 1.7399999999997817
+ 1.7100000000000364
+ 1.7800000000002
+ 1.669999999999618
+ 1.6499999999996362
+ 1.75
+ 1.6799999999998363
+ 1.6700000000000728
+ 1.7899999999999636
+ 1.7000000000002728
+ 1.6700000000000728
+ 1.7100000000000364
+ 1.680000000000291
LOG DETAILS:
2025-07-03 02:41:17.599
2025-07-03 02:41:17.604 act = <firebird.qa.plugin.Action object at [hex]>
2025-07-03 02:41:17.608 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-07-03 02:41:17.614
2025-07-03 02:41:17.620 @pytest.mark.version('>=6.0')
2025-07-03 02:41:17.626 def test_1(act: Action, capsys):
2025-07-03 02:41:17.632
2025-07-03 02:41:17.644 with act.db.connect() as con:
2025-07-03 02:41:17.655 cur=con.cursor()
2025-07-03 02:41:17.661 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-07-03 02:41:17.667 fb_pid = int(cur.fetchone()[0])
2025-07-03 02:41:17.673
2025-07-03 02:41:17.679 times_map = {}
2025-07-03 02:41:17.685 for i in range(0, N_MEASURES):
2025-07-03 02:41:17.691 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-07-03 02:41:17.697 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-07-03 02:41:17.703 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-07-03 02:41:17.709 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-07-03 02:41:17.715
2025-07-03 02:41:17.721 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-07-03 02:41:17.727 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-07-03 02:41:17.733 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-07-03 02:41:17.739 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-07-03 02:41:17.745
2025-07-03 02:41:17.750
2025-07-03 02:41:17.756 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-07-03 02:41:17.762 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-07-03 02:41:17.768
2025-07-03 02:41:17.774 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-07-03 02:41:17.779
2025-07-03 02:41:17.786 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-07-03 02:41:17.792 if median_ratio > MAX_RATIO:
2025-07-03 02:41:17.798 print(f'CPU times for each of {N_MEASURES} measures:')
2025-07-03 02:41:17.803 for sp_name in ('hash_eval', 'udr_call', ):
2025-07-03 02:41:17.809 print(f'{sp_name=}:')
2025-07-03 02:41:17.815 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-07-03 02:41:17.821 print(p)
2025-07-03 02:41:17.826
2025-07-03 02:41:17.830 act.expected_stdout = expected_stdout
2025-07-03 02:41:17.834 act.stdout = capsys.readouterr().out
2025-07-03 02:41:17.839 > assert act.clean_stdout == act.clean_expected_stdout
2025-07-03 02:41:17.843 E AssertionError: assert
2025-07-03 02:41:17.848 E - Medians ratio: acceptable
2025-07-03 02:41:17.852 E + Medians ratio: /* perf_issue_tag */ POOR: 4.85714, more than threshold: 0.4
2025-07-03 02:41:17.857 E + CPU times for each of 21 measures:
2025-07-03 02:41:17.861 E + sp_name='hash_eval':
2025-07-03 02:41:17.866 E + 0.34999999999990905
2025-07-03 02:41:17.870 E + 0.32999999999992724
2025-07-03 02:41:17.874 E + 0.3400000000001455
2025-07-03 02:41:17.879 E + 0.36000000000012733
2025-07-03 02:41:17.885 E + 0.3500000000003638
2025-07-03 02:41:17.891 E + 0.3400000000001455
2025-07-03 02:41:17.897 E + 0.34999999999990905
2025-07-03 02:41:17.903 E + 0.33999999999969077
2025-07-03 02:41:17.909 E + 0.36000000000012733
2025-07-03 02:41:17.915 E + 0.34999999999990905
2025-07-03 02:41:17.921 E + 0.34999999999990905
2025-07-03 02:41:17.926 E + 0.36000000000012733
2025-07-03 02:41:17.931 E + 0.3500000000003638
2025-07-03 02:41:17.936 E + 0.3400000000001455
2025-07-03 02:41:17.941 E + 0.36000000000012733
2025-07-03 02:41:17.945 E + 0.3400000000001455
2025-07-03 02:41:17.950 E + 0.34999999999990905
2025-07-03 02:41:17.954 E + 0.34999999999990905
2025-07-03 02:41:17.959 E + 0.33999999999969077
2025-07-03 02:41:17.963 E + 0.3400000000001455
2025-07-03 02:41:17.968 E + 0.33999999999969077
2025-07-03 02:41:17.973 E + sp_name='udr_call':
2025-07-03 02:41:17.978 E + 1.7100000000000364
2025-07-03 02:41:17.982 E + 1.6399999999998727
2025-07-03 02:41:17.987 E + 1.699999999999818
2025-07-03 02:41:17.991 E + 1.699999999999818
2025-07-03 02:41:17.996 E + 1.7399999999997817
2025-07-03 02:41:18.001 E + 1.7199999999998
2025-07-03 02:41:18.005 E + 1.7000000000002728
2025-07-03 02:41:18.009 E + 1.6600000000003092
2025-07-03 02:41:18.014 E + 1.7399999999997817
2025-07-03 02:41:18.018 E + 1.7100000000000364
2025-07-03 02:41:18.023 E + 1.7800000000002
2025-07-03 02:41:18.027 E + 1.669999999999618
2025-07-03 02:41:18.032 E + 1.6499999999996362
2025-07-03 02:41:18.036 E + 1.75
2025-07-03 02:41:18.041 E + 1.6799999999998363
2025-07-03 02:41:18.046 E + 1.6700000000000728
2025-07-03 02:41:18.051 E + 1.7899999999999636
2025-07-03 02:41:18.055 E + 1.7000000000002728
2025-07-03 02:41:18.059 E + 1.6700000000000728
2025-07-03 02:41:18.064 E + 1.7100000000000364
2025-07-03 02:41:18.068 E + 1.680000000000291
2025-07-03 02:41:18.073
2025-07-03 02:41:18.077 tests/bugs/gh_7989_test.py:152: AssertionError
2025-07-03 02:41:18.082 ---------------------------- Captured stdout setup -----------------------------
2025-07-03 02:41:18.086 Creating db: localhost:/var/tmp/qa_2024/test_11663/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.85714, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.34999999999990905
E + 0.32999999999992724
E + 0.3400000000001455
E + 0.36000000000012733
E + 0.3500000000003638
E + 0.3400000000001455
E + 0.34999999999990905
E + 0.33999999999969077
E + 0.36000000000012733
E + 0.34999999999990905
E + 0.34999999999990905
E + 0.36000000000012733
E + 0.3500000000003638
E + 0.3400000000001455
E + 0.36000000000012733
E + 0.3400000000001455
E + 0.34999999999990905
E + 0.34999999999990905
E + 0.33999999999969077
E + 0.3400000000001455
E + 0.33999999999969077
E + sp_name='udr_call':
E + 1.7100000000000364
E + 1.6399999999998727
E + 1.699999999999818
E + 1.699999999999818
E + 1.7399999999997817
E + 1.7199999999998
E + 1.7000000000002728
E + 1.6600000000003092
E + 1.7399999999997817
E + 1.7100000000000364
E + 1.7800000000002
E + 1.669999999999618
E + 1.6499999999996362
E + 1.75
E + 1.6799999999998363
E + 1.6700000000000728
E + 1.7899999999999636
E + 1.7000000000002728
E + 1.6700000000000728
E + 1.7100000000000364
E + 1.680000000000291
tests/bugs/gh_7989_test.py:152: AssertionError
|