793345 - Code executed with Debugger.executeInGlobalWithBindings (Scratchpad or Webconsole) runs 10x - 80x slower than the same code in a script tag

Status: REOPENED

(Core :: JavaScript Engine: JIT, defect, P3)

Description

[Jared Wein [:jaws] (please needinfo? me)]

Attachment: HTML file for reproducing the bug

STR:
Open the attached HTML file and view the console. You should see performance timings for the four JS micro-benchmarks.
Open the Scratchpad and copy/paste the JS into the Scratchpad
Hit Ctrl+L

Check the console for the Scratchpad timings.

The scratchpad timings are slower, but in particular the second loop two orders of magnitude slower.

Comment 1

[Anton Kovalyov (:anton)]

It's even worse on my computer—while running attached JS from Scratchpad I hit "unresponsive script" twice.

Comment 2

[Brandon Benvie [:benvie]]

This is probably due to the Debugger being attached to the window (this performance drop is still seen after bug 825039 landed). You can see the same performance drop in the webconsole if you do `console.dir(this)` and then run the benchmarks code in the console. Going to mark this invalid because this is expected and there's no way to work around it (a Debugged target is always going to be slow path code).

Comment 3

[Dave Camp (:dcamp)]

If you aren't expecting to pause execution (as with a breakpoint/debugger statement) you shouldn't have to leave the page in debugging mode, right?  We shouldn't need debug mode to do simple variable inspection.

Comment 4

[Brandon Benvie [:benvie]]

Code executed in the webconsole suffers from this as well, even without looking at the window in the VariablesView. Renaming this bug to more accurately reflect the problem.

Comment 5

[Alexandre Poirot [:ochameau]]

Still reproducing using the attached document.
The webconsole ends up calling Debugger.evalInGlobalWithBindings, could it be the reason why console evaluation are slower??

Comment 6

[Brian Grinstead [:bgrins]]

I found an interesting performance issue when looking into this bug.  If code passed into Debugger.evalInGlobalWithBindings is happening inside a function call it's much faster than if I execute the same code directly.  As an example (which can be tested by pasting the following code into the webconsole or calling evalInGlobalWithBindings directly).

  (function() {
    var now = Date.now();
    for (var i =0; i < 10000000; i++) { }
    console.log('loop took ' + (Date.now() - now) + ' ms');
  })(); // Takes ~4ms

Execute the same code without any function calls:

  var now = Date.now();
  for (var i =0; i < 100000000; i++) { }
  console.log('loop took ' + (Date.now() - now) + ' ms');
  // Takes ~6948ms

Jim, any ideas what would cause this dropoff and/or ideas how we could fix it?

Comment 7

[Brian Grinstead [:bgrins]]

