Enable debug assertions in tests

[itowlson]

Fixes #3632.

[itowlson]

@alexcrichton I'm not sure if this was what you intended? I'm seeing some tests time out, likely during Wasm loading, which is possibly a flake - not all guests are hitting it - but could also be down to the longer Wasm preparation times we always see with debug builds (although, why would that not affect other tests). Did I mess up a setting?

[lann]

This is the change I asked for but the timeouts are not what I hoped for.

A smaller fix for #3632 could be:

Cargo.toml:

Ref: https://doc.rust-lang.org/cargo/reference/profiles.html#dev

# When running many tests (such as `make test-integration-full`), test execution
# seems to dominate run time. This profile optimizes for execution time over
# build time while retaining debug assertions.
[profile.bulk-test]
inherits = "release"
debug-assertions = true
overflow-checks = true

and then the Makefile rules would use --profile bulk-test.

There is a chance that one of those debug assertion features is the cause of the slowdown but I would be very surprised if that were the case.

Anyway @alexcrichton certainly has a better intuition for these things than I do so I'd like to see what he has to say.

[alexcrichton]

This is definitely what I was thinking, yeah. Doing some profiling locally most of the hot functions are related to tracing-* so I also attempted:

diff --git a/Cargo.toml b/Cargo.toml
index c68df9a5..ce228001 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -218,3 +218,6 @@ blocks_in_conditions = "allow"
 [[bin]]
 name = "spin"
 path = "src/bin/spin.rs"
+
+[profile.dev.package."*"]
+opt-level = 2

