Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
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.6316
  + 2.1053
  + 2.7778
  + 2.3810
  + 2.1429
  + 2.0000
  + 2.9444
  + 2.4444
  + 1.9524
  + 2.4706
  + 2.2222
  + Median value:       2.3810 - GREATER than threshold:       0.8000
  + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
  + 1.7200
  + 1.7727
  + 1.6818
  + 1.7727
  + 1.6786
  + 1.9524
  + 1.9565
  + 1.7619
  + 1.7727
  + 1.7727
  + 1.9091
  + Median value:       1.7727 - GREATER than threshold:       0.8000

LOG DETAILS:

2024-08-09 15:08:47.914
2024-08-09 15:08:47.919 act = <firebird.qa.plugin.Action object at [hex]>
2024-08-09 15:08:47.923 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-08-09 15:08:47.928
2024-08-09 15:08:47.933 @pytest.mark.version('>=3.0.3')
2024-08-09 15:08:47.937 def test_1(act: Action, capsys):
2024-08-09 15:08:47.942 time_data = {}
2024-08-09 15:08:47.946 with act.db.connect() as con:
2024-08-09 15:08:47.951 cur=con.cursor()
2024-08-09 15:08:47.956 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-08-09 15:08:47.960 fb_pid = int(cur.fetchone()[0])
2024-08-09 15:08:47.965
2024-08-09 15:08:47.969 for i in range(0, N_MEASURES):
2024-08-09 15:08:47.974 fb_info_1 = psutil.Process(fb_pid).cpu_times()
2024-08-09 15:08:47.978 con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
2024-08-09 15:08:47.983 fb_info_2 = psutil.Process(fb_pid).cpu_times()
2024-08-09 15:08:47.988 con.commit()
2024-08-09 15:08:47.992 fb_info_3 = psutil.Process(fb_pid).cpu_times()
2024-08-09 15:08:47.997 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-08-09 15:08:48.001
2024-08-09 15:08:48.006 con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
2024-08-09 15:08:48.011 fb_info_4 = psutil.Process(fb_pid).cpu_times()
2024-08-09 15:08:48.016 con.commit()
2024-08-09 15:08:48.023 fb_info_5 = psutil.Process(fb_pid).cpu_times()
2024-08-09 15:08:48.031 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-08-09 15:08:48.036
2024-08-09 15:08:48.043
2024-08-09 15:08:48.048 del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
2024-08-09 15:08:48.055 add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint'  ]
2024-08-09 15:08:48.063
2024-08-09 15:08:48.068 #for k,v in sorted(time_data.items()):
2024-08-09 15:08:48.075 #    print(k,':::',v)
2024-08-09 15:08:48.083 #print(del_constraint_to_commit_ratios)
2024-08-09 15:08:48.088 #print(add_constraint_to_commit_ratios)
2024-08-09 15:08:48.092
2024-08-09 15:08:48.097 del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
2024-08-09 15:08:48.101 add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
2024-08-09 15:08:48.105
2024-08-09 15:08:48.110 msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
2024-08-09 15:08:48.114 msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
2024-08-09 15:08:48.119
2024-08-09 15:08:48.123 if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
2024-08-09 15:08:48.128 print(msg_del_success)
2024-08-09 15:08:48.132 else:
2024-08-09 15:08:48.137 print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-08-09 15:08:48.141 for p in del_constraint_to_commit_ratios:
2024-08-09 15:08:48.145 print('%12.4f' % p)
2024-08-09 15:08:48.150 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
2024-08-09 15:08:48.154
2024-08-09 15:08:48.159
2024-08-09 15:08:48.163 if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
2024-08-09 15:08:48.168 print(msg_add_success)
2024-08-09 15:08:48.172 else:
2024-08-09 15:08:48.176 print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-08-09 15:08:48.181 for p in add_constraint_to_commit_ratios:
2024-08-09 15:08:48.185 print('%12.4f' % p)
2024-08-09 15:08:48.190 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
2024-08-09 15:08:48.194
2024-08-09 15:08:48.198 expected_stdout = '''
2024-08-09 15:08:48.203 ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-08-09 15:08:48.208 ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-08-09 15:08:48.213 '''
2024-08-09 15:08:48.217
2024-08-09 15:08:48.221 act.expected_stdout = expected_stdout
2024-08-09 15:08:48.226 act.stdout = capsys.readouterr().out
2024-08-09 15:08:48.230 >       assert act.clean_stdout == act.clean_expected_stdout
2024-08-09 15:08:48.235 E       assert
2024-08-09 15:08:48.239 E         - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-08-09 15:08:48.244 E         - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-08-09 15:08:48.248 E         + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-08-09 15:08:48.253 E         + 2.6316
2024-08-09 15:08:48.257 E         + 2.1053
2024-08-09 15:08:48.262 E         + 2.7778
2024-08-09 15:08:48.266 E         + 2.3810
2024-08-09 15:08:48.270 E         + 2.1429
2024-08-09 15:08:48.275 E         + 2.0000
2024-08-09 15:08:48.279 E         + 2.9444
2024-08-09 15:08:48.284 E         + 2.4444
2024-08-09 15:08:48.288 E         + 1.9524
2024-08-09 15:08:48.293 E         + 2.4706
2024-08-09 15:08:48.297 E         + 2.2222
2024-08-09 15:08:48.302 E         + Median value:       2.3810 - GREATER than threshold:       0.8000
2024-08-09 15:08:48.307 E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-08-09 15:08:48.312 E         + 1.7200
2024-08-09 15:08:48.316 E         + 1.7727
2024-08-09 15:08:48.321 E         + 1.6818
2024-08-09 15:08:48.325 E         + 1.7727
2024-08-09 15:08:48.330 E         + 1.6786
2024-08-09 15:08:48.334 E         + 1.9524
2024-08-09 15:08:48.339 E         + 1.9565
2024-08-09 15:08:48.343 E         + 1.7619
2024-08-09 15:08:48.348 E         + 1.7727
2024-08-09 15:08:48.352 E         + 1.7727
2024-08-09 15:08:48.357 E         + 1.9091
2024-08-09 15:08:48.361 E         + Median value:       1.7727 - GREATER than threshold:       0.8000
2024-08-09 15:08:48.366
2024-08-09 15:08:48.370 tests/bugs/core_5602_test.py:115: AssertionError
2024-08-09 15:08:48.375 ---------------------------- Captured stdout setup -----------------------------
2024-08-09 15:08:48.379 Restoring db: /var/tmp/qa_2024/test_11115/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.6316
E         + 2.1053
E         + 2.7778
E         + 2.3810
E         + 2.1429
E         + 2.0000
E         + 2.9444
E         + 2.4444
E         + 1.9524
E         + 2.4706
E         + 2.2222
E         + Median value:       2.3810 - GREATER than threshold:       0.8000
E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E         + 1.7200
E         + 1.7727
E         + 1.6818
E         + 1.7727
E         + 1.6786
E         + 1.9524
E         + 1.9565
E         + 1.7619
E         + 1.7727
E         + 1.7727
E         + 1.9091
E         + Median value:       1.7727 - GREATER than threshold:       0.8000

