Check firebird.log [no messages found for interval when this test was running]
Jump to: output_first_mismatch    outcomes_full_history    elapsed_time_chart
Show cross-report outcomes.

Annotation type Annotation details
2 @message
Performance problem

assert   
  - CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: EXPECTED
  + CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: /* perf_issue_tag */ UNEXPECTED less than 6
    CPU time ratio when sending INCOMPRESSABLE BINARY DATA and WireCompression is ON vs OFF: EXPECTED
    CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: EXPECTED
  + compressed_txt= [0.328125, 0.34375, 0.296875, 0.328125, 0.3125, 0.25, 0.28125, 0.390625, 0.359375]  min= 0.25  max= 0.390625
  + compressed_bin= [0.234375, 0.40625, 0.375, 0.375, 0.359375, 0.40625, 0.40625, 0.4375, 0.390625]  min= 0.234375  max= 0.4375
  + non_comprs_txt= [0.09375, 0.0625, 0.078125, 0.078125, 0.03125, 0.046875, 0.09375, 0.0625, 0.0625]  min= 0.03125  max= 0.09375
  + non_comprs_bin= [0.078125, 0.03125, 0.09375, 0.09375, 0.09375, 0.109375, 0.0625, 0.09375, 0.09375]  min= 0.03125  max= 0.109375
  + median(compressed_txt) / median(non_comprs_txt) = 5.25
  + median(compressed_bin) / median(non_comprs_bin) = 4.166666666666667
  + median(non_comprs_txt) / median(non_comprs_bin) = 0.6666666666666666

LOG DETAILS:

