Cranelift: ISLE mid-end performance regression (up to -66.08%)

[bongjunj]

Hi,

I performance-tested a no-opt version of Cranelift without ISLE mid-end optimizations. (You can confirmed this at prosyslab@c0df585)

Compared to the latest version of upstream Cranelift, surprisingly, the no-opt version produced a significantly faster x86_64 code for blake3, keccak, xchacha20. This experiment is conducted using the sightglass-cli.

Given that only mid-end rules are removed, some codegen backend might causing problem interacting with the mid-end. I want to investigate this problem, but I'm completely lost which part to look at first. Any comments will be appreciated.

Here is the demonstration:

> cargo run --release -- benchmark benchmarks/blake3-scalar/benchmark.wasm --engine engines/wasmtime/v-main/libengine.so engines/wasmtime/v-no-opts/libengine.so --pin
    Finished `release` profile [optimized] target(s) in 0.08s
     Running `target/release/sightglass-cli benchmark benchmarks/blake3-scalar/benchmark.wasm --engine engines/wasmtime/v-main/libengine.so engines/wasmtime/v-no-opts/libengine.so --pin`

execution :: cycles :: benchmarks/blake3-scalar/benchmark.wasm

  Δ = 502562.18 ± 4271.59 (confidence = 99%)

  no-opts/libengine.so is 2.55x to 2.58x faster than main/libengine.so!

  [816778 823363.48 880808] main/libengine.so
  [315506 320801.30 460046] no-opts/libengine.so

compilation :: cycles :: benchmarks/blake3-scalar/benchmark.wasm

  Δ = 51372480.98 ± 1109163.62 (confidence = 99%)

  no-opts/libengine.so is 1.19x to 1.20x faster than main/libengine.so!

  [310860540 313559414.86 330384818] main/libengine.so
  [260245364 262186933.88 278160088] no-opts/libengine.so

instantiation :: cycles :: benchmarks/blake3-scalar/benchmark.wasm

  Δ = 17444.42 ± 10445.70 (confidence = 99%)

  no-opts/libengine.so is 1.06x to 1.23x faster than main/libengine.so!

  [90902 137381.98 258206] main/libengine.so
  [87766 119937.56 198140] no-opts/libengine.so

Plus, here are some data for other benchmarks.
--iterations-per-process 10 --benchmark-phase execution ----pin is used.

bench	v-no-opts	base	speedup
blake3-scalar	320,225	868,750	-63.14%
blake3-simd	320,689	945,427	-66.08%
bz2	88,887,466	86,904,121	2.28%
pulldown-cmark	6,630,447	6,705,562	-1.12%
regex	209,902,394	211,477,705	-0.74%
shootout-base64	383,700,851	352,817,318	8.75%
shootout-keccak	25,589,899	49,540,506	-48.35%
shootout-xchacha20	4,489,570	4,816,315	-6.78%
spidermonkey	644,434,235	627,374,660	2.72%

[cfallin]

Hi @bongjunj -- thanks for reporting this! The place I would start is profiling to find the hottest inner loops, then comparing the disassembly of these loops before-and-after. That should help us triage the overall kind of problem -- whether it is code scheduling, or bad regalloc, or poor choice of instruction, or something else...

[bongjunj]

@cfallin thanks! working on the triage.

[alexcrichton]

I can pretty easily reproduce this myself cherry-picking the commit @bongjunj mentioned. Sightglass is producing surprising results for me though. One run yields

execution :: cycles :: ./benchmarks/blake3-simd/benchmark.wasm

  No difference in performance.

  [165008 555680.24 1110872] less-isle.so
  [371539 548436.46 1682729] main.so

a few runs later is

execution :: cycles :: ./benchmarks/blake3-simd/benchmark.wasm

  Δ = 147722.45 ± 92286.49 (confidence = 99%)

  main.so is 1.13x to 1.55x faster than less-isle.so!

  [167456 580352.29 1502815] less-isle.so
  [363903 432629.84 590110] main.so

passing --pin shows

execution :: cycles :: ./benchmarks/blake3-simd/benchmark.wasm

  Δ = 311980.36 ± 2354.27 (confidence = 99%)

  less-isle.so is 2.18x to 2.19x faster than main.so!

  [259525 263320.66 327692] less-isle.so
  [569582 575301.02 595577] main.so

running with taskset 0x1 shows

execution :: cycles :: ./benchmarks/blake3-simd/benchmark.wasm

  Δ = 200594.18 ± 2696.25 (confidence = 99%)

  less-isle.so is 2.18x to 2.21x faster than main.so!

  [162200 167555.71 209294] less-isle.so
  [363482 368149.89 400345] main.so

I don't really know what to make of this. My machine has P and E cores which seems like it might be factoring in.

I made custom builds with jitdump turned on and ran with perf record -k mono plus --iterations-per-process cranked way up. All I got though was that wasm[0]::function[8] was a hot function with ~41% in the less-isle.so profile and ~61% in the main.so profile. It's a massive function with no apparent loops.

I don't know what's going on here myself.

[alexcrichton]

Hm well the hot function is this one which is a massive function with zero control flow. That being said I could see egraphs deoptimizing this function in terms of instruction scheduling since we've seen pessimistic results in the past, so this might be an example of an overly-pessimistic case of instruction scheduling.