(In reply to Brian Grinstead [:bgrins] from comment #6)
> Execute the same code without any function calls:
> 
>   var now = Date.now();
>   for (var i =0; i < 100000000; i++) { }
>   console.log('loop took ' + (Date.now() - now) + ' ms');
>   // Takes ~6948ms

There was a copy/paste mistake with the number of loop iterations.  It should have been the same as the example above:

  var now = Date.now();
  for (var i =0; i < 10000000; i++) { }
  console.log('loop took ' + (Date.now() - now) + ' ms');

Comment 8

[Brian Grinstead [:bgrins]]

Ah, another typo.. I meant "executeInGlobalWithBindings" not evalInGlobalWithBindings.  Specifically for the webconsole, I'm talking about this call: https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/webconsole.js#1279

Comment 9

[Jim Blandy :jimb]

I don't understand the influences on code generation too well. Shu-yu Guo has done a lot of work on ameliorating Debugger's effect on performance. Shu, would you be willing to look into this?

Comment 10

[Shu-yu Guo [:shu]]

I'd guess we aren't OSRing for one reason or another. I can take a look next week sometime.

Comment 11

[Shu-yu Guo [:shu]]

It's probably something dumb like the loop on the top level means it's executing in a Debugger eval frame, which is always marked as a debuggee frame and thus is blacklisted for all JITs and don't get OSRed.

Comment 12

[Shu-yu Guo [:shu]]

(In reply to Brian Grinstead [:bgrins] from comment #8)
> Ah, another typo.. I meant "executeInGlobalWithBindings" not
> evalInGlobalWithBindings.  Specifically for the webconsole, I'm talking
> about this call:
> https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/
> webconsole.js#1279

executeInGlobalWithBindings is slow because of the Bindings part, which injects a non-syntactic scope object onto the scope chain. Ion does not compile global scripts with non-syntactic scope chains currently because---and I don't remember very well here---I was trying to land global lexical scope work and non-syntactic scope chains were just not a performance priority.

They still aren't, but this use case does up its priority a bit. I won't get around to looking at lifting this restriction any time soon, but I'll try to get to it eventually.

Comment 14

[Liz Henry (:lizzard) (relman/hg->git project)]

This came up in a duplicate, since this issue has been around since 43 or so, I don't think we need to track it but it does seem like something we should fix.

Comment 15

[Boris Zbarsky [:bzbarsky]]

I ran into this today. My testcase goes like this:

1. Load https://searchfox.org/mozilla-central/source/xpcom/string/nsTSubstring.cpp
2. Open web console.
3. Evaluate:

  var b = document.body;
  var b2 = b.cloneNode(true);
  var start = new Date;
  var count = 10000000;
  for (var i = 0; i < count; ++i)
    b.isSameNode(b2);
  var stop = new Date;
  console.log((stop - start)/count*1e6);

I would expect numbers in the "15" range as output; that's what I get if I wrap that code in an IIFE. Instead I get numbers around "700", so about 45x slower.

Profile is at https://perfht.ml/2Tw4Clv and shows that time is mostly spent doing the bareword looks, as somewhat expected. Of the ~7s total execution time, I have 4.6s under jit::DoGetNameFallback, about 0.5s under jit::DoBindNameFallback, 0.5s in (not under) jit::EnterBaselineAtBranch, what looks like 0.55s in the interpreter (self time for the "debugger eval code" label under Interpret). So I am guessing we are bouncing back and forth between interpreter and baseline and doing expensive name lookups to boot...

Comment 17

[Boris Zbarsky [:bzbarsky]]

For what it's worth, people keep running into this; see https://news.ycombinator.com/item?id=21912772 for the most recent case I saw.

Jan, is there something obvious we could do better here?

Comment 18

[Jan de Mooij [:jandem]]

Unfortunately I don't think there's a short-term fix other than using a saner environment chain for web console bindings/evaluation :/

Non-syntactic scopes destroying name lookup performance also affects JSM code... We have bug 1432901 on file to convert JSMs to ES modules to deal with that. That project won't have an effect on the devtools console, but with that use case gone we might be able to cleanup/optimize non-syntactic scopes more...

Comment 19

[Boris Zbarsky [:bzbarsky]]

Hmm. Could we get console to stop using a non-syntactic scope somehow? Fundamentally, I would expect that the set of "extra" names it's trying to inject into the scope chain is fixed and known in advance, and we ought to be able to make all other names suffer no performance penalty, I would think....

Comment 20

[Alexandre Poirot [:ochameau]]

Here is the typical list of symbols we are trying to expose via executeInGlobalWithBindings:
$, $$, $_, $x, $0, clear, clearHistory, keys, values, help, cd, inspect, pprint, print, copy
(FYI, out of this list, chrome only supports: copy, clear, inspector, keys, values and the various $ helpers)

The code that generates this list is quite convoluted, but yes, this list is probably known in advance.
I'm not that good with JS engine, nor the console code, but what would be the alternative to expose such symbols without polluting the global scope of the document we are debugging?

Comment 22

[Ben Bucksch (:BenB)]

Testcase in bug 1701923. Lack of inlining of functions means that particular code runs 80x slower.

It also locks up the browser UI for several minutes.

Comment 23

[Julian Descottes [:jdescottes]]

We are currently implementing similar APIs for WebDriver BiDi and I was explicitly checking this test case.
As a bit of background, we have 2 APIs to evaluate code in BiDi: "evaluate" and "callFunction". The first one, "evaluate" doesn't need any additional binding, so we just use executeInGlobal. For the second one however I need to pass some bindings to my evaluated expression and therefore I have to use executeInGlobalWithBindings. So I was concerned about running into the same kind of performance issues as the ones described here.

But when testing the script attached here with BiDi's callFunction, I could not see any noticeable performance impact. After investigating, it comes from the fact that we evaluate the code in an IIFE for call function. Basically I evaluate (function() { /** whatever slow script **/ })(). I imagine the function scope somehow shields us from the issues described in this bug?

I don't think we could use that consistently for DevTools, but it might be worth checking if there are situations where we could wrap the evaluated code in IIFEs without sideeffects for the user? Maybe console evals when the debugger is not paused could use that approach?

Comment 24

[Julian Descottes [:jdescottes]]

Hi arai!

This is more an FYI, rather than an actual question. Since you have been helping with Debugger APIs a lot, I wanted to bring the previous comment to your attention, in case it could prompt any idea to improve performances.

Basically, the performance issue described in this bug goes away as long as the code is wrapped in a IIFE. I somewhat understand that the scope where the code runs is less polluted than when there is no IIFE, but in practice the two patterns are similar. The bindings are still available to the code running in the IIFE. We cannot switch to using this all the time in DevTools, but maybe that could prompt some idea to improve the performance of the regular usage (without IIFE) as well.

Comment 25

[Tooru Fujisawa [:arai]]

Yes, the issue is around the top-level variables.

executeInGlobalWithBindings is almost equivalent of with (nenv) { ... } statement, with nenv object created below.

this means:

• if the variable name exists in the passed bindings, it becomes the nenv's propety, even if var declaration is inside the code
• if the variable name doesn't exist in the passed bindings, it becomes the current this's property

and this operation is not optimized.

https://searchfox.org/mozilla-central/rev/ffb50da3ca89100b6ae5054cfe69c187679515f0/js/src/debugger/Frame.cpp#1006-1009,1049-1051,1056,1061

Result<Completion> js::DebuggerGenericEval(
    JSContext* cx, const mozilla::Range<const char16_t> chars,
    HandleObject bindings, const EvalOptions& options, Debugger* dbg,
    HandleObject envArg, FrameIter* iter) {
...
  // If evalWithBindings, create the inner environment.
  if (bindings) {
    Rooted<PlainObject*> nenv(cx, NewPlainObjectWithProto(cx, nullptr));
...
    for (size_t i = 0; i < keys.length(); i++) {
...
          !NativeDefineDataProperty(cx, nenv, id, val, 0)) {

Then, if you enclose the code with function, top-level variables become function's local slot, and the access is optimized.

Also, the effect of this issue is slightly smaller for non-top-level lexical variables, because it doesn't lookup in nenv and location is known:

var now = Date.now();
for (let i = 0; i < 100000000; i++) { }
console.log('loop took ' + (Date.now() - now) + ' ms');

Then, I think the solution depends on what actual behavior the Console and WebDriver expects for Debugger.

Given the passed bindings is copied and treated like read-only, some behavior shared with with statement aren't really necessary, and the handling of the top-level variables could be simplified, such like, "if there's variable declaration, don't use the passed bindings, and always use local binding".
The passed bindings data needs to be checked only for accesses for unknown variables, both for get and set.

This way, the not-optimized variable handling doesn't happen inside the loop,
and possibly reduce the effect of non-syntactic scope to the JIT compilation.

Comment 26

[Tooru Fujisawa [:arai]]

Then, about the non-syntactic scope handling itself, we're moving away from it in ESMification (bug 1308512).
We could look into the remaining consumers and think about what the default behavior should be, and think about whether introducing yet another mode for Debugger makes sense, or modifying the default behavior makes sense.

Comment 28

[Nicolas B. Pierron [:nbp]]

(In reply to Tooru Fujisawa [:arai] from comment #25)

Yes, the issue is around the top-level variables.

executeInGlobalWithBindings is almost equivalent of with (nenv) { ... } statement, with nenv object created below.

We disable the JIT in the context of with statement. This is a feature of the JIT which is used extensively in our test suite.

Comment 29

[Iain Ireland [:iain]]

(In reply to Nicolas B. Pierron [:nbp] from comment #28)

We disable the JIT in the context of with statement. This is a feature of the JIT which is used extensively in our test suite.

Note that with uses dedicated opcodes (JSOp::EnterWith/JSOp::LeaveWith), and we check for those opcodes in WarpBuilder to disable it. I'm pretty sure the non-syntactic code in this case doesn't generate those opcodes (although it may generate JSOp::NonSyntacticGlobalThis, which is also unsupported), so it would theoretically be possible to improve Ion support in this case without breaking our test suite.

Comment 30

[BugBot [:suhaib / :marco/ :calixte]]

The severity field for this bug is relatively low, S3. However, the bug has 4 duplicates.
:sdetar, could you consider increasing the bug severity?

For more information, please visit auto_nag documentation.

Comment 32

[Tooru Fujisawa [:arai]]

bug 1842701 patch will add an optimization for the case where the script has no reference to DevTools' helper functions,
and in that case the script run in the same speed as the web content.

if the script has reference to DevTools' helper functions, the performance will remain slow.