Open Bug 793345 Opened 10 years ago Updated 25 days ago

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

Categories

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

defect

Tracking

()

REOPENED

People

(Reporter: jaws, Unassigned)

References

(Blocks 2 open bugs)

Details

(Keywords: perf)

Attachments

(1 file)

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.
It's even worse on my computer—while running attached JS from Scratchpad I hit "unresponsive script" twice.
Assignee: nobody → anton
Priority: -- → P2
Assignee: anton → nobody
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).
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → INVALID
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.
Status: RESOLVED → REOPENED
Resolution: INVALID → ---
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.
Summary: Unreliable performance measurements when running code in Scratchpad → Code executed in the Scratchpad and Webconsole runs 10x slower
Component: Developer Tools: Scratchpad → Developer Tools
Still reproducing using the attached document.
The webconsole ends up calling Debugger.evalInGlobalWithBindings, could it be the reason why console evaluation are slower??
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?
Component: Developer Tools → Developer Tools: Console
Flags: needinfo?(jimb)
Summary: Code executed in the Scratchpad and Webconsole runs 10x slower → Code executed with Debugger.evalInGlobalWithBindings (Scratchpad or Webconsole) runs 10x slower than the same code in a script tag
(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');
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
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?
Flags: needinfo?(jimb) → needinfo?(shu)
I'd guess we aren't OSRing for one reason or another. I can take a look next week sometime.
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.
(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.
Flags: needinfo?(shu)
Component: Developer Tools: Console → JavaScript Engine: JIT
Product: Firefox → Core
OS: Windows 7 → All
Hardware: x86_64 → All
Duplicate of this bug: 1272763
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.
Keywords: perf
Priority: P2 → P3

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...

Duplicate of this bug: 1573901

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?

Flags: needinfo?(jdemooij)

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...

Flags: needinfo?(jdemooij)
Summary: Code executed with Debugger.evalInGlobalWithBindings (Scratchpad or Webconsole) runs 10x slower than the same code in a script tag → Code executed with Debugger.executeInGlobalWithBindings (Scratchpad or Webconsole) runs 10x slower than the same code in a script tag

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....

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?

Duplicate of this bug: 1701923

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.

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

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?

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.

Flags: needinfo?(arai.unmht)

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.

Flags: needinfo?(arai.unmht)

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.

See Also: → 1780504
You need to log in before you can comment on or make changes to this bug.