[bongjunj]

@alexcrichton Can you share the workflow of your using jitdump and perf? Any existing docs will be helpful.

---

Just running perf seems not working.

perf record -k mono target/release/sightglass-cli benchmark --engine=engines/wasmtime/libengine.so --engine-flags=" --profile=jitdump" --iterations-per-process=1 --measure=perf-counters benchmarks/blake3-scalar/benchmark.wasm

[cfallin]

There is definitely something going on with function 8: the stack frame (grep for sub $N, %rsp in disassembly) is 0x130 bytes if I disable all opt rewrites (remove the call to constructor_simplify in the egraph pass) and 0x6b0 bytes in the unmodified run. The result is that the function body has a whole bunch more spills/reloads. Something is causing a lot more register pressure; isel is a plausible hypothesis there. I'll dig a bit more...

[cfallin]

Here are the no opt rewrites (but still GVN/alias/LICM) and full main branch opt CLIF dumps for function 8 (wasmtime compile --emit-clif dir foo.wat then take wasm[0]--function[8].clif from the directory).

The "optimized" variant is about twice as long (!).

There's a repeating rewrite pattern that seems to be happening that is a sort of reassociation of a 3-input add sequence -- in the baseline we have

v34 = iadd v27, v33
... [ lots of intermediate insts ] ...
v43 = iadd v34, v42
v44 = ... v43 ...

and in opt we have

... [ lots of intermediate insts ] ...
v1242 = iadd v33, v42
v1243 = iadd v27, v1242
v44 = ... v1243 ...

So we've (i) needlessly reassociated (v27 + v33) + v42 into v27 + (v33 + v42) (none of these are iconsts) and (ii) sunk one of the adds. The former is weird but "shrug". The latter is painful for register pressure: if means we have three live values over "lots of intermediate insts" rather than two.

Better inst scheduling integrated with regalloc would solve that (but, NP-hard problem about which at least one PhD thesis has been written); or alternately, we could "not fix what's not broken" and just avoid the rewrite.

The reassociation seems to go more haywire further down; looking at a diff (diff -u base.clif opt.clif) things are more-or-less 1-for-1 trades early on, but lots of extra iadds later.

I'll dig into the reassociation rules we have and see if I can figure out what's happening!

[cfallin]

OK, it seems that the reassociation rules added in #7466 are the issue. If I comment those out, I get this CLIF, and the compiled function body has a stack frame size of 0x130 bytes again.

cc @fitzgen -- it looks like there wasn't any data posted on that PR; did you have benchmarking results at the time? Mind benchmarking with/without those rules (and I guess the similar followups in #8518 as well)?

[alexcrichton]

Can you share the workflow of your using jitdump and perf?

I applied this diff:

diff --git a/crates/bench-api/src/lib.rs b/crates/bench-api/src/lib.rs
index 86c99c8c98..8a5180ca5e 100644
--- a/crates/bench-api/src/lib.rs
+++ b/crates/bench-api/src/lib.rs
@@ -423,6 +423,7 @@ impl BenchState {
         let mut config = options.config(None)?;
         // NB: always disable the compilation cache.
         config.cache(None);
+        config.profiler(wasmtime::ProfilingStrategy::JitDump);
         let engine = Engine::new(&config)?;
         let mut linker = Linker::<HostState>::new(&engine);

and then I ran:

$ taskset 0x1 perf record -k mono ./target/release/sightglass-cli benchmark -e ./less-isle.so --benchmark-phase execution ./benchmarks/blake3-simd/benchmark.wasm --iterations-per-process 100000

after awhile I ctrl-c'd it and followed these instructions to process the profile

[fitzgen]

Reverted the offending rewrite in #12116 -- could someone re-run these benchmarks on main and report whether everything is resolved or not now? Thanks!

[cfallin]

Here are the benchmarks that had the biggest drops no-rules to rules above:

execution :: cycles :: benchmarks/shootout/shootout-keccak.wasm

  Δ = 4097364.22 ± 837090.89 (confidence = 99%)

  no-rules.so is 1.14x to 1.21x faster than main.so!

  [26507651 27605359.73 36644170] main.so
  [22595511 23507995.51 29631085] no-rules.so

execution :: cycles :: benchmarks/shootout/shootout-xchacha20.wasm

  Δ = 16237.66 ± 10867.13 (confidence = 99%)

  main.so is 1.00x to 1.01x faster than no-rules.so!

  [2634524 2662033.25 2766405] main.so
  [2645145 2678270.91 2835592] no-rules.so

execution :: cycles :: benchmarks/blake3-scalar/benchmark.wasm

  No difference in performance.

  [207174 209371.73 231598] main.so
  [207346 210394.27 257140] no-rules.so

execution :: cycles :: benchmarks/blake3-simd/benchmark.wasm

  No difference in performance.

  [208507 212511.59 232974] main.so
  [208421 212331.42 290723] no-rules.so

So keccak is still weird, but "only" 14-21% slower rather than 48%. Giant drops in blake3-* went away entirely.

[alexcrichton]

I also see (consistently) a 20% slowdown of shootout-keccak. That is, deleting all the ISLE bits makes shootout-keccak faster. Local profiling shows in both profiles 98% of the time is spent in the keccak_core function which looks similar to the blake3 one