Add some debug logging for timing in module compiles (#3417)

* Add some debug logging for timing in module compiles

This is sometimes helpful when debugging slow compiles from fuzz bugs or
similar.

* Fix total duration calculation to not double-count

Cargo.lock

@@ -3514,6 +3514,7 @@ dependencies = [
  "cranelift-native",
  "cranelift-wasm",
  "gimli",
+ "log",
  "more-asserts",
  "object",
  "target-lexicon",

cranelift/codegen/src/timing.rs

@@ -130,6 +130,13 @@ mod details {
         pass: [PassTime; NUM_PASSES],
     }
 
+    impl PassTimes {
+        /// Returns the total amount of time taken by all the passes measured.
+        pub fn total(&self) -> Duration {
+            self.pass.iter().map(|p| p.total - p.child).sum()
+        }
+    }
+
     impl Default for PassTimes {
         fn default() -> Self {
             Self {

crates/cranelift/Cargo.toml

@@ -12,6 +12,7 @@ edition = "2018"
 
 [dependencies]
 anyhow = "1.0"
+log = "0.4"
 wasmtime-environ = { path = "../environ", version = "0.30.0" }
 cranelift-wasm = { path = "../../cranelift/wasm", version = "0.77.0" }
 cranelift-codegen = { path = "../../cranelift/codegen", version = "0.77.0" }

crates/cranelift/src/compiler.rs

@@ -194,6 +194,10 @@ impl wasmtime_environ::Compiler for Compiler {
             None
         };
 
+        let timing = cranelift_codegen::timing::take_current();
+        log::debug!("{:?} translated in {:?}", func_index, timing.total());
+        log::trace!("{:?} timing info\n{}", func_index, timing);
+
         let length = u32::try_from(code_buf.len()).unwrap();
         Ok(Box::new(CompiledFunction {
             body: code_buf,