tests/bugs/core_5602_test.py:115: AssertionError
Full history of outcomes and elapsed time, ms:
NN SNAP_INFO CS_outcome SS_outcome CS_run_time SS_run_time CS_run_beg CS_run_end SS_run_beg SS_run_end
1 3.0.13.33809 2025.05.06 28ad0 P P 11681 10485 2025.07.02 15:22:30.695 2025.07.02 15:22:42.376 2025.07.02 14:29:57.991 2025.07.02 14:30:08.476
2 3.0.13.33808 2025.04.25 28426 P P 13480 13699 2025.05.06 13:56:31.072 2025.05.06 13:56:44.552 2025.05.06 12:53:53.012 2025.05.06 12:54:06.711
3 3.0.13.33803 2025.02.25 08ebd P P 13522 12661 2025.04.25 17:11:27.175 2025.04.25 17:11:40.697 2025.04.25 16:09:19.253 2025.04.25 16:09:31.914
4 3.0.13.33796 2025.01.29 0ab85 P P 1765 875 2025.02.25 15:44:18.961 2025.02.25 15:44:20.726 2025.02.25 14:42:06.348 2025.02.25 14:42:07.223
5 3.0.13.33796 2025.01.14 99b3b P P 1827 880 2025.01.28 17:59:03.728 2025.01.28 17:59:05.555 2025.01.28 16:55:01.544 2025.01.28 16:55:02.424
6 3.0.13.33795 2024.11.24 b8847 P P 1860 925 2025.01.13 15:36:12.112 2025.01.13 15:36:13.972 2025.01.13 14:33:16.919 2025.01.13 14:33:17.844
7 3.0.13.33794 2024.10.15 abe09 P P 1374 631 2024.11.23 06:39:57.807 2024.11.23 06:39:59.181 2024.11.23 05:52:42.899 2024.11.23 05:52:43.530
8 3.0.13.33793 2024.10.04 82ccc P P 1681 697 2024.10.14 04:36:28.635 2024.10.14 04:36:30.316 2024.10.14 03:44:28.658 2024.10.14 03:44:29.355
9 3.0.13.33792 2024.08.31 d8791 P P 1723 723 2024.10.03 09:43:45.060 2024.10.03 09:43:46.783 2024.10.03 08:48:06.888 2024.10.03 08:48:07.611
10 3.0.13.33787 2024.08.17 2e0d6 P P 3855 1836 2024.08.25 15:41:54.779 2024.08.25 15:41:58.634 2024.08.25 13:40:25.525 2024.08.25 13:40:27.361
11 3.0.13.33787 2024.08.09 df740 P P 2090 935 2024.08.16 13:00:10.885 2024.08.16 13:00:12.975 2024.08.16 11:57:15.618 2024.08.16 11:57:16.553
12 3.0.12.33746 2024.07.15 11dd4 F F 1809 888 2024.08.09 12:56:04.948 2024.08.09 12:56:06.757 2024.08.09 11:51:47.177 2024.08.09 11:51:48.065
13 3.0.12.33746 2024.06.11 8a5eb F F 1765 759 2024.07.15 10:46:50.309 2024.07.15 10:46:52.074 2024.07.15 09:53:12.291 2024.07.15 09:53:13.050
14 3.0.12.33744 2024.05.09 9cf37 F F 1379 611 2024.05.12 15:53:02.505 2024.05.12 15:53:03.884 2024.05.12 15:04:40.526 2024.05.12 15:04:41.137
15 3.0.12.33744 2024.04.20 af6b2 F F 1405 582 2024.05.08 17:08:22.866 2024.05.08 17:08:24.271 2024.05.08 16:22:12.637 2024.05.08 16:22:13.219

Elapsed time, ms. Chart for last 15 runs:

Last commits information (all timestamps in UTC):