Wasmtime GitHub notifications bot (Oct 12 2022 at 15:31): Wasmtime GitHub notifications bot (Oct 12 2022 at 15:31):fitzgen commented on issue #5049:
Difference in benchmark results after the third commit:
<details>
host-wasm-frames-traps/20 time: [9.1573 µs 9.2173 µs 9.2943 µs] thrpt: [2.1519 Melem/s 2.1698 Melem/s 2.1840 Melem/s] change: time: [-71.950% -71.263% -70.647%] (p = 0.00 < 0.05) thrpt: [+240.68% +247.98% +256.50%] Performance has improved. Found 7 outliers among 100 measurements (7.00%) 1 (1.00%) high mild 6 (6.00%) high severe host-wasm-frames-traps/40 time: [17.594 µs 17.679 µs 17.777 µs] thrpt: [2.2500 Melem/s 2.2626 Melem/s 2.2735 Melem/s] change: time: [-82.311% -82.060% -81.828%] (p = 0.00 < 0.05) thrpt: [+450.31% +457.42% +465.32%] Performance has improved. Found 21 outliers among 100 measurements (21.00%) 12 (12.00%) low severe 2 (2.00%) low mild 3 (3.00%) high mild 4 (4.00%) high severe host-wasm-frames-traps/60 time: [24.421 µs 24.825 µs 25.198 µs] thrpt: [2.3812 Melem/s 2.4169 Melem/s 2.4569 Melem/s] change: time: [-87.209% -86.980% -86.694%] (p = 0.00 < 0.05) thrpt: [+651.54% +668.05% +681.82%] Performance has improved. Found 3 outliers among 100 measurements (3.00%) 2 (2.00%) high mild 1 (1.00%) high severe host-wasm-frames-traps/80 time: [30.406 µs 30.660 µs 31.073 µs] thrpt: [2.5746 Melem/s 2.6092 Melem/s 2.6311 Melem/s] change: time: [-90.168% -90.023% -89.849%] (p = 0.00 < 0.05) thrpt: [+885.12% +902.27% +917.09%] Performance has improved. Found 2 outliers among 100 measurements (2.00%) 2 (2.00%) high mild host-wasm-frames-traps/100 time: [41.574 µs 41.822 µs 42.132 µs] thrpt: [2.3735 Melem/s 2.3911 Melem/s 2.4053 Melem/s] change: time: [-91.218% -91.097% -90.974%] (p = 0.00 < 0.05) thrpt: [+1007.9% +1023.2% +1038.7%] Performance has improved. Found 18 outliers among 100 measurements (18.00%) 7 (7.00%) high mild 11 (11.00%) high severe host-wasm-frames-traps/120 time: [50.096 µs 50.518 µs 51.109 µs] thrpt: [2.3479 Melem/s 2.3754 Melem/s 2.3954 Melem/s] change: time: [-92.489% -92.372% -92.261%] (p = 0.00 < 0.05) thrpt: [+1192.2% +1211.0% +1231.3%] Performance has improved. Found 15 outliers among 100 measurements (15.00%) 9 (9.00%) high mild 6 (6.00%) high severe host-wasm-frames-traps/140 time: [57.252 µs 57.426 µs 57.624 µs] thrpt: [2.4295 Melem/s 2.4379 Melem/s 2.4453 Melem/s] change: time: [-93.581% -93.502% -93.423%] (p = 0.00 < 0.05) thrpt: [+1420.4% +1438.8% +1457.9%] Performance has improved. Found 13 outliers among 100 measurements (13.00%) 6 (6.00%) high mild 7 (7.00%) high severe host-wasm-frames-traps/160 time: [68.391 µs 70.340 µs 72.333 µs] thrpt: [2.2120 Melem/s 2.2747 Melem/s 2.3395 Melem/s] change: time: [-94.214% -94.064% -93.903%] (p = 0.00 < 0.05) thrpt: [+1540.2% +1584.6% +1628.4%] Performance has improved. Found 14 outliers among 100 measurements (14.00%) 6 (6.00%) high mild 8 (8.00%) high severe host-wasm-frames-traps/180 time: [76.005 µs 77.580 µs 79.369 µs] thrpt: [2.2679 Melem/s 2.3202 Melem/s 2.3683 Melem/s] change: time: [-95.074% -94.871% -94.668%] (p = 0.00 < 0.05) thrpt: [+1775.4% +1849.9% +1930.2%] Performance has improved. Found 11 outliers among 100 measurements (11.00%) 6 (6.00%) high mild 5 (5.00%) high severe host-wasm-frames-traps/200 time: [90.825 µs 94.718 µs 98.745 µs] thrpt: [2.0254 Melem/s 2.1115 Melem/s 2.2020 Melem/s] change: time: [-95.291% -95.072% -94.844%] (p = 0.00 < 0.05) thrpt: [+1839.6% +1929.0% +2023.4%] Performance has improved. Found 13 outliers among 100 measurements (13.00%) 6 (6.00%) high mild 7 (7.00%) high severe</details>
Wasmtime GitHub notifications bot (Oct 12 2022 at 16:12):github-actions[bot] commented on issue #5049:
Subscribe to Label Action
cc @peterhuene
<details>
This issue or pull request has been labeled: "wasmtime:api"Thus the following users have been cc'd because of the following labels:
- peterhuene: wasmtime:api
To subscribe or unsubscribe from this label, edit the <code>.github/subscribe-to-label.json</code> configuration file.
Learn more.
</details>
Wasmtime GitHub notifications bot (Oct 12 2022 at 16:13):Stebalien commented on issue #5049:
Thanks for looking into this! Unfortunately, no difference. I tested it here: https://github.com/filecoin-project/ref-fvm/commit/4242e722dfc99e3b5153080be96d2c21f3413dbb (looks like I got the patches correct).
I'll put a reproducer together by next week (have a few deadlines this week).
Wasmtime GitHub notifications bot (Oct 12 2022 at 18:55):fitzgen commented on issue #5049:
@Stebalien to be clear, enabling backtraces will always have some overhead that is proportional to how many frames are on the stack (capturing the stack is
O(frames)) so we shouldn't expect that performance is identical when backtraces are enabled and when they disabled. But comparing performance with this PR vs without this PR should ideally show a marked improvement in performance.Are you seeing identical performance with this patch applied vs without?
If so, how is the trap being triggered? Is it an
unreachablein Wasm, an out-of-bounds memory operation, a host function returningErr(wasmtime::Trap::new(...)), or something else?(Reproducer would still be appreciated, once you have the cycles.)
Wasmtime GitHub notifications bot (Oct 12 2022 at 19:30):Stebalien commented on issue #5049:
Are you seeing identical performance with this patch applied vs without?
Within the margin of error, yes. Basically, this test is 300-400x slower with backtraces enabled.
Is it an unreachable in Wasm, an out-of-bounds memory operation, a host function returning Err(wasmtime::Trap::new(...)), or something else?
The host is returning a
Trapfrom a syscall. Specifically:
- Host returns a Trap.
- Host handles the Trap on the other side of the
func.call.- Host returns to the next wasm instance up the stack.
- The next wasm instance calls back into the host (asking the host to "abort").
- The host returns another trap, go back to step 2.
In other words:
- Host -> Wasm -> Host -> Wasm ... (1000x) ... -> Host (traps) [Z]
- Wasm [W] <- Host [X] <- (Wasm [Y] skipped) <- Host (traps) [Z].
- Wasm [W] -> Host (traps) [X].
- Wasm [U] <- Host [V] <- (Wasm [W] skipped) <- Host (traps) [X].
And so on... Two steps backwards, one step forward, two steps backward, all the way to the top.
(Reproducer would still be appreciated, once you have the cycles.)
I'll also do a bit of profiling myself as well.
Wasmtime GitHub notifications bot (Oct 12 2022 at 19:36):cfallin commented on issue #5049:
The host is returning a
Trapfrom a syscall. Specifically:
- Host returns a Trap.
- Host handles the Trap on the other side of the
func.call.- Host returns to the next wasm instance up the stack.
- The next wasm instance calls back into the host (asking the host to "abort").
- The host returns another trap, go back to step 2.
To clarify, does this mean that for a stack of depth N, there are N traps?
The "quadratic slowdown with backtraces" behavior is completely expected then, from first principles, I think: you're taking N traps, and they have cost 1, 2, 3, ... N frames/levels deep. I don't think there's anything we could do to make this not be quadratic, short of some sort of magical lazily-expanding constant-time stack capture (which we can't do because we don't keep the stack around after the trap fires).
Wasmtime GitHub notifications bot (Oct 12 2022 at 20:30):Stebalien commented on issue #5049:
There's one trap at each level. If these stack traces cover the entire rust stack, not just the wasm module handling the trap, that would make sense.
In that case, would the wasmtime team consider keeping the ability to disable backtraces?
Wasmtime GitHub notifications bot (Oct 13 2022 at 14:20):fitzgen commented on issue #5049:
I think it would make sense to add an optional max number of frames captured in a backtrace, which can be set to zero to completely disable backtraces. Then we can limit the cost of a backtrace from O(frames) to some user-chosen acceptable constant overhead.
Going to go ahead and merge this PR and file a new issue for that config option. I'll cc you on it, @Stebalien.
Wasmtime GitHub notifications bot (Oct 13 2022 at 14:28):fitzgen commented on issue #5049:
I think it would make sense to add an optional max number of frames captured in a backtrace, which can be set to zero to completely disable backtraces. Then we can limit the cost of a backtrace from O(frames) to some user-chosen acceptable constant overhead.
#5052
Last updated: Oct 23 2024 at 20:03 UTC