which in theory optimizes all dependencies of spin, but not any workspace members of spin (largely what's desired here I believe). Despite this logging/tracing functions are still dominating the entire profile:

  Overhead  Command  Shared Object      Symbol
+    7.40%  spin     spin               [.] <core::slice::iter::Iter<&str> as core::iter::traits::iterator::Iterator>::position::<<tracing_core::field::FieldS▒
+    3.98%  spin     spin               [.] tracing_log::dispatch_record::{closure#0}                                                                         ◆
+    2.89%  spin     spin               [.] <str as core::cmp::PartialEq>::eq                                                                                 ▒
+    2.72%  spin     spin               [.] <&str as core::cmp::PartialEq>::eq                                                                                ▒
+    2.70%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::FILTERING::{K#0}::{closure#1} as core::ops::function::FnOnce<(core::op▒
+    2.70%  spin     spin               [.] <tracing_log::log_tracer::LogTracer as log::Log>::enabled                                                         ▒
+    2.47%  spin     spin               [.] <tracing_core::field::FieldSet>::field::<str>::{closure#0}                                                        ▒
+    2.03%  spin     spin               [.] tracing_log::loglevel_to_cs                                                                                       ▒
+    2.01%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<tracing_subscriber::fmt::fmt_layer::Layer<tracing_subscriber:▒
+    1.99%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<spin_telemetry::alert_in_dev::CommandLineAlertingLayer, traci▒
+    1.91%  spin     spin               [.] <tracing_core::field::FieldSet>::field::<str>                                                                     ▒
+    1.82%  spin     spin               [.] <std::thread::local::LocalKey<tracing_subscriber::filter::layer_filters::FilterState>>::try_with::<<tracing_subscr▒
+    1.73%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::FilterState>::set                                                     ▒
+    1.60%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<spin_telemetry::alert_in_dev::CommandLineAlertingLayer, traci▒
+    1.54%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<spin_telemetry::alert_in_dev::CommandLineAlertingLayer, traci▒
+    1.51%  spin     spin               [.] <std::thread::local::LocalKey<tracing_subscriber::filter::layer_filters::FilterState>>::try_with::<<tracing_subscr▒
+    1.39%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::FilterState>::did_enable::<<tracing_subscriber::filter::layer_filters:▒
+    1.37%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<tracing_subscriber::fmt::fmt_layer::Layer<tracing_subscriber:▒
+    1.35%  spin     spin               [.] <tracing_subscriber::layer::layered::Layered<core::option::Option<tracing_opentelemetry::metrics::MetricsLayer<tra▒
+    1.30%  spin     spin               [.] <std::thread::local::LocalKey<tracing_subscriber::filter::layer_filters::FilterState>>::try_with::<<tracing_subscr▒
+    1.25%  spin     spin               [.] <std::thread::local::LocalKey<tracing_subscriber::filter::layer_filters::FilterState>>::try_with::<<tracing_subscr▒
+    1.18%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<tracing_subscriber::fmt::fmt_layer::Layer<tracing_subscriber:▒
+    1.18%  spin     spin               [.] <tracing_subscriber::layer::layered::Layered<tracing_subscriber::filter::layer_filters::Filtered<tracing_subscribe▒
+    1.16%  spin     spin               [.] <std::thread::local::LocalKey<tracing_subscriber::filter::layer_filters::FilterState>>::try_with::<<tracing_subscr▒
+    1.15%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::Filtered<tracing_subscriber::fmt::fmt_layer::Layer<tracing_subscriber:▒
+    1.14%  spin     spin               [.] <tracing_subscriber::filter::layer_filters::FilterState>::and::<<tracing_subscriber::filter::layer_filters::Filter▒
     1.12%  spin     spin               [.] <tracing_subscriber::layer::layered::Layered<tracing_subscriber::filter::layer_filters::Filtered<spin_telemetry::a▒
+    1.08%  spin     spin               [.] tracing_subscriber::filter::layer_filters::FILTERING::{K#0}::{closure#1}                                          ▒
+    1.05%  spin     spin               [.] <tracing_subscriber::registry::sharded::Registry as tracing_core::subscriber::Subscriber>::event_enabled          ▒
     1.02%  spin     spin               [.] <tracing_subscriber::layer::layered::Layered<core::option::Option<tracing_subscriber::filter::layer_filters::Filte▒
+    1.02%  spin     spin               [.] <regalloc2::ion::data_structures::Env<cranelift_codegen::machinst::vcode::VCode<cranelift_codegen::isa::x64::lower▒
-    1.01%  spin     spin               [.] <std::thread::local::LocalKey<tracing_subscriber::filter::layer_filters::FilterState>>::try_with::<<tracing_subscr▒

Is there anything special about logging in Spin in tests? For example is logging enabled specifically at a higher level during tests? This looks like a bazillion log statements coming out of Cranelift and pretty inefficient processing of them (as one would expect in debug mode)

With this:

diff --git a/Cargo.toml b/Cargo.toml
index c68df9a5..8323236c 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -218,3 +218,8 @@ blocks_in_conditions = "allow"
 [[bin]]
 name = "spin"
 path = "src/bin/spin.rs"
+
+[profile.dev.package."*"]
+opt-level = 2
+[profile.dev.package.spin-telemetry]
+opt-level = 2

I can't copy the pid fast enough into perf to see what's still high up in the profile so that may be the winning configuration? (testing empirically went from ~20s to ~7s with that config locally)

[itowlson]

Is there anything special about logging in Spin in tests? For example is logging enabled specifically at a higher level during tests?

Looking at the Makefile (

spin/Makefile

Line 1 in 90dcf45

LOG_LEVEL_VAR ?= RUST_LOG=spin=trace

) it appears to be testing with RUST_LOG=spin=trace, so Spin's own tracing is gonna be pretty verbose. (I see one test that turns logging off, but generally it's this.) But Cranelift and other dependency crates should be operating at default log level with that I think?

Anyway if the goal at hand is to turn on debug assertions, then I reckon maybe I'll roll this back and adopt @lann's "turn on debug assertions" solution which seems... uh... more directly aligned to the goal. But if we want to speed up our tests then yeah that seems a worthy goal too!

[alexcrichton]

Ah ok makes sense w.r.t. logging yeah, once anything is set to trace the fast-path "is this log disabled" no longer kicks in and the filter has to go to the regex/string matching and that gets real slow in debug mode. In any case the PR as-is I think is fine, although I might recommend inheriting from dev to inherit incrementality and debuginfo while setting opt-level=2 which should be plenty for speed

[lann]

This (probably) explains at least part of the problem: https://github.com/bytecodealliance/wasmtime/blob/790bc4928077915304e5d658fc34b0625348f281/cranelift/codegen/src/lib.rs#L116

Cranelift uses debug_assertions as a signal that you are debugging and therefore want maximum verbosity.