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 5
    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= [1.3699999999999974, 1.3200000000000003, 1.269999999999996, 1.3099999999999952, 1.25, 1.2800000000000011, 1.3000000000000043, 1.2100000000000009, 1.2999999999999972]  min= 1.2100000000000009  max= 1.3699999999999974
  + compressed_bin= [1.3200000000000003, 1.2600000000000051, 1.240000000000002, 1.3100000000000023, 1.2899999999999991, 1.240000000000002, 1.3599999999999994, 1.3300000000000054, 1.2700000000000102]  min= 1.240000000000002  max= 1.3599999999999994
  + non_comprs_txt= [0.2600000000000051, 0.3100000000000023, 0.25, 0.28000000000000114, 0.25, 0.21000000000000796, 0.25, 0.269999999999996, 0.269999999999996]  min= 0.21000000000000796  max= 0.3100000000000023
  + non_comprs_bin= [0.3199999999999932, 0.29999999999999716, 0.28000000000000114, 0.3299999999999983, 0.29999999999999716, 0.20000000000000284, 0.35999999999999943, 0.3100000000000023, 0.28999999999999204]  min= 0.20000000000000284  max= 0.35999999999999943
  + median(compressed_txt) / median(non_comprs_txt) = 4.999999999999891
  + median(compressed_bin) / median(non_comprs_bin) = 4.300000000000038
  + median(non_comprs_txt) / median(non_comprs_bin) = 0.8666666666666919

LOG DETAILS:

