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.8235
  + 2.1667
  + 1.8750
  + 2.3500
  + 2.3684
  + 1.9524
  + 2.6111
  + 2.2632
  + 2.1579
  + 2.5500
  + 1.8636
  + Median value:       2.2632 - GREATER than threshold:       0.8000
  + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
  + 2.1905
  + 1.8095
  + 1.9524
  + 1.7273
  + 1.8182
  + 1.5909
  + 1.9048
  + 1.6087
  + 1.4800
  + 1.8696
  + 2.0500
  + Median value:       1.8182 - GREATER than threshold:       0.8000

LOG DETAILS:

2024-06-18 07:21:27.016
2024-06-18 07:21:27.021 act = <firebird.qa.plugin.Action object at [hex]>
2024-06-18 07:21:27.026 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-06-18 07:21:27.030
2024-06-18 07:21:27.035 @pytest.mark.version('>=3.0.3')
2024-06-18 07:21:27.040 def test_1(act: Action, capsys):
2024-06-18 07:21:27.045 time_data = {}
2024-06-18 07:21:27.049 with act.db.connect() as con:
2024-06-18 07:21:27.053 cur=con.cursor()
2024-06-18 07:21:27.058 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-06-18 07:21:27.062 fb_pid = int(cur.fetchone()[0])
2024-06-18 07:21:27.067
2024-06-18 07:21:27.071 for i in range(0, N_MEASURES):
2024-06-18 07:21:27.076 fb_info_1 = psutil.Process(fb_pid).cpu_times()
2024-06-18 07:21:27.081 con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
2024-06-18 07:21:27.085 fb_info_2 = psutil.Process(fb_pid).cpu_times()
2024-06-18 07:21:27.089 con.commit()
2024-06-18 07:21:27.094 fb_info_3 = psutil.Process(fb_pid).cpu_times()
2024-06-18 07:21:27.098 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-06-18 07:21:27.103
2024-06-18 07:21:27.107 con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
2024-06-18 07:21:27.112 fb_info_4 = psutil.Process(fb_pid).cpu_times()
2024-06-18 07:21:27.116 con.commit()
2024-06-18 07:21:27.121 fb_info_5 = psutil.Process(fb_pid).cpu_times()
2024-06-18 07:21:27.125 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-06-18 07:21:27.129
2024-06-18 07:21:27.134
2024-06-18 07:21:27.138 del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
2024-06-18 07:21:27.143 add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint'  ]
2024-06-18 07:21:27.148
2024-06-18 07:21:27.152 #for k,v in sorted(time_data.items()):
2024-06-18 07:21:27.157 #    print(k,':::',v)
2024-06-18 07:21:27.161 #print(del_constraint_to_commit_ratios)
2024-06-18 07:21:27.165 #print(add_constraint_to_commit_ratios)
2024-06-18 07:21:27.170
2024-06-18 07:21:27.174 del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
2024-06-18 07:21:27.179 add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
2024-06-18 07:21:27.184
2024-06-18 07:21:27.188 msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
2024-06-18 07:21:27.193 msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
2024-06-18 07:21:27.197
2024-06-18 07:21:27.201 if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
2024-06-18 07:21:27.206 print(msg_del_success)
2024-06-18 07:21:27.210 else:
2024-06-18 07:21:27.215 print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-06-18 07:21:27.220 for p in del_constraint_to_commit_ratios:
2024-06-18 07:21:27.224 print('%12.4f' % p)
2024-06-18 07:21:27.229 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
2024-06-18 07:21:27.233
2024-06-18 07:21:27.237
2024-06-18 07:21:27.242 if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
2024-06-18 07:21:27.246 print(msg_add_success)
2024-06-18 07:21:27.251 else:
2024-06-18 07:21:27.255 print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-06-18 07:21:27.260 for p in add_constraint_to_commit_ratios:
2024-06-18 07:21:27.264 print('%12.4f' % p)
2024-06-18 07:21:27.268 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
2024-06-18 07:21:27.273
2024-06-18 07:21:27.277 expected_stdout = '''
2024-06-18 07:21:27.281 ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-06-18 07:21:27.286 ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-06-18 07:21:27.290 '''
2024-06-18 07:21:27.294
2024-06-18 07:21:27.299 act.expected_stdout = expected_stdout
2024-06-18 07:21:27.303 act.stdout = capsys.readouterr().out
2024-06-18 07:21:27.308 >       assert act.clean_stdout == act.clean_expected_stdout
2024-06-18 07:21:27.312 E       assert
2024-06-18 07:21:27.317 E         - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-06-18 07:21:27.321 E         - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-06-18 07:21:27.327 E         + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-06-18 07:21:27.332 E         + 2.8235
2024-06-18 07:21:27.336 E         + 2.1667
2024-06-18 07:21:27.341 E         + 1.8750
2024-06-18 07:21:27.345 E         + 2.3500
2024-06-18 07:21:27.349 E         + 2.3684
2024-06-18 07:21:27.354 E         + 1.9524
2024-06-18 07:21:27.358 E         + 2.6111
2024-06-18 07:21:27.362 E         + 2.2632
2024-06-18 07:21:27.366 E         + 2.1579
2024-06-18 07:21:27.371 E         + 2.5500
2024-06-18 07:21:27.375 E         + 1.8636
2024-06-18 07:21:27.380 E         + Median value:       2.2632 - GREATER than threshold:       0.8000
2024-06-18 07:21:27.384 E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-06-18 07:21:27.388 E         + 2.1905
2024-06-18 07:21:27.393 E         + 1.8095
2024-06-18 07:21:27.397 E         + 1.9524
2024-06-18 07:21:27.404 E         + 1.7273
2024-06-18 07:21:27.410 E         + 1.8182
2024-06-18 07:21:27.414 E         + 1.5909
2024-06-18 07:21:27.419 E         + 1.9048
2024-06-18 07:21:27.423 E         + 1.6087
2024-06-18 07:21:27.427 E         + 1.4800
2024-06-18 07:21:27.432 E         + 1.8696
2024-06-18 07:21:27.436 E         + 2.0500
2024-06-18 07:21:27.440 E         + Median value:       1.8182 - GREATER than threshold:       0.8000
2024-06-18 07:21:27.445
2024-06-18 07:21:27.449 tests/bugs/core_5602_test.py:115: AssertionError
2024-06-18 07:21:27.454 ---------------------------- Captured stdout setup -----------------------------
2024-06-18 07:21:27.458 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.8235
E         + 2.1667
E         + 1.8750
E         + 2.3500
E         + 2.3684
E         + 1.9524
E         + 2.6111
E         + 2.2632
E         + 2.1579
E         + 2.5500
E         + 1.8636
E         + Median value:       2.2632 - GREATER than threshold:       0.8000
E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E         + 2.1905
E         + 1.8095
E         + 1.9524
E         + 1.7273
E         + 1.8182
E         + 1.5909
E         + 1.9048
E         + 1.6087
E         + 1.4800
E         + 1.8696
E         + 2.0500
E         + Median value:       1.8182 - 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.33814 2025.06.21 85255 P P 10805 10714 2025.07.01 10:15:23.556 2025.07.01 10:15:34.361 2025.07.01 09:27:31.705 2025.07.01 09:27:42.419
2 3.0.13.33813 2025.06.14 222a9 P P 10730 9530 2025.06.20 03:55:18.658 2025.06.20 03:55:29.388 2025.06.20 03:07:34.869 2025.06.20 03:07:44.399
3 3.0.13.33811 2025.05.07 16491 P P 11000 9973 2025.06.14 10:24:01.334 2025.06.14 10:24:12.334 2025.06.14 09:35:32.839 2025.06.14 09:35:42.812
4 3.0.13.33810 2025.05.06 02b1d P P 13513 12903 2025.05.07 08:51:41.626 2025.05.07 08:51:55.139 2025.05.07 07:56:14.589 2025.05.07 07:56:27.492
5 3.0.13.33809 2025.05.05 4ec6d P P 14452 12718 2025.05.06 08:57:54.099 2025.05.06 08:58:08.551 2025.05.06 08:02:06.381 2025.05.06 08:02:19.099
6 3.0.13.33808 2025.04.18 bf513 P P 22614 11639 2025.05.04 22:51:54.601 2025.05.04 22:52:17.215 2025.05.04 21:42:50.019 2025.05.04 21:43:01.658
7 3.0.13.33807 2025.04.14 73e94 P P 14505 12253 2025.04.18 08:51:07.954 2025.04.18 08:51:22.459 2025.04.18 07:54:39.718 2025.04.18 07:54:51.971
8 3.0.13.33806 2025.03.26 b6cfe P P 11077 11050 2025.04.14 07:43:35.518 2025.04.14 07:43:46.595 2025.04.14 06:52:35.079 2025.04.14 06:52:46.129
9 3.0.13.33805 2025.03.17 98320 P P 11826 10404 2025.03.25 05:08:22.800 2025.03.25 05:08:34.626 2025.03.25 04:18:17.151 2025.03.25 04:18:27.555
10 3.0.13.33804 2025.02.25 1439d P P 1352 862 2025.03.17 05:19:09.458 2025.03.17 05:19:10.810 2025.03.17 04:22:49.182 2025.03.17 04:22:50.044
11 3.0.13.33803 2025.01.29 f1848 P P 1449 789 2025.02.25 07:58:20.093 2025.02.25 07:58:21.542 2025.02.25 07:04:00.675 2025.02.25 07:04:01.464
12 3.0.13.33802 2025.01.28 650bd P P 2289 865 2025.01.29 22:48:36.845 2025.01.29 22:48:39.134 2025.01.29 21:41:34.475 2025.01.29 21:41:35.340
13 3.0.13.33800 2025.01.20 f20ab P P 1456 886 2025.01.28 08:15:14.599 2025.01.28 08:15:16.055 2025.01.28 07:18:24.624 2025.01.28 07:18:25.510
14 3.0.13.33798 2025.01.16 0c3bb P P 1456 851 2025.01.20 07:47:06.002 2025.01.20 07:47:07.458 2025.01.20 06:51:04.440 2025.01.20 06:51:05.291
15 3.0.13.33795 2024.12.23 1bf0b P P 1443 764 2025.01.16 07:43:47.571 2025.01.16 07:43:49.014 2025.01.16 06:49:11.431 2025.01.16 06:49:12.195
16 3.0.13.33794 2024.10.23 e2a6b P P 1087 616 2024.12.23 01:26:47.124 2024.12.23 01:26:48.211 2024.12.23 00:44:43.201 2024.12.23 00:44:43.817
17 3.0.13.33793 2024.09.02 3e627 P P 1344 722 2024.10.23 07:32:47.346 2024.10.23 07:32:48.690 2024.10.23 06:45:28.015 2024.10.23 06:45:28.737
18 3.0.13.33792 2024.08.30 d9f38 P P 2579 2110 2024.09.02 11:04:36.472 2024.09.02 11:04:39.051 2024.09.02 09:27:13.248 2024.09.02 09:27:15.358
19 3.0.13.33791 2024.08.21 c8a36 P P 2563 1710 2024.08.30 10:38:44.891 2024.08.30 10:38:47.454 2024.08.30 09:10:39.950 2024.08.30 09:10:41.660
20 3.0.13.33790 2024.08.20 3bf52 P P 2616 1311 2024.08.21 10:08:02.264 2024.08.21 10:08:04.880 2024.08.21 08:45:39.766 2024.08.21 08:45:41.077
21 3.0.13.33789 2024.08.09 7933a P P 1690 995 2024.08.19 06:24:25.432 2024.08.19 06:24:27.122 2024.08.19 05:27:28.122 2024.08.19 05:27:29.117
22 3.0.12.33787 2024.08.06 bf180 P P 1532 920 2024.08.09 06:11:19.046 2024.08.09 06:11:20.578 2024.08.09 05:14:46.424 2024.08.09 05:14:47.344
23 3.0.12.33784 2024.08.01 cd857 P P 1227 680 2024.08.06 05:09:55.437 2024.08.06 05:09:56.664 2024.08.06 04:22:01.803 2024.08.06 04:22:02.483
24 3.0.12.33779 2024.07.31 ae35d P P 1161 772 2024.08.01 05:08:21.253 2024.08.01 05:08:22.414 2024.08.01 04:20:32.428 2024.08.01 04:20:33.200
25 3.0.12.33778 2024.07.21 4680d P P 1237 601 2024.07.30 05:05:25.155 2024.07.30 05:05:26.392 2024.07.30 04:17:36.174 2024.07.30 04:17:36.775
26 3.0.12.33777 2024.07.19 8e912 P P 1298 713 2024.07.21 05:07:27.818 2024.07.21 05:07:29.116 2024.07.21 04:19:44.437 2024.07.21 04:19:45.150
27 3.0.12.33766 2024.07.13 b5086 P P 1233 715 2024.07.19 04:59:54.832 2024.07.19 04:59:56.065 2024.07.19 04:12:34.177 2024.07.19 04:12:34.892
28 3.0.12.33765 2024.07.10 06f2a P P 1335 731 2024.07.13 05:02:48.196 2024.07.13 05:02:49.531 2024.07.13 04:15:04.497 2024.07.13 04:15:05.228
29 3.0.12.33764 2024.06.18 4d0c0 P P 1352 640 2024.07.10 04:51:44.671 2024.07.10 04:51:46.023 2024.07.10 04:05:38.754 2024.07.10 04:05:39.394
30 3.0.12.33761 2024.06.17 b259d F F 1213 726 2024.06.18 04:53:17.305 2024.06.18 04:53:18.518 2024.06.18 04:06:37.906 2024.06.18 04:06:38.632
31 3.0.12.33758 2024.06.14 4f9bc F F 1204 649 2024.06.17 04:48:48.690 2024.06.17 04:48:49.894 2024.06.17 04:00:46.008 2024.06.17 04:00:46.657
32 3.0.12.33757 2024.06.13 c7a1c F F 1023 593 2024.06.14 05:01:59.425 2024.06.14 05:02:00.448 2024.06.14 04:21:26.140 2024.06.14 04:21:26.733
33 3.0.12.33744 2024.04.19 ecf36 F F 1046 570 2024.05.08 15:42:20.864 2024.05.08 15:42:21.910 2024.05.08 15:01:12.076 2024.05.08 15:01:12.646

Elapsed time, ms. Chart for last 33 runs:

Last commits information (all timestamps in UTC):