2 @message |
Performance problem
AssertionError: assert
- Medians ratio: acceptable
+ Medians ratio: /* perf_issue_tag */ POOR: 4.82857, more than threshold: 0.4
+ CPU times for each of 21 measures:
+ sp_name='hash_eval':
+ 0.3400000000001455
+ 0.40000000000009095
+ 0.4299999999998363
+ 0.36000000000012733
+ 0.34999999999990905
+ 0.3400000000001455
+ 0.3400000000001455
+ 0.33999999999969077
+ 0.34999999999990905
+ 0.3599999999996726
+ 0.3799999999996544
+ 0.3500000000003638
+ 0.3400000000001455
+ 0.32999999999992724
+ 0.34999999999990905
+ 0.34999999999990905
+ 0.34999999999990905
+ 0.32999999999992724
+ 0.32999999999992724
+ 0.3400000000001455
+ 0.3599999999996726
+ sp_name='udr_call':
+ 1.669999999999618
+ 1.7000000000002728
+ 1.75
+ 1.7599999999997635
+ 1.6900000000000546
+ 1.7100000000000364
+ 1.7100000000000364
+ 1.650000000000091
+ 1.680000000000291
+ 1.7200000000002547
+ 1.6700000000000728
+ 1.7299999999995634
+ 1.6700000000000728
+ 1.6700000000000728
+ 1.6600000000003092
+ 1.699999999999818
+ 1.7200000000002547
+ 1.7699999999999818
+ 1.6900000000000546
+ 1.6900000000000546
+ 1.6700000000000728
LOG DETAILS:
2025-06-25 02:42:55.804
2025-06-25 02:42:55.808 act = <firebird.qa.plugin.Action object at [hex]>
2025-06-25 02:42:55.813 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-06-25 02:42:55.818
2025-06-25 02:42:55.822 @pytest.mark.version('>=6.0')
2025-06-25 02:42:55.826 def test_1(act: Action, capsys):
2025-06-25 02:42:55.831
2025-06-25 02:42:55.836 with act.db.connect() as con:
2025-06-25 02:42:55.840 cur=con.cursor()
2025-06-25 02:42:55.845 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2025-06-25 02:42:55.850 fb_pid = int(cur.fetchone()[0])
2025-06-25 02:42:55.855
2025-06-25 02:42:55.859 times_map = {}
2025-06-25 02:42:55.863 for i in range(0, N_MEASURES):
2025-06-25 02:42:55.868 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-25 02:42:55.872 cur.callproc( 'sp_gen_hash', (N_HASH_EVALUATE_COUNT,) )
2025-06-25 02:42:55.877 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-25 02:42:55.881 times_map[ 'hash_eval', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-25 02:42:55.886
2025-06-25 02:42:55.890 fb_info_init = psutil.Process(fb_pid).cpu_times()
2025-06-25 02:42:55.894 cur.callproc( 'sp_udr_call', (N_UDR_CALLS_COUNT,) )
2025-06-25 02:42:55.899 fb_info_curr = psutil.Process(fb_pid).cpu_times()
2025-06-25 02:42:55.903 times_map[ 'udr_call', i ] = max(fb_info_curr.user - fb_info_init.user, 0.000001)
2025-06-25 02:42:55.908
2025-06-25 02:42:55.912
2025-06-25 02:42:55.917 sp_gen_hash_median = median([v for k,v in times_map.items() if k[0] == 'hash_eval'])
2025-06-25 02:42:55.921 sp_udr_call_median = median([v for k,v in times_map.items() if k[0] == 'udr_call'])
2025-06-25 02:42:55.925
2025-06-25 02:42:55.930 median_ratio = sp_udr_call_median / sp_gen_hash_median
2025-06-25 02:42:55.935
2025-06-25 02:42:55.939 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-25 02:42:55.949 if median_ratio > MAX_RATIO:
2025-06-25 02:42:55.954 print(f'CPU times for each of {N_MEASURES} measures:')
2025-06-25 02:42:55.958 for sp_name in ('hash_eval', 'udr_call', ):
2025-06-25 02:42:55.963 print(f'{sp_name=}:')
2025-06-25 02:42:55.967 for p in [v for k,v in times_map.items() if k[0] == sp_name]:
2025-06-25 02:42:55.972 print(p)
2025-06-25 02:42:55.977
2025-06-25 02:42:55.982 act.expected_stdout = expected_stdout
2025-06-25 02:42:55.986 act.stdout = capsys.readouterr().out
2025-06-25 02:42:55.990 > assert act.clean_stdout == act.clean_expected_stdout
2025-06-25 02:42:55.996 E AssertionError: assert
2025-06-25 02:42:56.000 E - Medians ratio: acceptable
2025-06-25 02:42:56.006 E + Medians ratio: /* perf_issue_tag */ POOR: 4.82857, more than threshold: 0.4
2025-06-25 02:42:56.014 E + CPU times for each of 21 measures:
2025-06-25 02:42:56.018 E + sp_name='hash_eval':
2025-06-25 02:42:56.023 E + 0.3400000000001455
2025-06-25 02:42:56.027 E + 0.40000000000009095
2025-06-25 02:42:56.032 E + 0.4299999999998363
2025-06-25 02:42:56.036 E + 0.36000000000012733
2025-06-25 02:42:56.040 E + 0.34999999999990905
2025-06-25 02:42:56.045 E + 0.3400000000001455
2025-06-25 02:42:56.049 E + 0.3400000000001455
2025-06-25 02:42:56.053 E + 0.33999999999969077
2025-06-25 02:42:56.058 E + 0.34999999999990905
2025-06-25 02:42:56.063 E + 0.3599999999996726
2025-06-25 02:42:56.067 E + 0.3799999999996544
2025-06-25 02:42:56.071 E + 0.3500000000003638
2025-06-25 02:42:56.076 E + 0.3400000000001455
2025-06-25 02:42:56.080 E + 0.32999999999992724
2025-06-25 02:42:56.084 E + 0.34999999999990905
2025-06-25 02:42:56.089 E + 0.34999999999990905
2025-06-25 02:42:56.093 E + 0.34999999999990905
2025-06-25 02:42:56.097 E + 0.32999999999992724
2025-06-25 02:42:56.102 E + 0.32999999999992724
2025-06-25 02:42:56.106 E + 0.3400000000001455
2025-06-25 02:42:56.110 E + 0.3599999999996726
2025-06-25 02:42:56.114 E + sp_name='udr_call':
2025-06-25 02:42:56.119 E + 1.669999999999618
2025-06-25 02:42:56.123 E + 1.7000000000002728
2025-06-25 02:42:56.127 E + 1.75
2025-06-25 02:42:56.131 E + 1.7599999999997635
2025-06-25 02:42:56.136 E + 1.6900000000000546
2025-06-25 02:42:56.141 E + 1.7100000000000364
2025-06-25 02:42:56.145 E + 1.7100000000000364
2025-06-25 02:42:56.149 E + 1.650000000000091
2025-06-25 02:42:56.154 E + 1.680000000000291
2025-06-25 02:42:56.158 E + 1.7200000000002547
2025-06-25 02:42:56.162 E + 1.6700000000000728
2025-06-25 02:42:56.167 E + 1.7299999999995634
2025-06-25 02:42:56.171 E + 1.6700000000000728
2025-06-25 02:42:56.176 E + 1.6700000000000728
2025-06-25 02:42:56.180 E + 1.6600000000003092
2025-06-25 02:42:56.184 E + 1.699999999999818
2025-06-25 02:42:56.189 E + 1.7200000000002547
2025-06-25 02:42:56.193 E + 1.7699999999999818
2025-06-25 02:42:56.198 E + 1.6900000000000546
2025-06-25 02:42:56.202 E + 1.6900000000000546
2025-06-25 02:42:56.206 E + 1.6700000000000728
2025-06-25 02:42:56.211
2025-06-25 02:42:56.215 tests/bugs/gh_7989_test.py:152: AssertionError
2025-06-25 02:42:56.220 ---------------------------- Captured stdout setup -----------------------------
2025-06-25 02:42:56.225 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.82857, more than threshold: 0.4
E + CPU times for each of 21 measures:
E + sp_name='hash_eval':
E + 0.3400000000001455
E + 0.40000000000009095
E + 0.4299999999998363
E + 0.36000000000012733
E + 0.34999999999990905
E + 0.3400000000001455
E + 0.3400000000001455
E + 0.33999999999969077
E + 0.34999999999990905
E + 0.3599999999996726
E + 0.3799999999996544
E + 0.3500000000003638
E + 0.3400000000001455
E + 0.32999999999992724
E + 0.34999999999990905
E + 0.34999999999990905
E + 0.34999999999990905
E + 0.32999999999992724
E + 0.32999999999992724
E + 0.3400000000001455
E + 0.3599999999996726
E + sp_name='udr_call':
E + 1.669999999999618
E + 1.7000000000002728
E + 1.75
E + 1.7599999999997635
E + 1.6900000000000546
E + 1.7100000000000364
E + 1.7100000000000364
E + 1.650000000000091
E + 1.680000000000291
E + 1.7200000000002547
E + 1.6700000000000728
E + 1.7299999999995634
E + 1.6700000000000728
E + 1.6700000000000728
E + 1.6600000000003092
E + 1.699999999999818
E + 1.7200000000002547
E + 1.7699999999999818
E + 1.6900000000000546
E + 1.6900000000000546
E + 1.6700000000000728
tests/bugs/gh_7989_test.py:152: AssertionError
|