2025-01-28 10:36:08.792
2025-01-28 10:36:08.800 act = <firebird.qa.plugin.Action object at [hex]>
2025-01-28 10:36:08.808 capsys = <_pytest.capture.CaptureFixture object at [hex]>
2025-01-28 10:36:08.818
2025-01-28 10:36:08.826 @pytest.mark.version('>=3.0')
2025-01-28 10:36:08.833 def test_1(act: Action, capsys):
2025-01-28 10:36:08.840
2025-01-28 10:36:08.847 # OPTIONAL CHECK: minimal ratio between CPU user time when WireCompression = false
2025-01-28 10:36:08.854 # and engine sends to client: 1) 'IDEALLY COMPRESSABLE'; 2) 'ABSOLUTELY IMCOMPRESSIBLE' data.
2025-01-28 10:36:08.860 # This can be useful to estimate record-level compression: textual data can be compressed
2025-01-28 10:36:08.867 # very well, so its transfer must take much less time then for GEN_UUID.
2025-01-28 10:36:08.873 # Experiments show that this ratio can be on Windows in the scope 0.3.... 0.8,
2025-01-28 10:36:08.878 # but on Linux it can be 1.0 or even slightly more then 1(!)
2025-01-28 10:36:08.883 # Windows: 0.500; 0.600; 0.571; 0.428; 0.714; 0.667; 0.625; 0.429; 0.571 // 4.0.1
2025-01-28 10:36:08.890 #          0.454; 0.357; 0.357; 0.500; 0.250; 0.385; 0.333; 0.200; 0.500 // 3.0.8
2025-01-28 10:36:08.897 # Linux:   0.684; 1.000; 1.000; 1.067; 0.867; 0.813; 0.800; 0.777; 0.750 // 4.0.1
2025-01-28 10:36:08.903 #          0.928; 1.000; 0.933; 1.000; 1.077; 0.750; 0.938; 0.929; 0.928 // 3.0.8
2025-01-28 10:36:08.908 if act.is_version('<4'):
2025-01-28 10:36:08.914 # 16.09.2022, 4.3.0.8 Classic: Windows -> 1.2
2025-01-28 10:36:08.919 MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF = 1.1 if platform.system() == 'Linux' else 1.5
2025-01-28 10:36:08.925 else:
2025-01-28 10:36:08.931 # 05.03.2023, 5.0.0.970, SS, Linux: 1.1 --> 1.3
2025-01-28 10:36:08.937 # 05.04.2023, 5.0.0.1001, SS, WIndows: 0.95 --> 1.5
2025-01-28 10:36:08.942 MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF = 1.3 if platform.system() == 'Linux' else 1.5
2025-01-28 10:36:08.947
2025-01-28 10:36:08.953 # Register Firebird server (D:\FB\probes\fid-set-dpb-probe-05x.py)
2025-01-28 10:36:08.959 srv_cfg = driver_config.register_server(name = 'test_srv_core_0733', config = '')
2025-01-28 10:36:08.965
2025-01-28 10:36:08.970 #srv_config_key_value_text = \
2025-01-28 10:36:08.975 #f"""
2025-01-28 10:36:08.980 #    [test_srv_core_0733]
2025-01-28 10:36:08.985 #    protocol = inet
2025-01-28 10:36:08.990 #"""
2025-01-28 10:36:08.995 #driver_config.register_server(name = 'test_srv_core_0733', config = srv_config_key_value_text)
2025-01-28 10:36:09.000 #db_cfg_object = driver_config.register_database(name = 'test_db_core_0733')
2025-01-28 10:36:09.005 #db_cfg_object.database.value = str(act.db.db_path)
2025-01-28 10:36:09.011
2025-01-28 10:36:09.019 benchmark_data = defaultdict(list)
2025-01-28 10:36:09.027
2025-01-28 10:36:09.035 for w_compr in (True, False):
2025-01-28 10:36:09.042
2025-01-28 10:36:09.049 db_cfg_name = f'test_db_core_0733__wcompr_{w_compr}'
2025-01-28 10:36:09.057 db_cfg_object = driver_config.register_database(name = db_cfg_name)
2025-01-28 10:36:09.065 db_cfg_object.server.value = srv_cfg.name
2025-01-28 10:36:09.073 # db_cfg_object.protocol.value = None /  XNET /  WNET -- these can not be used in this test!
2025-01-28 10:36:09.081 db_cfg_object.protocol.value = NetProtocol.INET
2025-01-28 10:36:09.089 db_cfg_object.database.value = str(act.db.db_path)
2025-01-28 10:36:09.097 db_cfg_object.config.value = f"""
2025-01-28 10:36:09.105 WireCrypt = Disabled
2025-01-28 10:36:09.113 WireCompression = {w_compr}
2025-01-28 10:36:09.121 """
2025-01-28 10:36:09.130 for i in range(0, N_MEASURES):
2025-01-28 10:36:09.138 with connect(db_cfg_name, user = act.db.user, password = act.db.password) as con:
2025-01-28 10:36:09.146 prot_name = db_cfg_object.protocol.value.name if db_cfg_object.protocol.value else 'Embedded'
2025-01-28 10:36:09.153 assert w_compr == con.info.is_compressed(), f'Protocol: {prot_name} - can not be used to measure wire_compression'
2025-01-28 10:36:09.160
2025-01-28 10:36:09.169 with con.cursor() as cur:
2025-01-28 10:36:09.176 cur.execute('select mon$server_pid, mon$remote_protocol as p from mon$attachments where mon$attachment_id = current_connection')
2025-01-28 10:36:09.183 for r in cur:
2025-01-28 10:36:09.190 fb_pid, connection_protocol = r
2025-01-28 10:36:09.198 assert connection_protocol.startswith('TCP'), f'Invalid connection protocol: {connection_protocol}'
2025-01-28 10:36:09.205
2025-01-28 10:36:09.212 for data_source in ('t_common_text', 't_binary_data'):
2025-01-28 10:36:09.219 cur.execute('select s from ' + data_source)
2025-01-28 10:36:09.226
2025-01-28 10:36:09.233 fb_info_a = psutil.Process(fb_pid).cpu_times()
2025-01-28 10:36:09.241 for r in cur:
2025-01-28 10:36:09.248 # *** FULL FETCH ***
2025-01-28 10:36:09.255 pass
2025-01-28 10:36:09.262 fb_info_b = psutil.Process(fb_pid).cpu_times()
2025-01-28 10:36:09.270
2025-01-28 10:36:09.277 k = ('WireCompression=%d' % (1 if w_compr else 0), 'DataSource='+data_source)
2025-01-28 10:36:09.286 benchmark_data[k] += fb_info_b.user - fb_info_a.user,
2025-01-28 10:36:09.294
2025-01-28 10:36:09.303
2025-01-28 10:36:09.312 compressed_txt = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=1' and k[1] == 'DataSource=t_common_text'][0]
2025-01-28 10:36:09.321 compressed_bin = [ v for k,v in benchmark_data.items() if k[0] == 'WireCompression=1' and k[1] == 'DataSource=t_binary_data'][0]
2025-01-28 10:36:09.329 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-01-28 10:36:09.336 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-01-28 10:36:09.343
2025-01-28 10:36:09.351 cpu_txt_wcompr_ON_vs_OFF = median(compressed_txt) / max(0.00001, median(non_comprs_txt))
2025-01-28 10:36:09.358 cpu_bin_wcompr_ON_vs_OFF = median(compressed_bin) / max(0.00001, median(non_comprs_bin))
2025-01-28 10:36:09.367 cpu_txt2bin_wcompr_OFF = median(non_comprs_txt) / max(0.00001, median(non_comprs_bin))
2025-01-28 10:36:09.377
2025-01-28 10:36:09.385 msg_result1 = 'CPU time ratio when sending %s and WireCompression is ON vs OFF: %s'
2025-01-28 10:36:09.392 what_sent1 = 'COMPRESSABLE TEXTUAL DATA'
2025-01-28 10:36:09.399 all_fine = 1
2025-01-28 10:36:09.406 if cpu_txt_wcompr_ON_vs_OFF > MIN_CPU_RATIO_TXT_WCOMPR_ON_OFF:
2025-01-28 10:36:09.413 print(msg_result1 % (what_sent1, 'EXPECTED') )
2025-01-28 10:36:09.420 else:
2025-01-28 10:36:09.428 print(msg_result1 % (what_sent1, '/* perf_issue_tag */ UNEXPECTED less than '+str(MIN_CPU_RATIO_TXT_WCOMPR_ON_OFF)) )
2025-01-28 10:36:09.435 all_fine = 0
2025-01-28 10:36:09.442
2025-01-28 10:36:09.448
2025-01-28 10:36:09.456 what_sent2 = 'INCOMPRESSABLE BINARY DATA'
2025-01-28 10:36:09.464 if cpu_bin_wcompr_ON_vs_OFF > MIN_CPU_RATIO_BIN_WCOMPR_ON_OFF:
2025-01-28 10:36:09.471 print(msg_result1 % (what_sent2, 'EXPECTED') )
2025-01-28 10:36:09.478 else:
2025-01-28 10:36:09.486 print(msg_result1 % (what_sent2, '/* perf_issue_tag */ UNEXPECTED, less than '+str(MIN_CPU_RATIO_BIN_WCOMPR_ON_OFF)) )
2025-01-28 10:36:09.495 all_fine = 0
2025-01-28 10:36:09.503
2025-01-28 10:36:09.511
2025-01-28 10:36:09.519 msg_result2 = 'CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: %s'
2025-01-28 10:36:09.528 if cpu_txt2bin_wcompr_OFF <= MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF:
2025-01-28 10:36:09.537 print(msg_result2 % ('EXPECTED') )
2025-01-28 10:36:09.546 else:
2025-01-28 10:36:09.554 print(msg_result2 % ('/* perf_issue_tag */ UNEXPECTED, more than ' + str(MAX_CPU_RATIO_TXT2BIN_WCOMPR_OFF)) )
2025-01-28 10:36:09.560 all_fine = 0
2025-01-28 10:36:09.566
2025-01-28 10:36:09.573 if not all_fine:
2025-01-28 10:36:09.580 print('compressed_txt=',compressed_txt,' min=',min(compressed_txt),' max=',max(compressed_txt))
2025-01-28 10:36:09.586 print('compressed_bin=',compressed_bin,' min=',min(compressed_bin),' max=',max(compressed_bin))
2025-01-28 10:36:09.593 print('non_comprs_txt=',non_comprs_txt,' min=',min(non_comprs_txt),' max=',max(non_comprs_txt))
2025-01-28 10:36:09.599 print('non_comprs_bin=',non_comprs_bin,' min=',min(non_comprs_bin),' max=',max(non_comprs_bin))
2025-01-28 10:36:09.607
2025-01-28 10:36:09.614 print('median(compressed_txt) / median(non_comprs_txt) =',1.000 * median(compressed_txt) / max(0.00001, median(non_comprs_txt)) )
2025-01-28 10:36:09.620 print('median(compressed_bin) / median(non_comprs_bin) =',1.000 * median(compressed_bin) / max(0.00001, median(non_comprs_bin)) )
2025-01-28 10:36:09.627 print('median(non_comprs_txt) / median(non_comprs_bin) =',1.000 * median(non_comprs_txt) / max(0.00001, median(non_comprs_bin)) )
2025-01-28 10:36:09.633
2025-01-28 10:36:09.640
2025-01-28 10:36:09.648 expected_stdout = ''
2025-01-28 10:36:09.662 for f in (what_sent1, what_sent2):
2025-01-28 10:36:09.673 expected_stdout += ''.join( (msg_result1 % (f, 'EXPECTED'), '\n')  )
2025-01-28 10:36:09.682 expected_stdout += (msg_result2 % 'EXPECTED')
2025-01-28 10:36:09.689
2025-01-28 10:36:09.697 act.expected_stdout = expected_stdout
2025-01-28 10:36:09.704 act.stdout = capsys.readouterr().out
2025-01-28 10:36:09.710 >       assert act.clean_stdout == act.clean_expected_stdout
2025-01-28 10:36:09.717 E       assert
2025-01-28 10:36:09.724 E         - CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: EXPECTED
2025-01-28 10:36:09.732 E         + CPU time ratio when sending COMPRESSABLE TEXTUAL DATA and WireCompression is ON vs OFF: /* perf_issue_tag */ UNEXPECTED less than 5
2025-01-28 10:36:09.755 E           CPU time ratio when sending INCOMPRESSABLE BINARY DATA and WireCompression is ON vs OFF: EXPECTED
2025-01-28 10:36:09.768 E           CPU time ratio when WireCompression is OFF and sending TEXTUAL vs BINARY data: EXPECTED
2025-01-28 10:36:09.777 E         + compressed_txt= [1.3699999999999974, 1.3200000000000003, 1.269999999999996, 1.3099999999999952, 1.25, 1.2800000000000011, 1.3000000000000043, 1.2100000000000009, 1.2999999999999972]  min= 1.2100000000000009  max= 1.3699999999999974
2025-01-28 10:36:09.784 E         + compressed_bin= [1.3200000000000003, 1.2600000000000051, 1.240000000000002, 1.3100000000000023, 1.2899999999999991, 1.240000000000002, 1.3599999999999994, 1.3300000000000054, 1.2700000000000102]  min= 1.240000000000002  max= 1.3599999999999994
2025-01-28 10:36:09.794 E         + non_comprs_txt= [0.2600000000000051, 0.3100000000000023, 0.25, 0.28000000000000114, 0.25, 0.21000000000000796, 0.25, 0.269999999999996, 0.269999999999996]  min= 0.21000000000000796  max= 0.3100000000000023
2025-01-28 10:36:09.807 E         + non_comprs_bin= [0.3199999999999932, 0.29999999999999716, 0.28000000000000114, 0.3299999999999983, 0.29999999999999716, 0.20000000000000284, 0.35999999999999943, 0.3100000000000023, 0.28999999999999204]  min= 0.20000000000000284  max= 0.35999999999999943
2025-01-28 10:36:09.815 E         + median(compressed_txt) / median(non_comprs_txt) = 4.999999999999891
2025-01-28 10:36:09.824 E         + median(compressed_bin) / median(non_comprs_bin) = 4.300000000000038
2025-01-28 10:36:09.841 E         + median(non_comprs_txt) / median(non_comprs_bin) = 0.8666666666666919
2025-01-28 10:36:09.851
2025-01-28 10:36:09.860 tests/bugs/core_0733_test.py:254: AssertionError
2025-01-28 10:36:09.875 ---------------------------- Captured stdout setup -----------------------------
2025-01-28 10:36:09.886 Creating db: localhost:/var/tmp/qa_2024/test_175/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 5
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= [1.3699999999999974, 1.3200000000000003, 1.269999999999996, 1.3099999999999952, 1.25, 1.2800000000000011, 1.3000000000000043, 1.2100000000000009, 1.2999999999999972]  min= 1.2100000000000009  max= 1.3699999999999974
E         + compressed_bin= [1.3200000000000003, 1.2600000000000051, 1.240000000000002, 1.3100000000000023, 1.2899999999999991, 1.240000000000002, 1.3599999999999994, 1.3300000000000054, 1.2700000000000102]  min= 1.240000000000002  max= 1.3599999999999994
E         + non_comprs_txt= [0.2600000000000051, 0.3100000000000023, 0.25, 0.28000000000000114, 0.25, 0.21000000000000796, 0.25, 0.269999999999996, 0.269999999999996]  min= 0.21000000000000796  max= 0.3100000000000023
E         + non_comprs_bin= [0.3199999999999932, 0.29999999999999716, 0.28000000000000114, 0.3299999999999983, 0.29999999999999716, 0.20000000000000284, 0.35999999999999943, 0.3100000000000023, 0.28999999999999204]  min= 0.20000000000000284  max= 0.35999999999999943
E         + median(compressed_txt) / median(non_comprs_txt) = 4.999999999999891
E         + median(compressed_bin) / median(non_comprs_bin) = 4.300000000000038
E         + median(non_comprs_txt) / median(non_comprs_bin) = 0.8666666666666919

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 3.0.13.33814 2025.06.21 85255 P P 41543 41374 2025.06.26 09:06:26.651 2025.06.26 09:07:08.194 2025.06.26 08:27:16.294 2025.06.26 08:27:57.668
2 3.0.13.33813 2025.06.14 222a9 P P 41617 41136 2025.06.20 03:25:18.824 2025.06.20 03:26:00.441 2025.06.20 02:46:00.353 2025.06.20 02:46:41.489
3 3.0.13.33811 2025.05.07 16491 P P 43855 41469 2025.06.14 09:53:16.296 2025.06.14 09:54:00.151 2025.06.14 09:13:43.638 2025.06.14 09:14:25.107
4 3.0.13.33810 2025.05.06 02b1d P P 51610 49961 2025.05.07 08:16:13.502 2025.05.07 08:17:05.112 2025.05.07 07:30:54.259 2025.05.07 07:31:44.220
5 3.0.13.33809 2025.05.05 4ec6d P P 51851 50625 2025.05.06 08:22:08.015 2025.05.06 08:22:59.866 2025.05.06 07:36:47.941 2025.05.06 07:37:38.566
6 3.0.13.33808 2025.04.18 bf513 P P 51359 50022 2025.05.04 22:03:11.316 2025.05.04 22:04:02.675 2025.05.04 21:17:40.920 2025.05.04 21:18:30.942
7 3.0.13.33807 2025.04.14 73e94 P P 52034 50995 2025.04.18 08:14:44.881 2025.04.18 08:15:36.915 2025.04.18 07:29:10.338 2025.04.18 07:30:01.333
8 3.0.13.33806 2025.03.26 b6cfe P P 44986 45395 2025.04.14 07:11:12.760 2025.04.14 07:11:57.746 2025.04.14 06:29:33.929 2025.04.14 06:30:19.324
9 3.0.13.33805 2025.03.17 98320 P P 47143 43970 2025.03.25 04:35:59.343 2025.03.25 04:36:46.486 2025.03.25 03:55:32.446 2025.03.25 03:56:16.416
10 3.0.13.33804 2025.02.25 1439d P P 849 560 2025.03.17 04:43:48.770 2025.03.17 04:43:49.619 2025.03.17 03:57:50.605 2025.03.17 03:57:51.165
11 3.0.13.33803 2025.01.29 f1848 P P 763 519 2025.02.25 07:23:56.096 2025.02.25 07:23:56.859 2025.02.25 06:40:21.442 2025.02.25 06:40:21.961
12 3.0.13.33802 2025.01.28 650bd P P 811 475 2025.01.29 22:02:11.330 2025.01.29 22:02:12.141 2025.01.29 21:17:35.385 2025.01.29 21:17:35.860
13 3.0.13.33800 2025.01.20 f20ab P F 862 560 2025.01.28 07:39:12.633 2025.01.28 07:39:13.495 2025.01.28 06:53:14.752 2025.01.28 06:53:15.312
14 3.0.13.33798 2025.01.16 0c3bb P P 770 522 2025.01.20 07:11:34.008 2025.01.20 07:11:34.778 2025.01.20 06:26:44.429 2025.01.20 06:26:44.951
15 3.0.13.33795 2024.12.23 1bf0b P P 772 523 2025.01.16 07:09:32.436 2025.01.16 07:09:33.208 2025.01.16 06:25:17.991 2025.01.16 06:25:18.514
16 3.0.13.33794 2024.10.23 e2a6b P P 673 349 2024.12.23 01:00:10.988 2024.12.23 01:00:11.661 2024.12.23 00:25:22.755 2024.12.23 00:25:23.104
17 3.0.13.33793 2024.09.02 3e627 P P 749 467 2024.10.23 07:02:30.597 2024.10.23 07:02:31.346 2024.10.23 06:24:36.726 2024.10.23 06:24:37.193
18 3.0.13.33792 2024.08.30 d9f38 P P 3307 774 2024.09.02 10:00:16.367 2024.09.02 10:00:19.674 2024.09.02 08:47:20.999 2024.09.02 08:47:21.773
19 3.0.13.33791 2024.08.21 c8a36 P P 1430 1309 2024.08.30 09:44:03.251 2024.08.30 09:44:04.681 2024.08.30 08:32:12.301 2024.08.30 08:32:13.610
20 3.0.13.33790 2024.08.20 3bf52 P P 1467 793 2024.08.21 09:15:03.028 2024.08.21 09:15:04.495 2024.08.21 08:11:45.169 2024.08.21 08:11:45.962
21 3.0.13.33789 2024.08.09 7933a P P 938 562 2024.08.19 05:48:29.738 2024.08.19 05:48:30.676 2024.08.19 05:03:10.480 2024.08.19 05:03:11.042
22 3.0.12.33787 2024.08.06 bf180 P P 964 625 2024.08.09 05:35:47.194 2024.08.09 05:35:48.158 2024.08.09 04:50:50.522 2024.08.09 04:50:51.147
23 3.0.12.33784 2024.08.01 cd857 P P 674 379 2024.08.06 04:39:42.494 2024.08.06 04:39:43.168 2024.08.06 04:01:14.379 2024.08.06 04:01:14.758
24 3.0.12.33779 2024.07.31 ae35d P P 682 397 2024.08.01 04:38:19.522 2024.08.01 04:38:20.204 2024.08.01 04:00:04.229 2024.08.01 04:00:04.626
25 3.0.12.33778 2024.07.21 4680d P P 710 360 2024.07.30 04:35:23.735 2024.07.30 04:35:24.445 2024.07.30 03:57:15.577 2024.07.30 03:57:15.937
26 3.0.12.33777 2024.07.19 8e912 P P 710 365 2024.07.21 04:37:30.653 2024.07.21 04:37:31.363 2024.07.21 03:59:19.494 2024.07.21 03:59:19.859
27 3.0.12.33766 2024.07.13 b5086 P P 659 355 2024.07.19 04:30:11.504 2024.07.19 04:30:12.163 2024.07.19 03:52:22.670 2024.07.19 03:52:23.025
28 3.0.12.33765 2024.07.10 06f2a P P 681 421 2024.07.13 04:32:57.144 2024.07.13 04:32:57.825 2024.07.13 03:53:46.417 2024.07.13 03:53:46.838
29 3.0.12.33764 2024.06.18 4d0c0 P P 559 383 2024.07.10 04:22:36.495 2024.07.10 04:22:37.054 2024.07.10 03:45:45.893 2024.07.10 03:45:46.276
30 3.0.12.33761 2024.06.17 b259d P P 657 407 2024.06.18 04:23:43.175 2024.06.18 04:23:43.832 2024.06.18 03:46:13.821 2024.06.18 03:46:14.228
31 3.0.12.33758 2024.06.14 4f9bc P P 721 377 2024.06.17 04:18:27.475 2024.06.17 04:18:28.196 2024.06.17 03:40:19.807 2024.06.17 03:40:20.184
32 3.0.12.33757 2024.06.13 c7a1c P P 547 423 2024.06.14 04:35:37.491 2024.06.14 04:35:38.038 2024.06.14 04:02:40.040 2024.06.14 04:02:40.463
33 3.0.12.33744 2024.04.19 ecf36 P P 531 330 2024.05.08 15:15:20.936 2024.05.08 15:15:21.467 2024.05.08 14:42:20.582 2024.05.08 14:42:20.912

Elapsed time, ms. Chart for last 33 runs:

Last commits information (all timestamps in UTC):