2 @message |
Performance problem
assert
- ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
- ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
+ /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
+ 2.8182
+ 2.9130
+ 2.6818
+ 2.7727
+ 2.7143
+ 2.5238
+ 2.8000
+ 2.6190
+ 2.7143
+ 3.0000
+ 2.4091
+ Median value: 2.7143 - GREATER than threshold: 0.8000
+ ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
+ 1.8485
+ 2.4167
+ 1.7419
+ 2.1923
+ 2.3043
+ 2.2400
+ 2.3333
+ 2.0667
+ 2.0769
+ 2.4583
+ 2.2069
+ Median value: 2.2069 - GREATER than threshold: 0.8000
LOG DETAILS:
2024-05-12 19:15:54.786
2024-05-12 19:15:54.793 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-12 19:15:54.799 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-12 19:15:54.804
2024-05-12 19:15:54.809 @pytest.mark.version('>=3.0.3')
2024-05-12 19:15:54.815 def test_1(act: Action, capsys):
2024-05-12 19:15:54.820 time_data = {}
2024-05-12 19:15:54.825 with act.db.connect() as con:
2024-05-12 19:15:54.830 cur=con.cursor()
2024-05-12 19:15:54.835 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-05-12 19:15:54.840 fb_pid = int(cur.fetchone()[0])
2024-05-12 19:15:54.846
2024-05-12 19:15:54.852 for i in range(0, N_MEASURES):
2024-05-12 19:15:54.858 fb_info_1 = psutil.Process(fb_pid).cpu_times()
2024-05-12 19:15:54.865 con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
2024-05-12 19:15:54.871 fb_info_2 = psutil.Process(fb_pid).cpu_times()
2024-05-12 19:15:54.877 con.commit()
2024-05-12 19:15:54.882 fb_info_3 = psutil.Process(fb_pid).cpu_times()
2024-05-12 19:15:54.887 time_data[ 'del_constraint', i ] = ( max(fb_info_2.user - fb_info_1.user, 0.000001), max(fb_info_3.user - fb_info_2.user, 0.000001) )
2024-05-12 19:15:54.892
2024-05-12 19:15:54.897 con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
2024-05-12 19:15:54.902 fb_info_4 = psutil.Process(fb_pid).cpu_times()
2024-05-12 19:15:54.910 con.commit()
2024-05-12 19:15:54.918 fb_info_5 = psutil.Process(fb_pid).cpu_times()
2024-05-12 19:15:54.923 time_data[ 'add_constraint', i ] = ( max(fb_info_4.user - fb_info_3.user, 0.000001), max(fb_info_5.user - fb_info_4.user, 0.000001) )
2024-05-12 19:15:54.930
2024-05-12 19:15:54.937
2024-05-12 19:15:54.943 del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
2024-05-12 19:15:54.949 add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint' ]
2024-05-12 19:15:54.956
2024-05-12 19:15:54.963 #for k,v in sorted(time_data.items()):
2024-05-12 19:15:54.968 # print(k,':::',v)
2024-05-12 19:15:54.973 #print(del_constraint_to_commit_ratios)
2024-05-12 19:15:54.978 #print(add_constraint_to_commit_ratios)
2024-05-12 19:15:54.983
2024-05-12 19:15:54.988 del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
2024-05-12 19:15:54.993 add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
2024-05-12 19:15:54.998
2024-05-12 19:15:55.002 msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
2024-05-12 19:15:55.008 msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
2024-05-12 19:15:55.013
2024-05-12 19:15:55.020 if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
2024-05-12 19:15:55.027 print(msg_del_success)
2024-05-12 19:15:55.033 else:
2024-05-12 19:15:55.040 print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-05-12 19:15:55.046 for p in del_constraint_to_commit_ratios:
2024-05-12 19:15:55.055 print('%12.4f' % p)
2024-05-12 19:15:55.062 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
2024-05-12 19:15:55.068
2024-05-12 19:15:55.075
2024-05-12 19:15:55.081 if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
2024-05-12 19:15:55.089 print(msg_add_success)
2024-05-12 19:15:55.098 else:
2024-05-12 19:15:55.103 print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-05-12 19:15:55.107 for p in add_constraint_to_commit_ratios:
2024-05-12 19:15:55.113 print('%12.4f' % p)
2024-05-12 19:15:55.119 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
2024-05-12 19:15:55.125
2024-05-12 19:15:55.130 expected_stdout = '''
2024-05-12 19:15:55.135 ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-05-12 19:15:55.140 ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-05-12 19:15:55.145 '''
2024-05-12 19:15:55.149
2024-05-12 19:15:55.154 act.expected_stdout = expected_stdout
2024-05-12 19:15:55.159 act.stdout = capsys.readouterr().out
2024-05-12 19:15:55.163 > assert act.clean_stdout == act.clean_expected_stdout
2024-05-12 19:15:55.168 E assert
2024-05-12 19:15:55.173 E - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-05-12 19:15:55.178 E - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-05-12 19:15:55.183 E + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-05-12 19:15:55.190 E + 2.8182
2024-05-12 19:15:55.195 E + 2.9130
2024-05-12 19:15:55.201 E + 2.6818
2024-05-12 19:15:55.206 E + 2.7727
2024-05-12 19:15:55.211 E + 2.7143
2024-05-12 19:15:55.216 E + 2.5238
2024-05-12 19:15:55.221 E + 2.8000
2024-05-12 19:15:55.227 E + 2.6190
2024-05-12 19:15:55.232 E + 2.7143
2024-05-12 19:15:55.236 E + 3.0000
2024-05-12 19:15:55.242 E + 2.4091
2024-05-12 19:15:55.248 E + Median value: 2.7143 - GREATER than threshold: 0.8000
2024-05-12 19:15:55.253 E + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-05-12 19:15:55.259 E + 1.8485
2024-05-12 19:15:55.264 E + 2.4167
2024-05-12 19:15:55.269 E + 1.7419
2024-05-12 19:15:55.275 E + 2.1923
2024-05-12 19:15:55.281 E + 2.3043
2024-05-12 19:15:55.287 E + 2.2400
2024-05-12 19:15:55.292 E + 2.3333
2024-05-12 19:15:55.296 E + 2.0667
2024-05-12 19:15:55.301 E + 2.0769
2024-05-12 19:15:55.306 E + 2.4583
2024-05-12 19:15:55.311 E + 2.2069
2024-05-12 19:15:55.316 E + Median value: 2.2069 - GREATER than threshold: 0.8000
2024-05-12 19:15:55.322
2024-05-12 19:15:55.328 tests/bugs/core_5602_test.py:115: AssertionError
2024-05-12 19:15:55.333 ---------------------------- Captured stdout setup -----------------------------
2024-05-12 19:15:55.344 Restoring db: /var/tmp/qa_2024/test_11114/test.fdb from /opt/distr/venv/firebird-qa/backups/core5602.fbk
|
3 #text |
act = <firebird.qa.plugin.Action pytest object at [hex]>
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>
@pytest.mark.version('>=3.0.3')
def test_1(act: Action, capsys):
time_data = {}
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])
for i in range(0, N_MEASURES):
fb_info_1 = psutil.Process(fb_pid).cpu_times()
con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
fb_info_2 = psutil.Process(fb_pid).cpu_times()
con.commit()
fb_info_3 = psutil.Process(fb_pid).cpu_times()
time_data[ 'del_constraint', i ] = ( max(fb_info_2.user - fb_info_1.user, 0.000001), max(fb_info_3.user - fb_info_2.user, 0.000001) )
con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
fb_info_4 = psutil.Process(fb_pid).cpu_times()
con.commit()
fb_info_5 = psutil.Process(fb_pid).cpu_times()
time_data[ 'add_constraint', i ] = ( max(fb_info_4.user - fb_info_3.user, 0.000001), max(fb_info_5.user - fb_info_4.user, 0.000001) )
del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint' ]
#for k,v in sorted(time_data.items()):
# print(k,':::',v)
#print(del_constraint_to_commit_ratios)
#print(add_constraint_to_commit_ratios)
del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
print(msg_del_success)
else:
print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
for p in del_constraint_to_commit_ratios:
print('%12.4f' % p)
print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
print(msg_add_success)
else:
print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
for p in add_constraint_to_commit_ratios:
print('%12.4f' % p)
print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
expected_stdout = '''
ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
'''
act.expected_stdout = expected_stdout
act.stdout = capsys.readouterr().out
> assert act.clean_stdout == act.clean_expected_stdout
E assert
E - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
E - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
E + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E + 2.8182
E + 2.9130
E + 2.6818
E + 2.7727
E + 2.7143
E + 2.5238
E + 2.8000
E + 2.6190
E + 2.7143
E + 3.0000
E + 2.4091
E + Median value: 2.7143 - GREATER than threshold: 0.8000
E + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E + 1.8485
E + 2.4167
E + 1.7419
E + 2.1923
E + 2.3043
E + 2.2400
E + 2.3333
E + 2.0667
E + 2.0769
E + 2.4583
E + 2.2069
E + Median value: 2.2069 - GREATER than threshold: 0.8000
tests/bugs/core_5602_test.py:115: AssertionError
|