1617666 - uBlock Origin internal benchmark is ~10 times slower with eagerEvaluation enabled

Status: RESOLVED FIXED

(DevTools :: Console, defect, P3)

Description

[gwarser]

What were you doing?

uBlock Origin internal benchmark run from devtools-toolbox console is ~10 times slower after https://bugzilla.mozilla.org/show_bug.cgi?id=1603356

Found by mozregression: https://hg.mozilla.org/integration/autoland/pushloghtml?fromchange=4abd12f068cf2ffcc4beb6f652ab8a8995443cc3&tochange=525336d7af5157b773fb6ab51777f5bd70ec1138

What happened?

µBlock.staticNetFilteringEngine.benchmark();
[uBO] Loading benchmark dataset... console.js:26:40
[uBO] Parsing benchmark dataset... console.js:26:40
[uBO] Benchmarking staticNetFilteringEngine.matchString()... console.js:26:40
[uBO] Evaluated 230363 requests in 73887 ms console.js:26:40
[uBO] 	Average: 0.321 ms per request console.js:26:40

What should have happened?

µBlock.staticNetFilteringEngine.benchmark();
[uBO] Benchmarking staticNetFilteringEngine.matchString()... console.js:26:40
Promise { <state>: "pending" }
[uBO] Evaluated 230363 requests in 8450 ms console.js:26:40
[uBO] 	Average: 0.037 ms per request console.js:26:40

Anything else we should know?

How to run this benchmark:

• fresh Nightly build
• install latest dev version of uBO from https://github.com/gorhill/uBlock/releases/ (it's easier to setup that way, can also be run in older uBO versions with more effort - custom build)
• open uBO Preferences (for ex. from about:addons, "..." button menu)
• enable option "I am an advanced user (required reading)"
• click small gear icon after "I am an advanced user (required reading)" string
• in new window set:
  • benchmarkDatasetURL to https://cdn.cliqz.com/adblocking/requests_top500.json.gz
  • consoleLogLevel to info - to actually see something printed in console
• open about:devtools-toolbox?type=extension&id=uBlock0%40raymondhill.net
• run in console: µBlock.staticNetFilteringEngine.benchmark();

Toggling devtools.webconsole.input.eagerEvaluation requires devtools-toolbox to be reloaded.

Comment 1

[:Harald Kirschner :digitarald]

Thanks for filing the extra bug.

Could you record a profile while running the benchmark using profiler.firefox.com (enable in Nightly via DevTools > Enable Profile Toolbar icon)? I will do so on my side as well.

Comment 2

[:Harald Kirschner :digitarald]

(Sorry, the last message was for the reporter.)

Comment 3

[:Harald Kirschner :digitarald]

I see a 7-9x slowdown:

Profile with instant eval on: https://perfht.ml/3c68eRB https://perfht.ml/2Vkyl1g

[uBO] Evaluated 230363 requests in 22327 ms console.js:26:40
[uBO] 	Average: 0.097 ms per request

Without instant eval: https://perfht.ml/2T4C6EY

[uBO] Evaluated 230363 requests in 3163 ms console.js:26:40
[uBO] 	Average: 0.014 ms per request

Comparison fast/slow: https://perfht.ml/2Ta3XUu

This shows JIT-related stacks as most impacted, exploding the time for

_tokenize
…
js::jit::Compile(JSContext*, JS::Handle<JSScript*>, js::jit::BaselineFrame*, unsigned int, unsigned char*, bool)
js::jit::TrackIonAbort(JSContext*, JSScript*, unsigned char*, char const*)
js::jit::JitcodeGlobalTable::lookupInternal(void*)

Logan, does eager eval change the JIT behavior in some way?

Comment 4

[gwarser]

With eagerEvaluation: https://perfht.ml/38X9Zyf
Two runs without eagerEvaluation: https://perfht.ml/38Xa595

Comment 5

[Logan Smyth [:loganfsmyth]]

Assigning to myself to investigate. I'll report back once I have a clear picture of the problem.

Comment 6

[Logan Smyth [:loganfsmyth]]

Attachment: Bug 1617666 - Clear and then re-add debuggees to avoid eval perf issues. r=jlast!

Comment 7

[Logan Smyth [:loganfsmyth]]

Definitely super edge-casey behavior. I had no idea that this was even behavior we had to worry about triggering, so I'm not surprised that we tripped over it.

Comment 8

[Logan Smyth [:loganfsmyth]]

Attachment: Bug 1617666 - Use a separate Debugger to improve performance of eval. r=jlast!

The SpiderMonkey Debugger API maintains a flag per-debuggee that tracks whether
the SpiderMonkey should notify the debugger when new frames are entered, and
whether the JIT scripts associated with the debuggee realm have been compiled
with debug instrumentation. To avoid constantly needing to clear and regenerate
JIT scripts, the flag is permanently enabled once "onEnterFrame" has been used
with a given Debugger instance, and when the flag is enabled, there is a
runtime performance cost.

This runtime cost is what is causing the performance regression here, so to
ensure that the flag is cleared at the end of a given instant-eval, we only
set "onEnterFrame" on a new temporary Debugger instance, instead of setting
it on th existing persistent Debugger instance.

Comment 9

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/4fb5e268cf74
Use a separate Debugger to improve performance of eval. r=jlast

Comment 10

[Bogdan Tara[:bogdan_tara | bogdant]]

https://hg.mozilla.org/mozilla-central/rev/4fb5e268cf74