2025-05-13 09:58:34.321
2025-05-13 09:58:34.321 act = <firebird.qa.plugin.Action object at [hex]>
2025-05-13 09:58:34.321 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-05-13 09:58:34.321
2025-05-13 09:58:34.321     @pytest.mark.version('>=3.0')
2025-05-13 09:58:34.321     def test_1(act: Action, capsys):
2025-05-13 09:58:34.321
2025-05-13 09:58:34.321         # OPTIONAL CHECK: minimal ratio between CPU user time when WireCompression = false
2025-05-13 09:58:34.321         # and engine sends to client: 1) 'IDEALLY COMPRESSABLE'; 2) 'ABSOLUTELY IMCOMPRESSIBLE' data.
2025-05-13 09:58:34.321         # This can be useful to estimate record-level compression: textual data can be compressed
2025-05-13 09:58:34.321         # very well, so its transfer must take much less time then for GEN_UUID.
2025-05-13 09:58:34.321         # Experiments show that this ratio can be on Windows in the scope 0.3.... 0.8,
2025-05-13 09:58:34.321         # but on Linux it can be 1.0 or even slightly more then 1(!)
2025-05-13 09:58:34.321         # Windows: 0.500; 0.600; 0.571; 0.428; 0.714; 0.667; 0.625; 0.429; 0.571 // 4.0.1
2025-05-13 09:58:34.321         #          0.454; 0.357; 0.357; 0.500; 0.250; 0.385; 0.333; 0.200; 0.500 // 3.0.8
2025-05-13 09:58:34.321         # Linux:   0.684; 1.000; 1.000; 1.067; 0.867; 0.813; 0.800; 0.777; 0.750 // 4.0.1
2025-05-13 09:58:34.322         #          0.928; 1.000; 0.933; 1.000; 1.077; 0.750; 0.938; 0.929; 0.928 // 3.0.8
2025-05-13 09:58:34.322         if act.is_version('<4'):
2025-05-13 09:58:34.322             # 16.09.2022, 4.3.0.8 Classic: Windows -> 1.2
2025-05-13 09:58:34.322             MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF = 1.1 if platform.system() == 'Linux' else 1.5
2025-05-13 09:58:34.322         else:
2025-05-13 09:58:34.322             # 05.03.2023, 5.0.0.970, SS, Linux: 1.1 --> 1.3
2025-05-13 09:58:34.322             # 05.04.2023, 5.0.0.1001, SS, WIndows: 0.95 --> 1.5
2025-05-13 09:58:34.322             MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF = 1.3 if platform.system() == 'Linux' else 1.5
2025-05-13 09:58:34.322
2025-05-13 09:58:34.322         # Register Firebird server (D:\FB\probes\fid-set-dpb-probe-05x.py)
2025-05-13 09:58:34.322         srv_cfg = driver_config.register_server(name = 'test_srv_core_0733', config = '')
2025-05-13 09:58:34.322
2025-05-13 09:58:34.322         #srv_config_key_value_text = \
2025-05-13 09:58:34.322         #f"""
2025-05-13 09:58:34.322         #    [test_srv_core_0733]
2025-05-13 09:58:34.322         #    protocol = inet
2025-05-13 09:58:34.322         #"""
2025-05-13 09:58:34.322         #driver_config.register_server(name = 'test_srv_core_0733', config = srv_config_key_value_text)
2025-05-13 09:58:34.322         #db_cfg_object = driver_config.register_database(name = 'test_db_core_0733')
2025-05-13 09:58:34.323         #db_cfg_object.database.value = str(act.db.db_path)
2025-05-13 09:58:34.323
2025-05-13 09:58:34.323         benchmark_data = defaultdict(list)
2025-05-13 09:58:34.323
2025-05-13 09:58:34.323         for w_compr in (True, False):
2025-05-13 09:58:34.323
2025-05-13 09:58:34.323             db_cfg_name = f'test_db_core_0733__wcompr_{w_compr}'
2025-05-13 09:58:34.323             db_cfg_object = driver_config.register_database(name = db_cfg_name)
2025-05-13 09:58:34.323             db_cfg_object.server.value = srv_cfg.name
2025-05-13 09:58:34.323             # db_cfg_object.protocol.value = None /  XNET /  WNET -- these can not be used in this test!
2025-05-13 09:58:34.323             db_cfg_object.protocol.value = NetProtocol.INET
2025-05-13 09:58:34.323             db_cfg_object.database.value = str(act.db.db_path)
2025-05-13 09:58:34.323             db_cfg_object.config.value = f"""
2025-05-13 09:58:34.323                 WireCrypt = Disabled
2025-05-13 09:58:34.323                 WireCompression = {w_compr}
2025-05-13 09:58:34.323             """
2025-05-13 09:58:34.323             for i in range(0, N_MEASURES):
2025-05-13 09:58:34.323                 with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
2025-05-13 09:58:34.323                     prot_name = db_cfg_object.protocol.value.name if db_cfg_object.protocol.value else 'Embedded'
2025-05-13 09:58:34.323                     assert w_compr == con.info.is_compressed(), f'Protocol: {prot_name} - can not be used to measure wire_compression'
2025-05-13 09:58:34.324
2025-05-13 09:58:34.324                     with con.cursor() as cur:
2025-05-13 09:58:34.324                         cur.execute('select mon$server_pid, mon$remote_protocol as p from mon$attachments where mon$attachment_id = current_connection')
2025-05-13 09:58:34.324                         for r in cur:
2025-05-13 09:58:34.324                             fb_pid, connection_protocol = r
2025-05-13 09:58:34.324                             assert connection_protocol.startswith('TCP'), f'Invalid connection protocol: {connection_protocol}'
2025-05-13 09:58:34.324
2025-05-13 09:58:34.324                         for data_source in ('t_common_text', 't_binary_data'):
2025-05-13 09:58:34.324                             cur.execute('select s from ' + data_source)
2025-05-13 09:58:34.324
2025-05-13 09:58:34.324                             fb_info_a = psutil.Process(fb_pid).cpu_times()
2025-05-13 09:58:34.324                             for r in cur:
2025-05-13 09:58:34.324                                 # *** FULL FETCH ***
2025-05-13 09:58:34.324                                 pass
2025-05-13 09:58:34.324                             fb_info_b = psutil.Process(fb_pid).cpu_times()
2025-05-13 09:58:34.324
2025-05-13 09:58:34.324                             k = ('WireCompression=%d' % (1 if w_compr else 0), 'DataSource='+data_source)
2025-05-13 09:58:34.324                             benchmark_data[k] += fb_info_b.user - fb_info_a.user,
2025-05-13 09:58:34.324
2025-05-13 09:58:34.324
2025-05-13 09:58:34.325         compressed_txt = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=1' and k[1] == 'DataSource=t_common_text'][0]
2025-05-13 09:58:34.325         compressed_bin = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=1' and k[1] == 'DataSource=t_binary_data'][0]
2025-05-13 09:58:34.325         non_comprs_txt = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=0' and k[1] == 'DataSource=t_common_text'][0]
2025-05-13 09:58:34.325         non_comprs_bin = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=0' and k[1] == 'DataSource=t_binary_data'][0]
2025-05-13 09:58:34.325
2025-05-13 09:58:34.325         cpu_txt_wcompr_ON_vs_OFF = median(compressed_txt) / max(0.00001, median(non_comprs_txt))
2025-05-13 09:58:34.325         cpu_bin_wcompr_ON_vs_OFF = median(compressed_bin) / max(0.00001, median(non_comprs_bin))
2025-05-13 09:58:34.325         cpu_txt2bin_wcompr_OFF = median(non_comprs_txt) / max(0.00001, median(non_comprs_bin))
2025-05-13 09:58:34.325
2025-05-13 09:58:34.325         msg_result1 = 'CPU time ratio when sending %s and WireCompression is ON vs OFF: %s'
2025-05-13 09:58:34.325         what_sent1 = 'COMPRESSABLE TEXTUAL DATA'
2025-05-13 09:58:34.325         all_fine = 1
2025-05-13 09:58:34.325         if cpu_txt_wcompr_ON_vs_OFF > MIN_CPU_RATIO_TXT_WCOMPR_ON_OFF:
2025-05-13 09:58:34.325             print(msg_result1 % (what_sent1, 'EXPECTED') )
2025-05-13 09:58:34.325         else:
2025-05-13 09:58:34.325             print(msg_result1 % (what_sent1, '/* perf_issue_tag */ UNEXPECTED less than '+str(MIN_CPU_RATIO_TXT_WCOMPR_ON_OFF)) )
2025-05-13 09:58:34.325             all_fine = 0
2025-05-13 09:58:34.325
2025-05-13 09:58:34.325
2025-05-13 09:58:34.326         what_sent2 = 'INCOMPRESSABLE BINARY DATA'
2025-05-13 09:58:34.326         if cpu_bin_wcompr_ON_vs_OFF > MIN_CPU_RATIO_BIN_WCOMPR_ON_OFF:
2025-05-13 09:58:34.326             print(msg_result1 % (what_sent2, 'EXPECTED') )
2025-05-13 09:58:34.326         else:
2025-05-13 09:58:34.326             print(msg_result1 % (what_sent2, '/* perf_issue_tag */ UNEXPECTED, less than '+str(MIN_CPU_RATIO_BIN_WCOMPR_ON_OFF)) )
2025-05-13 09:58:34.326             all_fine = 0
2025-05-13 09:58:34.326
2025-05-13 09:58:34.326
2025-05-13 09:58:34.326         msg_result2 = 'CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: %s'
2025-05-13 09:58:34.326         if cpu_txt2bin_wcompr_OFF <= MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF:
2025-05-13 09:58:34.326             print(msg_result2 % ('EXPECTED') )
2025-05-13 09:58:34.326         else:
2025-05-13 09:58:34.326             print(msg_result2 % ('/* perf_issue_tag */ UNEXPECTED, more than ' + str(MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF)) )
2025-05-13 09:58:34.326             all_fine = 0
2025-05-13 09:58:34.326
2025-05-13 09:58:34.326         if not all_fine:
2025-05-13 09:58:34.326             print('compressed_txt=',compressed_txt,' min=',min(compressed_txt),' max=',max(compressed_txt))
2025-05-13 09:58:34.326             print('compressed_bin=',compressed_bin,' min=',min(compressed_bin),' max=',max(compressed_bin))
2025-05-13 09:58:34.326             print('non_comprs_txt=',non_comprs_txt,' min=',min(non_comprs_txt),' max=',max(non_comprs_txt))
2025-05-13 09:58:34.326             print('non_comprs_bin=',non_comprs_bin,' min=',min(non_comprs_bin),' max=',max(non_comprs_bin))
2025-05-13 09:58:34.327
2025-05-13 09:58:34.327             print('median(compressed_txt) / median(non_comprs_txt) =',1.000 * median(compressed_txt) / max(0.00001, median(non_comprs_txt)) )
2025-05-13 09:58:34.327             print('median(compressed_bin) / median(non_comprs_bin) =',1.000 * median(compressed_bin) / max(0.00001, median(non_comprs_bin)) )
2025-05-13 09:58:34.327             print('median(non_comprs_txt) / median(non_comprs_bin) =',1.000 * median(non_comprs_txt) / max(0.00001, median(non_comprs_bin)) )
2025-05-13 09:58:34.327
2025-05-13 09:58:34.327
2025-05-13 09:58:34.327         expected_stdout = ''
2025-05-13 09:58:34.327         for f in (what_sent1, what_sent2):
2025-05-13 09:58:34.327             expected_stdout += ''.join( (msg_result1 % (f, 'EXPECTED'), '\n')  )
2025-05-13 09:58:34.327         expected_stdout += (msg_result2 % 'EXPECTED')
2025-05-13 09:58:34.327
2025-05-13 09:58:34.327         act.expected_stdout = expected_stdout
2025-05-13 09:58:34.327         act.stdout = capsys.readouterr().out
2025-05-13 09:58:34.327 >       assert act.clean_stdout == act.clean_expected_stdout
2025-05-13 09:58:34.327 E       assert
2025-05-13 09:58:34.327 E         - CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: EXPECTED
2025-05-13 09:58:34.327 E         + CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: /* perf_issue_tag */ UNEXPECTED less than 6
2025-05-13 09:58:34.328 E           CPU time ratio when sending INCOMPRESSABLE BINARY DATA and WireCompression is ON vs OFF: EXPECTED
2025-05-13 09:58:34.328 E           CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: EXPECTED
2025-05-13 09:58:34.328 E         + compressed_txt= [0.328125, 0.34375, 0.296875, 0.328125, 0.3125, 0.25, 0.28125, 0.390625, 0.359375]  min= 0.25  max= 0.390625
2025-05-13 09:58:34.328 E         + compressed_bin= [0.234375, 0.40625, 0.375, 0.375, 0.359375, 0.40625, 0.40625, 0.4375, 0.390625]  min= 0.234375  max= 0.4375
2025-05-13 09:58:34.328 E         + non_comprs_txt= [0.09375, 0.0625, 0.078125, 0.078125, 0.03125, 0.046875, 0.09375, 0.0625, 0.0625]  min= 0.03125  max= 0.09375
2025-05-13 09:58:34.328 E         + non_comprs_bin= [0.078125, 0.03125, 0.09375, 0.09375, 0.09375, 0.109375, 0.0625, 0.09375, 0.09375]  min= 0.03125  max= 0.109375
2025-05-13 09:58:34.328 E         + median(compressed_txt) / median(non_comprs_txt) = 5.25
2025-05-13 09:58:34.328 E         + median(compressed_bin) / median(non_comprs_bin) = 4.166666666666667
2025-05-13 09:58:34.328 E         + median(non_comprs_txt) / median(non_comprs_bin) = 0.6666666666666666
2025-05-13 09:58:34.328
2025-05-13 09:58:34.328 tests\bugs\core_0733_test.py:254: AssertionError
2025-05-13 09:58:34.328 ---------------------------- Captured stdout setup ----------------------------
2025-05-13 09:58:34.328 Creating db: localhost:H:\QA\temp\qa2024.tmp\fbqa\test_173\test.fdb [page_size=None, sql_dialect=None, charset='NONE', user=SYSDBA, password=masterkey]
3 #text
act = <firebird.qa.plugin.Action pytest object at [hex]>
capsys = <_pytest.capture.CaptureFixture pytest object at [hex]>

    @pytest.mark.version('>=3.0')
    def test_1(act: Action, capsys):
    
        # OPTIONAL CHECK: minimal ratio between CPU user time when WireCompression = false
        # and engine sends to client: 1) 'IDEALLY COMPRESSABLE'; 2) 'ABSOLUTELY IMCOMPRESSIBLE' data.
        # This can be useful to estimate record-level compression: textual data can be compressed
        # very well, so its transfer must take much less time then for GEN_UUID.
        # Experiments show that this ratio can be on Windows in the scope 0.3.... 0.8,
        # but on Linux it can be 1.0 or even slightly more then 1(!)
        # Windows: 0.500; 0.600; 0.571; 0.428; 0.714; 0.667; 0.625; 0.429; 0.571 // 4.0.1
        #          0.454; 0.357; 0.357; 0.500; 0.250; 0.385; 0.333; 0.200; 0.500 // 3.0.8
        # Linux:   0.684; 1.000; 1.000; 1.067; 0.867; 0.813; 0.800; 0.777; 0.750 // 4.0.1
        #          0.928; 1.000; 0.933; 1.000; 1.077; 0.750; 0.938; 0.929; 0.928 // 3.0.8
        if act.is_version('<4'):
            # 16.09.2022, 4.3.0.8 Classic: Windows -> 1.2
            MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF = 1.1 if platform.system() == 'Linux' else 1.5
        else:
            # 05.03.2023, 5.0.0.970, SS, Linux: 1.1 --> 1.3
            # 05.04.2023, 5.0.0.1001, SS, WIndows: 0.95 --> 1.5
            MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF = 1.3 if platform.system() == 'Linux' else 1.5
    
        # Register Firebird server (D:\FB\probes\fid-set-dpb-probe-05x.py)
        srv_cfg = driver_config.register_server(name = 'test_srv_core_0733', config = '')
    
        #srv_config_key_value_text = \
        #f"""
        #    [test_srv_core_0733]
        #    protocol = inet
        #"""
        #driver_config.register_server(name = 'test_srv_core_0733', config = srv_config_key_value_text)
        #db_cfg_object = driver_config.register_database(name = 'test_db_core_0733')
        #db_cfg_object.database.value = str(act.db.db_path)
    
        benchmark_data = defaultdict(list)
    
        for w_compr in (True, False):
    
            db_cfg_name = f'test_db_core_0733__wcompr_{w_compr}'
            db_cfg_object = driver_config.register_database(name = db_cfg_name)
            db_cfg_object.server.value = srv_cfg.name
            # db_cfg_object.protocol.value = None /  XNET /  WNET -- these can not be used in this test!
            db_cfg_object.protocol.value = NetProtocol.INET
            db_cfg_object.database.value = str(act.db.db_path)
            db_cfg_object.config.value = f"""
                WireCrypt = Disabled
                WireCompression = {w_compr}
            """
            for i in range(0, N_MEASURES):
                with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
                    prot_name = db_cfg_object.protocol.value.name if db_cfg_object.protocol.value else 'Embedded'
                    assert w_compr == con.info.is_compressed(), f'Protocol: {prot_name} - can not be used to measure wire_compression'
    
                    with con.cursor() as cur:
                        cur.execute('select mon$server_pid, mon$remote_protocol as p from mon$attachments where mon$attachment_id = current_connection')
                        for r in cur:
                            fb_pid, connection_protocol = r
                            assert connection_protocol.startswith('TCP'), f'Invalid connection protocol: {connection_protocol}'
    
                        for data_source in ('t_common_text', 't_binary_data'):
                            cur.execute('select s from ' + data_source)
    
                            fb_info_a = psutil.Process(fb_pid).cpu_times()
                            for r in cur:
                                # *** FULL FETCH ***
                                pass
                            fb_info_b = psutil.Process(fb_pid).cpu_times()
    
                            k = ('WireCompression=%d' % (1 if w_compr else 0), 'DataSource='+data_source)
                            benchmark_data[k] += fb_info_b.user - fb_info_a.user,
    
    
        compressed_txt = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=1' and k[1] == 'DataSource=t_common_text'][0]
        compressed_bin = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=1' and k[1] == 'DataSource=t_binary_data'][0]
        non_comprs_txt = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=0' and k[1] == 'DataSource=t_common_text'][0]
        non_comprs_bin = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=0' and k[1] == 'DataSource=t_binary_data'][0]
    
        cpu_txt_wcompr_ON_vs_OFF = median(compressed_txt) / max(0.00001, median(non_comprs_txt))
        cpu_bin_wcompr_ON_vs_OFF = median(compressed_bin) / max(0.00001, median(non_comprs_bin))
        cpu_txt2bin_wcompr_OFF = median(non_comprs_txt) / max(0.00001, median(non_comprs_bin))
    
        msg_result1 = 'CPU time ratio when sending %s and WireCompression is ON vs OFF: %s'
        what_sent1 = 'COMPRESSABLE TEXTUAL DATA'
        all_fine = 1
        if cpu_txt_wcompr_ON_vs_OFF > MIN_CPU_RATIO_TXT_WCOMPR_ON_OFF:
            print(msg_result1 % (what_sent1, 'EXPECTED') )
        else:
            print(msg_result1 % (what_sent1, '/* perf_issue_tag */ UNEXPECTED less than '+str(MIN_CPU_RATIO_TXT_WCOMPR_ON_OFF)) )
            all_fine = 0
    
    
        what_sent2 = 'INCOMPRESSABLE BINARY DATA'
        if cpu_bin_wcompr_ON_vs_OFF > MIN_CPU_RATIO_BIN_WCOMPR_ON_OFF:
            print(msg_result1 % (what_sent2, 'EXPECTED') )
        else:
            print(msg_result1 % (what_sent2, '/* perf_issue_tag */ UNEXPECTED, less than '+str(MIN_CPU_RATIO_BIN_WCOMPR_ON_OFF)) )
            all_fine = 0
    
    
        msg_result2 = 'CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: %s'
        if cpu_txt2bin_wcompr_OFF <= MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF:
            print(msg_result2 % ('EXPECTED') )
        else:
            print(msg_result2 % ('/* perf_issue_tag */ UNEXPECTED, more than ' + str(MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF)) )
            all_fine = 0
    
        if not all_fine:
            print('compressed_txt=',compressed_txt,' min=',min(compressed_txt),' max=',max(compressed_txt))
            print('compressed_bin=',compressed_bin,' min=',min(compressed_bin),' max=',max(compressed_bin))
            print('non_comprs_txt=',non_comprs_txt,' min=',min(non_comprs_txt),' max=',max(non_comprs_txt))
            print('non_comprs_bin=',non_comprs_bin,' min=',min(non_comprs_bin),' max=',max(non_comprs_bin))
    
            print('median(compressed_txt) / median(non_comprs_txt) =',1.000 * median(compressed_txt) / max(0.00001, median(non_comprs_txt)) )
            print('median(compressed_bin) / median(non_comprs_bin) =',1.000 * median(compressed_bin) / max(0.00001, median(non_comprs_bin)) )
            print('median(non_comprs_txt) / median(non_comprs_bin) =',1.000 * median(non_comprs_txt) / max(0.00001, median(non_comprs_bin)) )
    
    
        expected_stdout = ''
        for f in (what_sent1, what_sent2):
            expected_stdout += ''.join( (msg_result1 % (f, 'EXPECTED'), '\n')  )
        expected_stdout += (msg_result2 % 'EXPECTED')
    
        act.expected_stdout = expected_stdout
        act.stdout = capsys.readouterr().out
