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:
+ 3.0000
+ 1.7391
+ 2.2857
+ 2.5000
+ 2.5263
+ 2.3600
+ 2.4545
+ 2.0435
+ 2.4211
+ 2.4000
+ 2.0455
+ Median value: 2.4000 - GREATER than threshold: 0.8000
+ ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
+ 1.8750
+ 1.4815
+ 1.7826
+ 1.7917
+ 1.7826
+ 1.8333
+ 1.6400
+ 1.7647
+ 1.9615
+ 1.6296
+ 2.1739
+ Median value: 1.7826 - GREATER than threshold: 0.8000
LOG DETAILS:
2024-05-12 18:17:13.604
2024-05-12 18:17:13.609 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-12 18:17:13.614 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-12 18:17:13.618
2024-05-12 18:17:13.623 @pytest.mark.version('>=3.0.3')
2024-05-12 18:17:13.628 def test_1(act: Action, capsys):
2024-05-12 18:17:13.633 time_data = {}
2024-05-12 18:17:13.637 with act.db.connect() as con:
2024-05-12 18:17:13.642 cur=con.cursor()
2024-05-12 18:17:13.647 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-05-12 18:17:13.652 fb_pid = int(cur.fetchone()[0])
2024-05-12 18:17:13.670
2024-05-12 18:17:13.675 for i in range(0, N_MEASURES):
2024-05-12 18:17:13.681 fb_info_1 = psutil.Process(fb_pid).cpu_times()
2024-05-12 18:17:13.686 con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
2024-05-12 18:17:13.692 fb_info_2 = psutil.Process(fb_pid).cpu_times()
2024-05-12 18:17:13.698 con.commit()
2024-05-12 18:17:13.702 fb_info_3 = psutil.Process(fb_pid).cpu_times()
2024-05-12 18:17:13.707 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 18:17:13.712
2024-05-12 18:17:13.718 con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
2024-05-12 18:17:13.722 fb_info_4 = psutil.Process(fb_pid).cpu_times()
2024-05-12 18:17:13.727 con.commit()
2024-05-12 18:17:13.732 fb_info_5 = psutil.Process(fb_pid).cpu_times()
2024-05-12 18:17:13.736 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 18:17:13.741
2024-05-12 18:17:13.746
2024-05-12 18:17:13.751 del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
2024-05-12 18:17:13.756 add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint' ]
2024-05-12 18:17:13.761
2024-05-12 18:17:13.765 #for k,v in sorted(time_data.items()):
2024-05-12 18:17:13.771 # print(k,':::',v)
2024-05-12 18:17:13.775 #print(del_constraint_to_commit_ratios)
2024-05-12 18:17:13.781 #print(add_constraint_to_commit_ratios)
2024-05-12 18:17:13.785
2024-05-12 18:17:13.790 del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
2024-05-12 18:17:13.796 add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
2024-05-12 18:17:13.800
2024-05-12 18:17:13.805 msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
2024-05-12 18:17:13.809 msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
2024-05-12 18:17:13.813
2024-05-12 18:17:13.818 if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
2024-05-12 18:17:13.822 print(msg_del_success)
2024-05-12 18:17:13.827 else:
2024-05-12 18:17:13.832 print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-05-12 18:17:13.838 for p in del_constraint_to_commit_ratios:
2024-05-12 18:17:13.844 print('%12.4f' % p)
2024-05-12 18:17:13.851 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
2024-05-12 18:17:13.857
2024-05-12 18:17:13.862
2024-05-12 18:17:13.869 if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
2024-05-12 18:17:13.875 print(msg_add_success)
2024-05-12 18:17:13.880 else:
2024-05-12 18:17:13.885 print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-05-12 18:17:13.890 for p in add_constraint_to_commit_ratios:
2024-05-12 18:17:13.896 print('%12.4f' % p)
2024-05-12 18:17:13.901 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
2024-05-12 18:17:13.905
2024-05-12 18:17:13.910 expected_stdout = '''
2024-05-12 18:17:13.916 ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-05-12 18:17:13.921 ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-05-12 18:17:13.926 '''
2024-05-12 18:17:13.931
2024-05-12 18:17:13.935 act.expected_stdout = expected_stdout
2024-05-12 18:17:13.940 act.stdout = capsys.readouterr().out
2024-05-12 18:17:13.945 > assert act.clean_stdout == act.clean_expected_stdout
2024-05-12 18:17:13.949 E assert
2024-05-12 18:17:13.954 E - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-05-12 18:17:13.958 E - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-05-12 18:17:13.963 E + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-05-12 18:17:13.967 E + 3.0000
2024-05-12 18:17:13.973 E + 1.7391
2024-05-12 18:17:13.978 E + 2.2857
2024-05-12 18:17:13.982 E + 2.5000
2024-05-12 18:17:13.987 E + 2.5263
2024-05-12 18:17:13.992 E + 2.3600
2024-05-12 18:17:13.997 E + 2.4545
2024-05-12 18:17:14.001 E + 2.0435
2024-05-12 18:17:14.006 E + 2.4211
2024-05-12 18:17:14.010 E + 2.4000
2024-05-12 18:17:14.016 E + 2.0455
2024-05-12 18:17:14.021 E + Median value: 2.4000 - GREATER than threshold: 0.8000
2024-05-12 18:17:14.026 E + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-05-12 18:17:14.031 E + 1.8750
2024-05-12 18:17:14.035 E + 1.4815
2024-05-12 18:17:14.040 E + 1.7826
2024-05-12 18:17:14.044 E + 1.7917
2024-05-12 18:17:14.048 E + 1.7826
2024-05-12 18:17:14.052 E + 1.8333
2024-05-12 18:17:14.056 E + 1.6400
2024-05-12 18:17:14.061 E + 1.7647
2024-05-12 18:17:14.065 E + 1.9615
2024-05-12 18:17:14.069 E + 1.6296
2024-05-12 18:17:14.073 E + 2.1739
2024-05-12 18:17:14.079 E + Median value: 1.7826 - GREATER than threshold: 0.8000
2024-05-12 18:17:14.083
2024-05-12 18:17:14.088 tests/bugs/core_5602_test.py:115: AssertionError
2024-05-12 18:17:14.092 ---------------------------- Captured stdout setup -----------------------------
2024-05-12 18:17:14.097 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 + 3.0000
E + 1.7391
E + 2.2857
E + 2.5000
E + 2.5263
E + 2.3600
E + 2.4545
E + 2.0435
E + 2.4211
E + 2.4000
E + 2.0455
E + Median value: 2.4000 - GREATER than threshold: 0.8000
E + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E + 1.8750
E + 1.4815
E + 1.7826
E + 1.7917
E + 1.7826
E + 1.8333
E + 1.6400
E + 1.7647
E + 1.9615
E + 1.6296
E + 2.1739
E + Median value: 1.7826 - GREATER than threshold: 0.8000
tests/bugs/core_5602_test.py:115: AssertionError
|