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

Annotation type Annotation details
1 @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.7500
  + 2.3333
  + 2.3333
  + 2.3333
  + 2.3333
  + 2.6250
  + 2.6250
  + 2.3333
  + 2.3333
  + 2.3333
  + 2.3333
  + Median value:       2.3333 - GREATER than threshold:       0.8000
  + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
  + 2.1000
  + 1.9091
  + 2.1000
  + 2.1000
  + 2.1000
  + 1.9091
  + 1.8182
  + 2.1000
  + 2.1000
  + 2.1000
  + 1.8182
  + Median value:       2.1000 - GREATER than threshold:       0.8000

LOG DETAILS:

2024-05-21 11:13:38.543
2024-05-21 11:13:38.543 act = <firebird.qa.plugin.Action object at [hex]>
2024-05-21 11:13:38.543 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543     @pytest.mark.version('>=3.0.3')
2024-05-21 11:13:38.543     def test_1(act: Action, capsys):
2024-05-21 11:13:38.543         time_data = {}
2024-05-21 11:13:38.543         with act.db.connect() as con:
2024-05-21 11:13:38.543             cur=con.cursor()
2024-05-21 11:13:38.543             cur.execute('select mon$server_pid as p from mon$attachments where mon$attachment_id = current_connection')
2024-05-21 11:13:38.543             fb_pid = int(cur.fetchone()[0])
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543             for i in range(0, N_MEASURES):
2024-05-21 11:13:38.543                 fb_info_1 = psutil.Process(fb_pid).cpu_times()
2024-05-21 11:13:38.543                 con.execute_immediate(f'alter domain bool_emul drop constraint -- {i}')
2024-05-21 11:13:38.543                 fb_info_2 = psutil.Process(fb_pid).cpu_times()
2024-05-21 11:13:38.543                 con.commit()
2024-05-21 11:13:38.543                 fb_info_3 = psutil.Process(fb_pid).cpu_times()
2024-05-21 11:13:38.543                 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-21 11:13:38.543
2024-05-21 11:13:38.543                 con.execute_immediate(f"alter domain bool_emul add check (value in ('t', 'f')) -- {i}")
2024-05-21 11:13:38.543                 fb_info_4 = psutil.Process(fb_pid).cpu_times()
2024-05-21 11:13:38.543                 con.commit()
2024-05-21 11:13:38.543                 fb_info_5 = psutil.Process(fb_pid).cpu_times()
2024-05-21 11:13:38.543                 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-21 11:13:38.543
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         del_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'del_constraint' ]
2024-05-21 11:13:38.543         add_constraint_to_commit_ratios = [ v[0] / v[1] for k,v in time_data.items() if k[0] == 'add_constraint'  ]
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         #for k,v in sorted(time_data.items()):
2024-05-21 11:13:38.543         #    print(k,':::',v)
2024-05-21 11:13:38.543         #print(del_constraint_to_commit_ratios)
2024-05-21 11:13:38.543         #print(add_constraint_to_commit_ratios)
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         del_constr_to_commit_median = median(del_constraint_to_commit_ratios)
2024-05-21 11:13:38.543         add_constr_to_commit_median = median(add_constraint_to_commit_ratios)
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         msg_del_success = 'ALTER DOMAIN DROP CONSTRAINT performed for acceptable time'
2024-05-21 11:13:38.543         msg_add_success = 'ALTER DOMAIN ADD CONSTRAINT performed for acceptable time'
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         if del_constr_to_commit_median < DEL_2_COMMIT_MAX_RATIO:
2024-05-21 11:13:38.543             print(msg_del_success)
2024-05-21 11:13:38.543         else:
2024-05-21 11:13:38.543             print('/* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-05-21 11:13:38.543             for p in del_constraint_to_commit_ratios:
2024-05-21 11:13:38.543                 print('%12.4f' % p)
2024-05-21 11:13:38.543             print('Median value: %12.4f - GREATER than threshold: %12.4f' % (del_constr_to_commit_median,DEL_2_COMMIT_MAX_RATIO))
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         if add_constr_to_commit_median < ADD_2_COMMIT_MAX_RATIO:
2024-05-21 11:13:38.543             print(msg_add_success)
2024-05-21 11:13:38.543         else:
2024-05-21 11:13:38.543             print('ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:')
2024-05-21 11:13:38.543             for p in add_constraint_to_commit_ratios:
2024-05-21 11:13:38.543                 print('%12.4f' % p)
2024-05-21 11:13:38.543             print('Median value: %12.4f - GREATER than threshold: %12.4f' % (add_constr_to_commit_median,ADD_2_COMMIT_MAX_RATIO))
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         expected_stdout = '''
2024-05-21 11:13:38.543             ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-05-21 11:13:38.543             ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-05-21 11:13:38.543         '''
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543         act.expected_stdout = expected_stdout
2024-05-21 11:13:38.543         act.stdout = capsys.readouterr().out
2024-05-21 11:13:38.543 >       assert act.clean_stdout == act.clean_expected_stdout
2024-05-21 11:13:38.543 E       assert
2024-05-21 11:13:38.543 E         - ALTER DOMAIN DROP CONSTRAINT performed for acceptable time
2024-05-21 11:13:38.543 E         - ALTER DOMAIN ADD CONSTRAINT performed for acceptable time
2024-05-21 11:13:38.543 E         + /* perf_issue_tag */ ALTER DOMAIN DROP CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-05-21 11:13:38.543 E         + 2.7500
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.6250
2024-05-21 11:13:38.543 E         + 2.6250
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + 2.3333
2024-05-21 11:13:38.543 E         + Median value:       2.3333 - GREATER than threshold:       0.8000
2024-05-21 11:13:38.543 E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 1.9091
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 1.9091
2024-05-21 11:13:38.543 E         + 1.8182
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 2.1000
2024-05-21 11:13:38.543 E         + 1.8182
2024-05-21 11:13:38.543 E         + Median value:       2.1000 - GREATER than threshold:       0.8000
2024-05-21 11:13:38.543
2024-05-21 11:13:38.543 tests\bugs\core_5602_test.py:115: AssertionError
2024-05-21 11:13:38.543 ---------------------------- Captured stdout setup ----------------------------
2024-05-21 11:13:38.543 Restoring db: R:\temp\qa\fbqa\test_11126\test.fdb from F:\FBQA\qa-repo\backups\core5602.fbk
2 #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.7500
E         + 2.3333
E         + 2.3333
E         + 2.3333
E         + 2.3333
E         + 2.6250
E         + 2.6250
E         + 2.3333
E         + 2.3333
E         + 2.3333
E         + 2.3333
E         + Median value:       2.3333 - GREATER than threshold:       0.8000
E         + ALTER DOMAIN ADD CONSTRAINT perfomed too slow. Ratios of DML to COMMIT time:
E         + 2.1000
E         + 1.9091
E         + 2.1000
E         + 2.1000
E         + 2.1000
E         + 1.9091
E         + 1.8182
E         + 2.1000
E         + 2.1000
E         + 2.1000
E         + 1.8182
E         + Median value:       2.1000 - 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.14 6638e P P 7589 6786 2025.06.29 14:37:55.691 2025.06.29 14:38:03.280 2025.06.29 14:03:04.477 2025.06.29 14:03:11.263
2 3.0.13.33809 2025.05.06 28ad0 P P 7836 6703 2025.05.14 08:19:33.424 2025.05.14 08:19:41.260 2025.05.14 07:43:02.980 2025.05.14 07:43:09.683
3 3.0.13.33808 2025.04.25 28426 P P 7586 6502 2025.05.06 13:30:23.527 2025.05.06 13:30:31.113 2025.05.06 12:55:44.427 2025.05.06 12:55:50.929
4 3.0.13.33803 2025.04.23 307b8 F P 8345 6943 2025.04.25 13:38:56.658 2025.04.25 13:39:05.003 2025.04.25 13:04:10.296 2025.04.25 13:04:17.239
5 3.0.13.33803 2025.03.25 ea22a F P 7582 6257 2025.04.20 08:10:15.499 2025.04.20 08:10:23.081 2025.04.20 07:13:44.218 2025.04.20 07:13:50.475
6 3.0.13.33803 2025.02.25 08ebd P P 7680 6944 2025.03.25 10:25:54.711 2025.03.25 10:26:02.391 2025.03.25 09:28:10.128 2025.03.25 09:28:17.072
7 3.0.13.33796 2025.01.29 0ab85 P P 7624 6574 2025.02.25 12:16:33.751 2025.02.25 12:16:41.375 2025.02.25 11:41:27.219 2025.02.25 11:41:33.793
8 3.0.13.33796 2025.01.14 99b3b P P 7574 6601 2025.01.24 11:21:05.666 2025.01.24 11:21:13.240 2025.01.24 10:46:10.848 2025.01.24 10:46:17.449
9 3.0.13.33795 2024.12.13 fbbd9 F P 7915 6799 2025.01.01 12:32:07.867 2025.01.01 12:32:15.782 2025.01.01 11:56:45.808 2025.01.01 11:56:52.607
10 3.0.13.33795 2024.11.24 b8847 P P 7694 6603 2024.12.11 12:29:52.281 2024.12.11 12:29:59.975 2024.12.11 11:54:41.777 2024.12.11 11:54:48.380
11 3.0.13.33794 2024.10.15 abe09 P P 8037 6698 2024.11.22 12:06:14.933 2024.11.22 12:06:22.970 2024.11.22 11:30:57.489 2024.11.22 11:31:04.187
12 3.0.13.33793 2024.10.14 f831a P P 7703 6629 2024.10.15 12:33:50.290 2024.10.15 12:33:57.993 2024.10.15 11:58:24.365 2024.10.15 11:58:30.994
13 3.0.13.33793 2024.10.04 82ccc F P 7634 6539 2024.10.12 12:32:49.249 2024.10.12 12:32:56.883 2024.10.12 11:57:41.627 2024.10.12 11:57:48.166
14 3.0.13.33792 2024.08.31 d8791 P P 7694 7067 2024.10.03 12:41:07.618 2024.10.03 12:41:15.312 2024.10.03 12:04:57.654 2024.10.03 12:05:04.721
15 3.0.13.33787 2024.08.23 8ee81 P P 7661 6802 2024.09.01 12:51:19.642 2024.09.01 12:51:27.303 2024.09.01 12:12:09.333 2024.09.01 12:12:16.135
16 3.0.13.33787 2024.08.09 df740 F P 7843 6761 2024.08.23 12:47:08.694 2024.08.23 12:47:16.537 2024.08.23 12:08:10.187 2024.08.23 12:08:16.948
17 3.0.12.33746 2024.07.15 11dd4 F F 13255 11553 2024.08.09 12:07:22.228 2024.08.09 12:07:35.483 2024.08.09 11:28:46.356 2024.08.09 11:28:57.909
18 3.0.12.33746 2024.06.11 8a5eb F F 13348 11586 2024.07.15 11:00:42.030 2024.07.15 11:00:55.378 2024.07.15 10:26:52.011 2024.07.15 10:27:03.597
19 3.0.12.33745 2024.05.21 301a7 F F 12329 10329 2024.05.25 07:58:19.348 2024.05.25 07:58:31.677 2024.05.25 07:27:04.671 2024.05.25 07:27:15.000
20 3.0.12.33745 2024.05.09 9cf37 F F 12313 10798 2024.05.21 07:58:40.040 2024.05.21 07:58:52.353 2024.05.21 07:27:19.961 2024.05.21 07:27:30.759
21 3.0.12.33744 2024.04.20 af6b2 F F 12485 10407 2024.05.11 07:55:09.743 2024.05.11 07:55:22.228 2024.05.11 07:24:32.790 2024.05.11 07:24:43.197
22 3.0.12.33740 2024.04.06 c6cdd F F 11579 9985 2024.04.21 02:09:20.638 2024.04.21 02:09:32.217 2024.04.21 01:39:07.193 2024.04.21 01:39:17.178
23 3.0.12.33726 2024.03.29 1fac6 P P 6923 5875 2024.04.05 07:05:02.398 2024.04.05 07:05:09.321 2024.04.05 06:35:21.794 2024.04.05 06:35:27.669
24 3.0.12.33726 2024.03.11 456ca P P 6813 5890 2024.03.29 12:45:55.294 2024.03.29 12:46:02.107 2024.03.29 12:17:39.059 2024.03.29 12:17:44.949

Elapsed time, ms. Chart for last 24 runs:

Last commits information (all timestamps in UTC):