Updating tracing-core from 0.1.30 to 0.1.31 results in singificant binary size increase

[smalis-msft]

Bug Report

Version

tracing 0.1.37
tracing-attributes 0.1.27
tracing-core 0.1.30
tracing-log 0.1.4
tracing-log 0.2.0
tracing-serde 0.1.3
tracing-subscriber 0.3.18

Crates

tracing-core 0.1.31

Description

Over in https://github.com/microsoft/openvmm we use tracing heavily for all of our logging. We care a lot about binary size for one of our binaries, openvmm-hcl. Updating the workspace from tracing-core 0.1.30 to 0.1.31, with no other changes, results in roughly 300kb of additional .text binary size when compiled with our shipping profile (fat LTO, 1 codegen unit). I suspect this is due to #2555 from looking at the release notes, but am not 100% certain. The results on v0.1.33 are unchanged from v0.1.31.

Repro Steps

1. Follow our guide to setting up a development environment on WSL/Linux: https://openvmm.dev/guide/dev_guide/getting_started/linux.html
2. Install cargo-bloat
3. Run cargo bloat -p openvmm_hcl --target x86_64-unknown-linux-musl --profile underhill-ship to measure the baseline
4. Run cargo update -p tracing-core --precise 0.1.31 to update
5. Run cargo bloat -p openvmm_hcl --target x86_64-unknown-linux-musl --profile underhill-ship again to measure the regression

Example outputs

Before

File  .text     Size                 Crate Name
0.1%   1.5% 167.5KiB        underhill_core underhill_core::worker::new_underhill_vm::<pal_async::io_pool::IoDriver<pa...
0.0%   0.5%  52.5KiB        underhill_core <underhill_core::dispatch::LoadedVm>::run::<underhill_core::worker::Restar...
0.0%   0.5%  51.2KiB underhill_attestation underhill_attestation::initialize_platform_security::{closure#0}
0.0%   0.4%  47.5KiB      underhill_config <underhill_config::Vtl2Settings>::read_from_inner
0.0%   0.4%  43.5KiB         virt_mshv_vtl <virt_mshv_vtl::processor::UhProcessor<virt_mshv_vtl::processor::snp::SnpB...
0.0%   0.4%  41.8KiB          vmotherboard <vmotherboard::base_chipset::BaseChipsetBuilder>::build::{closure#0}
0.0%   0.3%  37.1KiB           vmbus_relay <vmbus_relay::RelayTask>::run::{closure#0}
0.0%   0.3%  33.7KiB           diag_server <diag_server::diag_service::DiagServiceHandler>::handle_diag_request::<pal...
0.0%   0.3%  29.1KiB        underhill_core <underhill_core::worker::UhVmNetworkSettings>::new_underhill_nic::{closure#0}
0.0%   0.3%  28.8KiB          vmbus_client <vmbus_client::ClientTask<vmbus_client_hcl::MessageSource>>::run::{closure#0}
0.0%   0.2%  27.8KiB underhill_attestation underhill_attestation::get_derived_keys::{closure#0}
0.0%   0.2%  27.7KiB        underhill_core underhill_core::run_control::{closure#0}
0.0%   0.2%  27.6KiB        underhill_core <underhill_core::worker::UnderhillVmWorker>::new_or_restart::{closure#0}::...
0.0%   0.2%  27.4KiB              scsidisk <scsidisk::SimpleScsiDisk as scsi_core::AsyncScsiDisk>::execute_scsi::{clo...
0.0%   0.2%  27.0KiB        underhill_core underhill_core::main
0.0%   0.2%  26.9KiB        underhill_init underhill_init::do_main
0.0%   0.2%  26.3KiB                netvsp <netvsp::NetChannel<vmbus_channel::gpadl_ring::GpadlRingMem>>::main_loop::...
0.0%   0.2%  26.1KiB        underhill_core <underhill_core::dispatch::vtl2_settings_worker::Vtl2SettingsWorker>::hand...
0.0%   0.2%  25.4KiB        underhill_core <underhill_core::emuplat::netvsp::HclNetworkVFManagerWorker>::run::{closur...
0.0%   0.2%  25.0KiB         firmware_uefi <firmware_uefi::UefiDevice>::handle_nvram_command_inner::{closure#0}
5.7%  90.2%  10.0MiB                       And 27682 smaller methods. Use -n N to show more.
6.3% 100.0%  11.0MiB                       .text section size

After

File  .text     Size                 Crate Name
0.1%   1.4% 165.7KiB        underhill_core underhill_core::worker::new_underhill_vm::<pal_async::io_pool::IoDriver<pa...
0.0%   0.5%  54.2KiB        underhill_core <underhill_core::dispatch::LoadedVm>::run::<underhill_core::worker::Restar...
0.0%   0.5%  52.2KiB underhill_attestation underhill_attestation::initialize_platform_security::{closure#0}
0.0%   0.4%  47.5KiB      underhill_config <underhill_config::Vtl2Settings>::read_from_inner
0.0%   0.4%  45.4KiB         virt_mshv_vtl <virt_mshv_vtl::processor::UhProcessor<virt_mshv_vtl::processor::snp::SnpB...
0.0%   0.4%  42.9KiB          vmotherboard <vmotherboard::base_chipset::BaseChipsetBuilder>::build::{closure#0}
0.0%   0.3%  39.4KiB           vmbus_relay <vmbus_relay::RelayTask>::run::{closure#0}
0.0%   0.3%  33.8KiB           diag_server <diag_server::diag_service::DiagServiceHandler>::handle_diag_request::<pal...
0.0%   0.3%  33.3KiB             pal_async <pal_async::task::TaskFuture<<vmbus_server::VmbusServerBuilder<&underhill_...
0.0%   0.3%  33.1KiB         virt_mshv_vtl <virt_mshv_vtl::processor::UhProcessor<virt_mshv_vtl::processor::tdx::TdxB...
0.0%   0.3%  32.5KiB          vmbus_client <vmbus_client::ClientTask<vmbus_client_hcl::MessageSource>>::run::{closure#0}
0.0%   0.3%  29.1KiB        underhill_core <underhill_core::worker::UhVmNetworkSettings>::new_underhill_nic::{closure#0}
0.0%   0.2%  28.8KiB              scsidisk <scsidisk::SimpleScsiDisk as scsi_core::AsyncScsiDisk>::execute_scsi::{clo...
0.0%   0.2%  28.6KiB        underhill_core <underhill_core::worker::UnderhillVmWorker>::new_or_restart::{closure#0}::...
0.0%   0.2%  28.5KiB underhill_attestation underhill_attestation::get_derived_keys::{closure#0}
0.0%   0.2%  27.9KiB        underhill_core underhill_core::run_control::{closure#0}
0.0%   0.2%  27.9KiB        underhill_core underhill_core::main
0.0%   0.2%  27.6KiB                netvsp <netvsp::NetChannel<vmbus_channel::gpadl_ring::GpadlRingMem>>::main_loop::...
0.0%   0.2%  27.3KiB        underhill_core <underhill_core::emuplat::netvsp::HclNetworkVFManagerWorker>::run::{closur...
0.0%   0.2%  26.9KiB        underhill_init underhill_init::do_main
5.7%  90.1%  10.1MiB                       And 27672 smaller methods. Use -n N to show more.
6.4% 100.0%  11.3MiB                       .text section size

[klensy]

Looks similar to rust-lang/rust#146188, in that case should be fixed by #3373, but you can manually set max_level_* and release_max_level_* as in docs https://docs.rs/tracing/latest/tracing/level_filters/index.html