>       assert act.clean_stdout == act.clean_expected_stdout
E       assert   
E         - CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: EXPECTED
E         + CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: /* perf_issue_tag */ UNEXPECTED less than 6
E           CPU time ratio when sending INCOMPRESSABLE BINARY DATA and WireCompression is ON vs OFF: EXPECTED
E           CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: EXPECTED
E         + compressed_txt= [0.328125, 0.34375, 0.296875, 0.328125, 0.3125, 0.25, 0.28125, 0.390625, 0.359375]  min= 0.25  max= 0.390625
E         + compressed_bin= [0.234375, 0.40625, 0.375, 0.375, 0.359375, 0.40625, 0.40625, 0.4375, 0.390625]  min= 0.234375  max= 0.4375
E         + non_comprs_txt= [0.09375, 0.0625, 0.078125, 0.078125, 0.03125, 0.046875, 0.09375, 0.0625, 0.0625]  min= 0.03125  max= 0.09375
E         + non_comprs_bin= [0.078125, 0.03125, 0.09375, 0.09375, 0.09375, 0.109375, 0.0625, 0.09375, 0.09375]  min= 0.03125  max= 0.109375
E         + median(compressed_txt) / median(non_comprs_txt) = 5.25
E         + median(compressed_bin) / median(non_comprs_bin) = 4.166666666666667
E         + median(non_comprs_txt) / median(non_comprs_bin) = 0.6666666666666666

