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.4545
  + 2.2381
  + 2.2381
  + 2.6842
  + 2.0000
  + 2.4500
  + 2.2381
  + 2.3182
  + 2.4211
  + 2.0417
  + 2.4000
  + Median value:       2.3182 - GREATER than threshold:       0.8000
  + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
  + 2.0769
  + 1.5152
  + 2.1364
  + 2.4286
  + 2.0909
  + 2.3333
  + 2.1364
  + 2.3182
  + 2.0000
  + 2.1818
  + 2.0000
  + Median value:       2.1364 - GREATER than threshold:       0.8000

LOG DETAILS:

2024-06-18 08:14:28.349
2024-06-18 08:14:28.355 act = <firebird.qa.plugin.Action object at [hex]>
2024-06-18 08:14:28.361 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-06-18 08:14:28.367
2024-06-18 08:14:28.373 @pytest.mark.version('>=3.0.3')
2024-06-18 08:14:28.379 def test_1(act: Action, capsys):
2024-06-18 08:14:28.383 time_data = {}
2024-06-18 08:14:28.388 with act.db.connect() as con:
2024-06-18 08:14:28.392 cur=con.cursor()
2024-06-18 08:14:28.397 cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-06-18 08:14:28.402 fb_pid = int(cur.fetchone()[0])
2024-06-18 08:14:28.406
2024-06-18 08:14:28.410 for i in range(0, N_MEASURES):
2024-06-18 08:14:28.415 fb_info_1 = psutil.Process(fb_pid).cpu_times()
2024-06-18 08:14:28.420 con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
2024-06-18 08:14:28.424 fb_info_2 = psutil.Process(fb_pid).cpu_times()
2024-06-18 08:14:28.429 con.commit()
2024-06-18 08:14:28.433 fb_info_3 = psutil.Process(fb_pid).cpu_times()
2024-06-18 08:14:28.438 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 08:14:28.442
2024-06-18 08:14:28.447 con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
2024-06-18 08:14:28.452 fb_info_4 = psutil.Process(fb_pid).cpu_times()
2024-06-18 08:14:28.456 con.commit()
2024-06-18 08:14:28.461 fb_info_5 = psutil.Process(fb_pid).cpu_times()
2024-06-18 08:14:28.466 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 08:14:28.470
2024-06-18 08:14:28.474
2024-06-18 08:14:28.479 del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
2024-06-18 08:14:28.483 add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint'  ]
2024-06-18 08:14:28.488
2024-06-18 08:14:28.492 #for k,v in sorted(time_data.items()):
2024-06-18 08:14:28.497 #    print(k,':::',v)
2024-06-18 08:14:28.501 #print(del_constraint_to_commit_ratios)
2024-06-18 08:14:28.506 #print(add_constraint_to_commit_ratios)
2024-06-18 08:14:28.510
2024-06-18 08:14:28.515 del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
2024-06-18 08:14:28.519 add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
2024-06-18 08:14:28.524
2024-06-18 08:14:28.528 msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
2024-06-18 08:14:28.532 msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
2024-06-18 08:14:28.536
2024-06-18 08:14:28.541 if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
2024-06-18 08:14:28.545 print(msg_del_success)
2024-06-18 08:14:28.549 else:
2024-06-18 08:14:28.554 print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-06-18 08:14:28.558 for p in del_constraint_to_commit_ratios:
2024-06-18 08:14:28.563 print('%12.4f' % p)
2024-06-18 08:14:28.567 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
2024-06-18 08:14:28.572
2024-06-18 08:14:28.576
2024-06-18 08:14:28.581 if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
2024-06-18 08:14:28.585 print(msg_add_success)
2024-06-18 08:14:28.590 else:
2024-06-18 08:14:28.594 print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-06-18 08:14:28.599 for p in add_constraint_to_commit_ratios:
2024-06-18 08:14:28.603 print('%12.4f' % p)
2024-06-18 08:14:28.608 print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
2024-06-18 08:14:28.612
2024-06-18 08:14:28.617 expected_stdout = '''
2024-06-18 08:14:28.622 ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-06-18 08:14:28.626 ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-06-18 08:14:28.631 '''
2024-06-18 08:14:28.636
2024-06-18 08:14:28.640 act.expected_stdout = expected_stdout
2024-06-18 08:14:28.645 act.stdout = capsys.readouterr().out
2024-06-18 08:14:28.649 >       assert act.clean_stdout == act.clean_expected_stdout
2024-06-18 08:14:28.653 E       assert
2024-06-18 08:14:28.658 E         - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-06-18 08:14:28.662 E         - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-06-18 08:14:28.667 E         + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-06-18 08:14:28.671 E         + 2.4545
2024-06-18 08:14:28.676 E         + 2.2381
2024-06-18 08:14:28.680 E         + 2.2381
2024-06-18 08:14:28.685 E         + 2.6842
2024-06-18 08:14:28.689 E         + 2.0000
2024-06-18 08:14:28.694 E         + 2.4500
2024-06-18 08:14:28.698 E         + 2.2381
2024-06-18 08:14:28.702 E         + 2.3182
2024-06-18 08:14:28.707 E         + 2.4211
2024-06-18 08:14:28.711 E         + 2.0417
2024-06-18 08:14:28.716 E         + 2.4000
2024-06-18 08:14:28.720 E         + Median value:       2.3182 - GREATER than threshold:       0.8000
2024-06-18 08:14:28.725 E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-06-18 08:14:28.730 E         + 2.0769
2024-06-18 08:14:28.734 E         + 1.5152
2024-06-18 08:14:28.739 E         + 2.1364
2024-06-18 08:14:28.743 E         + 2.4286
2024-06-18 08:14:28.747 E         + 2.0909
2024-06-18 08:14:28.752 E         + 2.3333
2024-06-18 08:14:28.756 E         + 2.1364
2024-06-18 08:14:28.761 E         + 2.3182
2024-06-18 08:14:28.766 E         + 2.0000
2024-06-18 08:14:28.771 E         + 2.1818
2024-06-18 08:14:28.775 E         + 2.0000
2024-06-18 08:14:28.780 E         + Median value:       2.1364 - GREATER than threshold:       0.8000
2024-06-18 08:14:28.784
2024-06-18 08:14:28.789 tests/bugs/core_5602_test.py:115: AssertionError
2024-06-18 08:14:28.793 ---------------------------- Captured stdout setup -----------------------------
2024-06-18 08:14:28.798 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.4545
E         + 2.2381
E         + 2.2381
E         + 2.6842
E         + 2.0000
E         + 2.4500
E         + 2.2381
E         + 2.3182
E         + 2.4211
E         + 2.0417
E         + 2.4000
E         + Median value:       2.3182 - GREATER than threshold:       0.8000
E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E         + 2.0769
E         + 1.5152
E         + 2.1364
E         + 2.4286
E         + 2.0909
E         + 2.3333
E         + 2.1364
E         + 2.3182
E         + 2.0000
E         + 2.1818
E         + 2.0000
E         + Median value:       2.1364 - 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 10909 9622 2025.06.28 09:30:19.382 2025.06.28 09:30:30.291 2025.06.28 08:42:41.428 2025.06.28 08:42:51.050
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):