wasmtime / issue #3523 Huge increase in wasmtime compilation · git-wasmtime

Thanks for the update, I can indeed reproduce the large discrepancy in compile times. What's happening here is that something pathological is being hit in Cranelift, and it's definitely something that we should fix!

Specifically in this wasm file the

<xcm_executor::XcmExecutor<Config> as xcm::v2::traits::ExecuteXcm<<Config as xcm_executor::config::Config>::Call>>::execute_xcm_in_credit

function takes 16s to compile. In that wasm file it's function index 1198 and the mangled name is

_ZN155_$LT$xcm_executor..XcmExecutor$LT$Config$GT$$u20$as$u20$xcm..v2..traits..ExecuteXcm$LT$$LT$Config$u20$as$u20$xcm_executor..config..Config$GT$..Call$GT$$GT$21execute_xcm_in_credit17hf41c2b7a319ac14dE

Extracting just that one function to a wasm module yields extract.wasm.gz and this can be reproduced locally with wamtime compile extract.wasm taking 16-17s locally. The breakdown I see is:

$ RUST_LOG=wasmtime_cranelift ./target/release/wasmtime compile extract.wasm
 DEBUG wasmtime_cranelift::compiler > FuncIndex(989) translated in 16.363414899s
 TRACE wasmtime_cranelift::compiler > FuncIndex(989) timing info
======== ========  ==================================
   Total     Self  Pass
-------- --------  ----------------------------------
   0.320    0.320  Translate WASM function
  16.039    0.025  Compilation passes
   0.001    0.001  Control flow graph
   0.002    0.002  Dominator tree
   0.000    0.000  Loop analysis
   0.001    0.001  Pre-legalization rewriting
   0.004    0.004  Dead code elimination
   0.012    0.012  Global value numbering
   0.036    0.027  Loop invariant code motion
   0.000    0.000  Remove unreachable blocks
   0.246    0.246  Remove constant phi-nodes
   0.188    0.188  VCode lowering
   0.022    0.022  VCode post-register allocation finalization
   0.026    0.026  VCode emission
   0.000    0.000  VCode emission finalization
  15.478   15.478  Register allocation
   0.004    0.004  Binary machine code emission
   0.008    0.008  Layout full renumbering
======== ========  ==================================

There are known pitfalls with our register allocator at this time and plans to move to a better register allocator. My guess is that this is likely to fall into that category of "probably will get fixed", but @cfallin do you think it's worthwhile digging in more here to figure out why something is triggering the slowdown here?

@girazoki and @notlesh in the meantime for your specific use case if you'd like to avoid this slowdown I'd recommend taking a look at

<xcm_executor::XcmExecutor<Config> as xcm::v2::traits::ExecuteXcm<<Config as xcm_executor::config::Config>::Call>>::execute_xcm_in_credit

and trying to simplify it a bit. It's a huge function in the wasm and probably has a ton of stuff #[inline]'d into it which greatly increases the size of the function. It may be the case that adding #[inline(never)] or otherwise removing #[inline] annotations in a few places could improve wasmtime compile times. Nevertheless we should still fix this in Wasmtime, but that's at least a possibility for fixing things in the near future if you're interested.

Stream: git-wasmtime

Topic: wasmtime / issue #3523 Huge increase in wasmtime compilation

Wasmtime GitHub notifications bot (Nov 15 2021 at 19:16):

Wasmtime GitHub notifications bot (Nov 15 2021 at 19:17):

Wasmtime GitHub notifications bot (Nov 15 2021 at 19:27):

Wasmtime GitHub notifications bot (Nov 15 2021 at 19:27):

Wasmtime GitHub notifications bot (Nov 15 2021 at 19:28):

Wasmtime GitHub notifications bot (Nov 15 2021 at 19:54):

Wasmtime GitHub notifications bot (Nov 15 2021 at 20:03):

Wasmtime GitHub notifications bot (Nov 15 2021 at 21:05):

Wasmtime GitHub notifications bot (Nov 15 2021 at 21:11):

Wasmtime GitHub notifications bot (Nov 15 2021 at 21:11):