WASM huge performance regression

[davxy]

While re-running the Sassafras benches I noticed a slowdown for the whole set of (Sassafras) benchmarks.

After bisection I found that it started with #2217

To easily reproduce/test I created a branch from the commit which introduced the regression: https://github.com/davxy/polkadot-sdk/tree/davxy-perfs-degradation-poc

This contains the minimal code to trigger it... mostly a patch to the do_something extrinsic for the node-template to execute some code which computes a bandersnatch ring verifier.

$ cargo build -p node-template --release --features runtime-benchmarks
$ ./benchmark.sh
...
Time ~=   207800 µs

The degradation is not noticed with

$ WASM_BUILD_STD=0 cargo build -p node-template --release --features runtime-benchmarks
$ ./benchmark.sh
..
Time ~=    16070 µs

These timings badly impacts Sassafras as for tickets verification we go from the realm of ms to almost seconds, which probably is not acceptable.

cc @koute @bkchr

[bkchr]

Please run the benchmarks using the production profile. Does that help?

[davxy]

EDIT: I haven't update my script to point toproduction folder. So production doesn't have the issue. Only release

[davxy]

I also suspect that this may affect the Weight of the more involved extrinsics already used in prod

[burdges]

Just a few possible regression sources:

Could the recompiled std break the fallback mechanism our forked curves use, thereby invoking direct curve arithmetic instead of the host calls?

Could the recompiled std reduce allocation speed? We do have some allocation inside arkworks, not anything in a loop afaik, but maybe if your benchmark runs in a loop it'd add up.

[koute]

This is really weird. Compiling the std should definitely not have regressed the performance. This smells like a bug to me.

I'll take a look at this. If there will be a quick fix then I'll do that; if not I'll make a PR to flip the WASM_BUILD_STD default the other way around.

[koute]

(1) production profile, precompiled std:

Time ~=    16530
              µs

(2) production profile, compiling std:

Time ~=    16230
              µs

(3) release profile, compiling std

Time ~=    23050
              µs

Built with:

# (1)
WASM_BUILD_STD=0 cargo build -p node-template --profile=production --features runtime-benchmarks

# (2)
cargo build -p node-template --profile=production --features runtime-benchmarks

# (3)
cargo build -p node-template --release --features runtime-benchmarks

All builds were done fresh, where for (1) I removed the target/production after the first build.

My rustc:

$ rustc --version
rustc 1.75.0-nightly (edf0b1db0 2023-11-10)

@davxy I'm afraid I can't reproduce your issue. Can you give me your exact rustc version?

[davxy]

❯ rustc --version
rustc 1.74.0 (79e9716c9 2023-11-13)

I see that you used nightly. Please retry with stable.

I tried with nightly as well and indeed it doesn't have the problem

❯ rustc +nightly --version
rustc 1.76.0-nightly (a1a37735c 2023-11-23)

[davxy]

@koute please also try with a more complete benchmark which is a bit slower also on nightly

Branch: https://github.com/davxy/polkadot-sdk/tree/restore-sassafras-good-shape

Benchmarks: Sassafras tickets submission (x is the number of tickets)

Stable (1.74)

$ cargo build -p node-sassafras --release --features runtime-benchmarks
$ ./benchmark submit_tickets
...
Time ~=   705900
    + x    34260
              µs

Stable (1.74) + WASM_BUILD_STD=0

$ WASM_BUILD_STD=0 cargo build -p node-sassafras --release --features runtime-benchmarks
$ ./benchmark submit_tickets
...
Time ~=    68550
    + x     3865
              µs

Nightly (1.76)

$ cargo +nightly build -p node-sassafras --release --features runtime-benchmarks
$ ./benchmark submit_tickets
...
Time ~=    90390
    + x     5048
              µs

Nightly (1.76) + WASM_BUILD_STD=0

$ WASM_BUILD_STD=0 cargo +nightly build -p node-sassafras --release --features runtime-benchmarks
$ ./benchmark submit_tickets
Time ~=    67000
    + x     3910
                  µs

[koute]

I see that you used nightly. Please retry with stable.

Still can't reproduce it, even on stable.

$ CARGO_TARGET_DIR=target/build-std-false WASM_BUILD_STD=0 rustup run 1.74.0 cargo build -p node-template --profile=production --features runtime-benchmarks
$ CARGO_TARGET_DIR=target/build-std-true WASM_BUILD_STD=1 rustup run 1.74.0 cargo build -p node-template --profile=production --features runtime-benchmarks

$ binary="./target/build-std-false/production/node-template" ./benchmark.sh
Time ~=    16140
              µs

$ binary="./target/build-std-true/production/node-template" ./benchmark.sh
Time ~=    16480
              µs

(I commented out the binary=... line in your script so that I can set the path through an environment variable.)

And just to verify, the std does get built in one case and not in the other:

$ ls target/build-std-false/production/wbuild/node-template-runtime/target/wasm32-unknown-unknown/production/build | rg std | wc -l
0
$ ls target/build-std-true/production/wbuild/node-template-runtime/target/wasm32-unknown-unknown/production/build | rg std | wc -l
1

The blobs are different in size, and the build-std one is smaller (which is as expected):

$ stat target/build-std-true/production/wbuild/node-template-runtime/node_template_runtime.wasm | rg "Size: \d+" -o
Size: 5620625
$ stat target/build-std-false/production/wbuild/node-template-runtime/node_template_runtime.wasm | rg "Size: \d+" -o
Size: 5872569

And verify that it was compiled with stable:

$ cat target/build-std-true/production/wbuild/node-template-runtime/target/.rustc_info.json | rg -o "rustc \S+ .+?\)"
rustc 1.74.0 (79e9716c9 2023-11-13)
$ cat target/build-std-false/production/wbuild/node-template-runtime/target/.rustc_info.json | rg -o "rustc \S+ .+?\)"
rustc 1.74.0 (79e9716c9 2023-11-13)

[koute]

I managed to reproduce the issue for the second benchmark which @davxy posted, but it needs to be compiled as release.

Build type	Build std?	Weight	Size of .wasm
release	No	69730	7203988
release	Yes	744300	6960520
production	No	69740	6269825
production	Yes	69240	6015984

I'm guessing something inside of std is probably not getting inlined, which craters the performance, and the prebuilt stds are not affected because they're built with LTO?

[davxy]

For the record: current nightly doesn't have the issue in release as well

Bisection of nightly versions allowed to determine from which version they solved the issue.

(for submit_tickets sassafras benchmark):

• nightly-2023-10-19 => 80600 + 5226·x µs (GOOD)
• nightly-2023-10-18 => 681000 + 35460·x µs (VERY BAD)

After further analysis of at the rust log I strongly suspect that:

• this is the commit: rust-lang/rust@5d5edf0
• and this is the PR Automatically enable cross-crate inlining for small functions rust-lang/rust#116505

So next stable will probably benefit from the speedup without explicit have to enable lto

[davxy]

@koute I tried the beta channel.

• 1.75.0-beta.5 (1a06ac5b5 2023-12-01) => 82890 + 5102·x µs

So next stable will probably benefit from the speedup without explicit have to enable lto

So in the next stable (1.75) we can definitely benefit of the speedup

---

Let's keep this open until 28-dec when the new stable is released

[bkchr]

I don't see any reason to keep this issue open. Especially as we run benchmarks using the production profile.