tests\bugs\core_0733_test.py:254: 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 5.0.3.1674 2025.06.27 3ee5c F P 16954 15959 2025.06.29 10:23:01.864 2025.06.29 10:23:18.818 2025.06.29 09:31:54.775 2025.06.29 09:32:10.734
2 5.0.3.1657 2025.06.26 dcb8a F P 17048 15755 2025.06.27 10:23:45.888 2025.06.27 10:24:02.936 2025.06.27 09:33:00.103 2025.06.27 09:33:15.858
3 5.0.3.1657 2025.06.20 8b4d2 F P 16507 16112 2025.06.26 10:37:58.708 2025.06.26 10:38:15.215 2025.06.26 09:47:00.478 2025.06.26 09:47:16.590
4 5.0.3.1657 2025.06.19 4bd4c F P 16816 16095 2025.06.20 04:42:13.043 2025.06.20 04:42:29.859 2025.06.20 03:50:45.342 2025.06.20 03:51:01.437
5 5.0.3.1657 2025.06.11 dae6f F P 17075 16448 2025.06.19 10:13:50.085 2025.06.19 10:14:07.160 2025.06.19 09:22:47.597 2025.06.19 09:23:04.045
6 5.0.3.1657 2025.06.10 dbc92 F P 16766 15768 2025.06.11 07:59:42.314 2025.06.11 07:59:59.080 2025.06.11 07:08:25.260 2025.06.11 07:08:41.028
7 5.0.3.1656 2025.06.05 00512 F P 17487 16109 2025.06.10 09:14:54.538 2025.06.10 09:15:12.025 2025.06.10 08:23:25.953 2025.06.10 08:23:42.062
8 5.0.3.1656 2025.05.20 c4b11 F P 16823 16596 2025.06.03 09:02:22.297 2025.06.03 09:02:39.120 2025.06.03 08:11:59.281 2025.06.03 08:12:15.877
9 5.0.3.1652 2025.05.13 f51c6 F P 16519 15795 2025.05.21 05:43:45.000 2025.05.21 05:44:01.519 2025.05.21 04:53:11.250 2025.05.21 04:53:27.045
10 5.0.3.1651 2025.05.08 ee9d2 F P 16559 15703 2025.05.13 05:56:00.675 2025.05.13 05:56:17.234 2025.05.13 04:47:17.013 2025.05.13 04:47:32.716
11 5.0.3.1651 2025.05.04 3d914 F P 17308 16228 2025.05.09 03:44:58.319 2025.05.09 03:45:15.627 2025.05.09 02:36:18.915 2025.05.09 02:36:35.143
12 5.0.3.1651 2025.04.30 141ef F P 16624 15270 2025.05.02 03:52:59.926 2025.05.02 03:53:16.550 2025.05.02 02:44:17.207 2025.05.02 02:44:32.477
13 5.0.3.1650 2025.04.30 6253f F F 16966 15916 2025.05.01 03:51:53.843 2025.05.01 03:52:10.809 2025.05.01 02:42:51.536 2025.05.01 02:43:07.452
14 5.0.3.1650 2025.04.28 4cbff P P 16304 15448 2025.04.30 03:50:58.725 2025.04.30 03:51:15.029 2025.04.30 02:42:37.330 2025.04.30 02:42:52.778
15 5.0.3.1649 2025.04.21 5b2d0 P F 16353 16508 2025.04.26 09:24:11.495 2025.04.26 09:24:27.848 2025.04.26 08:14:46.379 2025.04.26 08:15:02.887
16 5.0.3.1648 2025.04.18 2f4c5 F P 16455 15409 2025.04.20 03:35:36.857 2025.04.20 03:35:53.312 2025.04.20 02:44:10.212 2025.04.20 02:44:25.621
17 5.0.3.1635 2025.04.03 f6bd1 F P 16787 16190 2025.04.18 06:03:09.096 2025.04.18 06:03:25.883 2025.04.18 04:53:18.303 2025.04.18 04:53:34.493
18 5.0.3.1635 2025.03.31 22ec6 F F 16977 16870 2025.04.03 09:08:40.368 2025.04.03 09:08:57.345 2025.04.03 07:58:09.664 2025.04.03 07:58:26.534
19 5.0.3.1633 2025.03.28 3123a F P 17080 16047 2025.03.31 09:07:09.239 2025.03.31 09:07:26.319 2025.03.31 07:56:51.575 2025.03.31 07:57:07.622
20 5.0.3.1633 2025.03.27 e0fb8 F F 17338 16003 2025.03.28 09:35:29.694 2025.03.28 09:35:47.032 2025.03.28 08:22:08.394 2025.03.28 08:22:24.397
21 5.0.3.1631 2025.03.25 bda65 P P 16997 19744 2025.03.27 09:16:19.650 2025.03.27 09:16:36.647 2025.03.27 08:20:33.820 2025.03.27 08:20:53.564
22 5.0.3.1631 2025.03.21 1925b P F 17108 17154 2025.03.25 05:50:23.547 2025.03.25 05:50:40.655 2025.03.25 04:55:11.264 2025.03.25 04:55:28.418
23 5.0.3.1629 2025.03.18 506d7 F P 19684 16454 2025.03.20 08:50:49.237 2025.03.20 08:51:08.921 2025.03.20 07:56:18.767 2025.03.20 07:56:35.221
24 5.0.3.1628 2025.03.14 16d05 F P 17369 15619 2025.03.18 08:45:55.763 2025.03.18 08:46:13.132 2025.03.18 07:52:00.562 2025.03.18 07:52:16.181
25 5.0.3.1627 2025.02.26 4e218 P P 17187 15956 2025.03.13 09:03:32.895 2025.03.13 09:03:50.082 2025.03.13 08:08:23.784 2025.03.13 08:08:39.740
26 5.0.3.1624 2025.02.25 dc3b2 F F 17231 16624 2025.02.26 14:36:39.642 2025.02.26 14:36:56.873 2025.02.26 13:41:44.061 2025.02.26 13:42:00.685
27 5.0.2.1615 2025.02.20 4a726 F P 17656 16423 2025.02.25 07:51:48.792 2025.02.25 07:52:06.448 2025.02.25 06:40:06.473 2025.02.25 06:40:22.896
28 5.0.2.1615 2025.02.14 9cb76 F P 16996 15796 2025.02.15 03:19:54.180 2025.02.15 03:20:11.176 2025.02.15 02:25:53.650 2025.02.15 02:26:09.446
29 5.0.2.1577 2025.02.07 f50a2 P P 16698 15656 2025.02.14 05:33:39.848 2025.02.14 05:33:56.546 2025.02.14 04:41:31.895 2025.02.14 04:41:47.551
30 5.0.2.1577 2024.12.24 3c80e P P 16271 16479 2025.02.06 08:47:16.371 2025.02.06 08:47:32.642 2025.02.06 07:55:05.373 2025.02.06 07:55:21.852
31 5.0.2.1576 2024.12.17 646b0 P F 16309 16364 2024.12.24 08:30:23.648 2024.12.24 08:30:39.957 2024.12.24 07:38:28.502 2024.12.24 07:38:44.866
32 5.0.2.1575 2024.12.09 9af52 F P 18168 15290 2024.12.16 08:27:19.076 2024.12.16 08:27:37.244 2024.12.16 07:35:44.462 2024.12.16 07:35:59.752
33 5.0.2.1575 2024.12.08 63d39 F P 16591 15072 2024.12.09 14:20:21.835 2024.12.09 14:20:38.426 2024.12.09 13:33:59.087 2024.12.09 13:34:14.159
34 5.0.2.1571 2024.12.08 8d11a F P 16359 16332 2024.12.09 05:32:03.238 2024.12.09 05:32:19.597 2024.12.09 04:42:35.484 2024.12.09 04:42:51.816
35 5.0.2.1567 2024.12.07 b01a2 F P 16553 16162 2024.12.08 01:08:58.012 2024.12.08 01:09:14.565 2024.12.08 00:18:16.959 2024.12.08 00:18:33.121
36 5.0.2.1567 2024.12.02 6ae74 F F 16017 15288 2024.12.04 08:15:43.783 2024.12.04 08:15:59.800 2024.12.04 07:29:07.260 2024.12.04 07:29:22.548
37 5.0.2.1567 2024.11.26 56e63 P P 16161 16151 2024.11.30 08:17:54.340 2024.11.30 08:18:10.501 2024.11.30 07:27:03.963 2024.11.30 07:27:20.114
38 5.0.2.1567 2024.11.21 96f61 F P 16695 15392 2024.11.27 08:15:05.196 2024.11.27 08:15:21.891 2024.11.27 07:24:15.885 2024.11.27 07:24:31.277
39 5.0.2.1567 2024.11.18 e1289 F P 16836 16095 2024.11.21 08:33:34.013 2024.11.21 08:33:50.849 2024.11.21 07:20:45.390 2024.11.21 07:21:01.485
40 5.0.2.1533 2024.10.23 0ec43 P F 17062 15707 2024.11.18 08:08:32.120 2024.11.18 08:08:49.182 2024.11.18 07:17:43.448 2024.11.18 07:17:59.155
41 5.0.2.1533 2024.10.22 8af7a P P 16205 15752 2024.10.23 08:16:32.841 2024.10.23 08:16:49.046 2024.10.23 07:25:53.050 2024.10.23 07:26:08.802
42 5.0.2.1532 2024.10.15 36dc0 P P 16373 15395 2024.10.22 14:18:36.821 2024.10.22 14:18:53.194 2024.10.22 13:28:16.993 2024.10.22 13:28:32.388
43 5.0.2.1518 2024.10.04 259ba F P 17010 15330 2024.10.15 08:12:57.073 2024.10.15 08:13:14.083 2024.10.15 07:22:26.288 2024.10.15 07:22:41.618
44 5.0.2.1518 2024.09.26 703cd F P 18835 15481 2024.10.03 08:17:26.174 2024.10.03 08:17:45.009 2024.10.03 07:26:53.353 2024.10.03 07:27:08.834
45 5.0.2.1489 2024.08.31 994a6 P P 16089 15383 2024.09.26 08:36:19.891 2024.09.26 08:36:35.980 2024.09.26 07:26:52.144 2024.09.26 07:27:07.527
46 5.0.2.1476 2024.08.09 843ea F P 16945 15656 2024.09.01 08:23:08.907 2024.09.01 08:23:25.852 2024.09.01 07:12:41.523 2024.09.01 07:12:57.179
47 5.0.1.1454 2024.08.08 30f9f F P 16942 16032 2024.08.09 08:05:18.734 2024.08.09 08:05:35.676 2024.08.09 07:16:12.391 2024.08.09 07:16:28.423
48 5.0.1.1453 2024.08.07 ebbc3 F P 17143 16286 2024.08.08 19:19:10.928 2024.08.08 19:19:28.071 2024.08.08 18:30:02.611 2024.08.08 18:30:18.897
49 5.0.1.1453 2024.08.06 1b9d0 F P 17261 15841 2024.08.07 07:38:04.121 2024.08.07 07:38:21.382 2024.08.07 06:51:50.955 2024.08.07 06:52:06.796
50 5.0.1.1453 2024.07.30 48044 P P 24395 24888 2024.08.03 07:37:04.231 2024.08.03 07:37:28.626 2024.08.03 06:50:29.077 2024.08.03 06:50:53.965
51 5.0.1.1453 2024.07.28 8d956 P P 24688 22971 2024.07.30 07:18:28.767 2024.07.30 07:18:53.455 2024.07.30 06:34:04.636 2024.07.30 06:34:27.607
52 5.0.1.1429 2024.07.19 8ee90 P P 24309 22784 2024.07.27 07:17:18.726 2024.07.27 07:17:43.035 2024.07.27 06:33:06.031 2024.07.27 06:33:28.815
53 5.0.1.1428 2024.07.15 00392 P P 24176 22752 2024.07.19 07:12:42.533 2024.07.19 07:13:06.709 2024.07.19 06:28:47.938 2024.07.19 06:29:10.690
54 5.0.1.1428 2024.06.30 67a31 P P 23396 22892 2024.07.15 07:24:09.180 2024.07.15 07:24:32.576 2024.07.15 06:39:05.169 2024.07.15 06:39:28.061
55 5.0.1.1415 2024.06.12 f8731 P P 23549 22931 2024.06.22 04:23:09.544 2024.06.22 04:23:33.093 2024.06.22 03:39:27.338 2024.06.22 03:39:50.269
56 5.0.1.1415 2024.06.11 31d74 P P 23799 22971 2024.06.11 22:56:04.185 2024.06.11 22:56:27.984 2024.06.11 22:17:25.969 2024.06.11 22:17:48.940
57 5.0.1.1401 2024.06.05 f9b76 P P 24205 23158 2024.06.11 03:46:42.849 2024.06.11 03:47:07.054 2024.06.11 03:08:03.227 2024.06.11 03:08:26.385
58 5.0.1.1398 2024.05.10 5e3ce P P 24143 23252 2024.05.25 04:41:50.168 2024.05.25 04:42:14.311 2024.05.25 04:03:23.079 2024.05.25 04:03:46.331
59 5.0.1.1397 2024.05.09 ee2ef P P 23893 23143 2024.05.10 04:38:20.771 2024.05.10 04:38:44.664 2024.05.10 04:00:14.628 2024.05.10 04:00:37.771
60 5.0.1.1392 2024.04.29 7dbc2 P P 24284 23394 2024.05.09 16:27:53.567 2024.05.09 16:28:17.851 2024.05.09 15:49:40.737 2024.05.09 15:50:04.131
61 5.0.1.1386 2024.04.25 c0328 P P 23815 22956 2024.04.29 04:37:23.806 2024.04.29 04:37:47.621 2024.04.29 03:59:27.048 2024.04.29 03:59:50.004
62 5.0.1.1386 2024.04.20 80571 P P 23734 23000 2024.04.25 04:39:10.392 2024.04.25 04:39:34.126 2024.04.25 04:01:07.304 2024.04.25 04:01:30.304
63 5.0.1.1378 2024.04.07 5292b P P 23737 23252 2024.04.20 04:59:14.057 2024.04.20 04:59:37.794 2024.04.20 03:59:47.333 2024.04.20 04:00:10.585
64 5.0.1.1346 2024.03.16 fe320 P P 23393 22634 2024.04.07 03:02:18.322 2024.04.07 03:02:41.715 2024.04.07 02:26:02.967 2024.04.07 02:26:25.601
65 5.0.1.1346 2024.03.02 da408 P P 23642 22751 2024.03.25 21:49:58.274 2024.03.25 21:50:21.916 2024.03.25 21:13:44.021 2024.03.25 21:14:06.772
66 5.0.1.1340 2024.02.17 08a71 P P 23455 22674 2024.03.25 23:19:41.985 2024.03.25 23:20:05.440 2024.03.25 22:43:30.869 2024.03.25 22:43:53.543
67 5.0.1.1325 2024.02.06 c98fb P P 23626 22704 2024.03.26 01:51:07.871 2024.03.26 01:51:31.497 2024.03.26 00:53:48.691 2024.03.26 00:54:11.395
68 5.0.1.1325 2024.02.02 1d438 P P 23579 22861 2024.03.26 07:07:43.327 2024.03.26 07:08:06.906 2024.03.26 06:09:30.394 2024.03.26 06:09:53.255
69 5.0.1.1325 2024.01.26 cffb6 P P 23548 22830 2024.03.26 09:34:19.009 2024.03.26 09:34:42.557 2024.03.26 08:36:54.987 2024.03.26 08:37:17.817
70 5.0.1.1325 2024.01.26 d3810 P P 23673 22720 2024.03.26 11:26:09.707 2024.03.26 11:26:33.380 2024.03.26 10:29:05.321 2024.03.26 10:29:28.041
71 5.0.1.1318 2024.01.21 a7ca3 P P 23642 22959 2024.03.26 12:55:10.843 2024.03.26 12:55:34.485 2024.03.26 12:19:11.892 2024.03.26 12:19:34.851
72 5.0.1.1318 2024.01.21 d429d P P 23643 22751 2024.03.26 14:36:51.133 2024.03.26 14:37:14.776 2024.03.26 14:00:48.822 2024.03.26 14:01:11.573
73 5.0.1.1318 2024.01.21 f1ab5 P P 23626 22799 2024.03.26 16:52:47.078 2024.03.26 16:53:10.704 2024.03.26 16:16:50.181 2024.03.26 16:17:12.980
74 5.0.1.1318 2024.01.20 46722 P P 23532 22788 2024.03.26 18:19:50.523 2024.03.26 18:20:14.055 2024.03.26 17:43:56.024 2024.03.26 17:44:18.812

Elapsed time, ms. Chart for last 74 runs:

Last commits information (all timestamps in UTC):