1288493 - Opening devtools (any panel) causes big JS slowdown test page with evals

Status: RESOLVED FIXED

(DevTools :: Debugger, defect, P2)

Description

[Brian Grinstead [:bgrins]]

Attachment: slow-page.html

Spun out from Bug 1125322.

STR:

Open attached test case
Click process (note the # of ms it took)
Open devtools (any tool)
Click process again

Expected:

Times are around the same

Actual:

Times are 10-20x longer

I see around 10ms and 150-200ms respectively although it varies per click and I'm sure it varies a lot per-device.

Comment 1

[Brian Grinstead [:bgrins]]

Hi Shu, with this much of a slowdown it makes me wonder if this is JIT related.  Would you be able to take a look and see if attaching the debugger is indeed causing the JS to slow down on this page?

Comment 2

[Brian Grinstead [:bgrins]]

OK, this must be something in devtools-land, since I've tested on the page with:

  Cu.import("resource://gre/modules/jsdebugger.jsm");
  addDebuggerToGlobal(this);
  var dbg = new Debugger();
  var DOwindow = dbg.addDebuggee(content.window);

And the slowdown doesn't happen.  It only happens once the toolbox is opened (and it gets fast again once it is closed).

Comment 3

[Brian Grinstead [:bgrins]]

Tracked this case down to evals introducing new sources.  Here's a simpler test case which is around 10x slower with the toolbox opened:

data:text/html,<button onclick='var start = new Date(); for (var i = 0; i < 1000;  i++) { eval("1+1"); } document.querySelector("div").textContent=(new Date()) - start'>click me</button><div></div>

We get a packet for every new source like:

from  "server1.conn2.child1/26"
type  "newSource"
source  {
  generatedUrl  ""
  url  ""
  isBlackBoxed  ""
  isPrettyPrinted  ""
  isSourceMapped  ""
  sourceMapURL  ""
  introductionUrl  "https://bug1288493.bmoattachments.org/attachment.cgi?id=8773395"
  introductionType  "eval"
}

Comment 4

[raphael777777]

Do you think a fix for this will be out soon? Thanks so much for looking into it!

Comment 5

[Brian Grinstead [:bgrins]]

Hi Eddy, there is a test case (see Comment 3) where running it with devtools opened is around 10x slower.  It seems to have to do with newSource packets that are generated due to multiple evals happening.  Doing some profiling, it seems most of the time is spent adding a source in the script actor: https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/script.js#1924.  Which then spends a lot of time in TabSources.source() and in actor creation (SourceActor).

Do you have some time to profile this further and see if there's anything we can do to address this test case?  I'm hoping anything done here will also speed up source creation in the general case.

Comment 6

[Eddy Bruel [:ejpbruel]]

(In reply to Brian Grinstead [:bgrins] from comment #5)
> Hi Eddy, there is a test case (see Comment 3) where running it with devtools
> opened is around 10x slower.  It seems to have to do with newSource packets
> that are generated due to multiple evals happening.  Doing some profiling,
> it seems most of the time is spent adding a source in the script actor:
> https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/script.
> js#1924.  Which then spends a lot of time in TabSources.source() and in
> actor creation (SourceActor).
> 
> Do you have some time to profile this further and see if there's anything we
> can do to address this test case?  I'm hoping anything done here will also
> speed up source creation in the general case.

Jup. I will look into this early next week, probably on monday.

Comment 7

[Eddy Bruel [:ejpbruel]]

(In reply to Brian Grinstead [:bgrins] from comment #5)
> Hi Eddy, there is a test case (see Comment 3) where running it with devtools
> opened is around 10x slower.  It seems to have to do with newSource packets
> that are generated due to multiple evals happening.  Doing some profiling,
> it seems most of the time is spent adding a source in the script actor:
> https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/script.
> js#1924.  Which then spends a lot of time in TabSources.source() and in
> actor creation (SourceActor).
> 
> Do you have some time to profile this further and see if there's anything we
> can do to address this test case?  I'm hoping anything done here will also
> speed up source creation in the general case.

At first glance, we don't seem to be spending particularly long in each call to addSource; somewhere between 0 and 1ms. However, if you're doing 1000 calls to eval, that amounts to 1000 calls to addSource, so those numbers still add up.

Comment 8

[Eddy Bruel [:ejpbruel]]

(In reply to Eddy Bruel [:ejpbruel] from comment #7)
> (In reply to Brian Grinstead [:bgrins] from comment #5)
> > Hi Eddy, there is a test case (see Comment 3) where running it with devtools
> > opened is around 10x slower.  It seems to have to do with newSource packets
> > that are generated due to multiple evals happening.  Doing some profiling,
> > it seems most of the time is spent adding a source in the script actor:
> > https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/script.
> > js#1924.  Which then spends a lot of time in TabSources.source() and in
> > actor creation (SourceActor).
> > 
> > Do you have some time to profile this further and see if there's anything we
> > can do to address this test case?  I'm hoping anything done here will also
> > speed up source creation in the general case.
> 
> At first glance, we don't seem to be spending particularly long in each call
> to addSource; somewhere between 0 and 1ms. However, if you're doing 1000
> calls to eval, that amounts to 1000 calls to addSource, so those numbers
> still add up.

After looking at it more closely, I can't find any obvious performance bottlenecks in addSource. In a nutshell, here is what happens in the debugger for each call to eval:

For each call to eval, addSource performs the following steps:
1. Create a non-source mapped source actor for the source.
2. Set and pending breakpoints for the source.

We don't have any pending breakpoints in this scenario, so we should be able to ignore the performance cost of 2.

Creating a non-source mapped source actor involves the following steps:
1. Check if the source is an eval source. If so, set the URL of the source to null.
2. Check if the source is an inline source. If so, set isInlineSource to true.
3. Call the source() function to create the source actor.

The source() function then performs the following steps:
1. Check if the source is allowed. If not, return early.
2. Check if we have a cached inline source actor for the source. If so, return that.
3. Check if the source is an inline source. If so:
   a. Create an inline source actor for the source.
   b. Return the inline source actor.
4. Check if we have a cached source actor for the source. If so, return that.

In this case, since we are dealing with an eval source, all of the above checks should fail. The source() function then continues as follows:

5. Create a source actor for the source.
6. Get a reusable actor id for the source actor from the source actor store.
7. Override the actor id of the source actor with the reusable actor id.
8. Update the reusable actor id on the source actor store.
9. Check if the source needs to be blackboxed. If so, blackbox the source.
10. Cache the source actor.
11. Emit a new source actor.
12. Return the source actor.

As far as I can tell, none of these steps involve any loops, or other operations that are known to be expensive. That conclusion seems reasonable, since my measurements indicate we don't spend more than 1ms in each call to addSource, and this time does not increase as the number of eval sources increases.

Comment 9

[Eddy Bruel [:ejpbruel]]

Based on comment 8, my conclusion is that there is an inherent cost to evaluating new sources when the debugger is active. This cost, although small, is not negligible, and adds up as the number of calls to eval increases.

Because this cost is inherent, I can't really think of anything to improve the situation. One thing we could do is optionally turn of the newScript notification in the debugger API for eval sources. That would eliminate the increased cost to eval. Unfortunately, it also would make eval sources undebuggable.

Another thing we could do is see if we could somehow short-circuit most of the checks described in comment 8 when the source is an eval source. For instance, if we can assume that eval sources are never source mapped or blackboxed, we can eliminate the checks for that. I don't expect any big performance wins from this though. At best, it would give you the same slowdown at 2000 calls to eval, instead of a 1000 (or at least in that order of magnitude).

Brian, do you have any other ideas on what we could do to improve things here? If not, I'm leaning towards resolving this bug as WONTFIX.

Comment 10

[Jarda Snajdr [:jsnajdr]]

There is bug 1176050 that's somewhat related to this. Opening NetMonitor and watching the requests makes the page load 4 times slower. My effort to fix this by optimizing NetMonitor (by lazy loading request data it doesn't need) turned out to be naive and didn't bring any improvements.

I noticed however there is a lot of protocol traffic caused by tools I don't have open, namely console and debugger.

I see minimizing devtools impact on page performance as very important for developers. People around me doing web development complaint about it often. It'd be sad to see this WONTFIXed.

Comment 11

[Brian Grinstead [:bgrins]]

(In reply to Jarda Snajdr [:jsnajdr] from comment #10)
> There is bug 1176050 that's somewhat related to this. Opening NetMonitor and
> watching the requests makes the page load 4 times slower. My effort to fix
> this by optimizing NetMonitor (by lazy loading request data it doesn't need)
> turned out to be naive and didn't bring any improvements.
> 
> I noticed however there is a lot of protocol traffic caused by tools I don't
> have open, namely console and debugger.
> 
> I see minimizing devtools impact on page performance as very important for
> developers. People around me doing web development complaint about it often.
> It'd be sad to see this WONTFIXed.

I agree that ideally opening devtools should have minimal effect on any page but in this particular scenario where many evals are created in a loop, each introduces a new script that needs to be hooked up with the debugger.  Maybe there are some improvements we can do, but I trust the evaluation in Comment 9 that it won't speed it up by an order of magnitude.

If the actual RDP transmission is a bottleneck we should dig more into that, since it would be a general improvement across all tools and pages with a lot of traffic.  Have you done any profiling for Bug 1176050 to determine how much of the slowness is related to RDP?

FYI, I've checked this particular test case (in Comment 3) in Chrome and see a similar magnitude of slowdown, although unfortunately Firefox is much slower on this particular case to start with.

Chrome 54 canary: 1ms without devtools opened and 50ms with devtools opened
Firefox 51: 10ms without devtools opened and 200ms with devtools opened

Comment 12

[Brian Grinstead [:bgrins]]

I spent a bit of time also profiling this and notice that sometimes even just accessing source.introductionType can take 1ms (in isEvalSource), and there are a number of other similar source lookups (introductionScript,  displayURL, etc).  There might be some places where we could carefully avoid looking up properties on the source or cache them, but it looks like it generally might be slow to access these source properties on the Debugger Source objects.  Maybe that's unavoidable overhead?

Comment 13

[Jarda Snajdr [:jsnajdr]]

(In reply to Brian Grinstead [:bgrins] from comment #11)
> If the actual RDP transmission is a bottleneck we should dig more into that,
> since it would be a general improvement across all tools and pages with a
> lot of traffic.  Have you done any profiling for Bug 1176050 to determine
> how much of the slowness is related to RDP?

When profiling the page load, the FPS goes very clearly towards zero and the JS flame chart shows a mixture of actions (the netmonitor actor observing the Necko channel, debugger transport transporting, the frontend drawing and styling) where nothing dominates. So there seems to be no single place that can be identified as the culprit.

It doesn't help that the browser toolbox is adding noise to the profiling - it has its own console that cannot be turned off and its own protocol traffic (over the TCP transport) can be seen in the profile.

Comment 14

[Brian Grinstead [:bgrins]]

(In reply to Eddy Bruel [:ejpbruel] from comment #9)
> Based on comment 8, my conclusion is that there is an inherent cost to
> evaluating new sources when the debugger is active. This cost, although
> small, is not negligible, and adds up as the number of calls to eval
> increases.
> 
> Because this cost is inherent, I can't really think of anything to improve
> the situation. One thing we could do is optionally turn of the newScript
> notification in the debugger API for eval sources. That would eliminate the
> increased cost to eval. Unfortunately, it also would make eval sources
> undebuggable.

Yeah, I'd rather have correctness than speed in this case

> Another thing we could do is see if we could somehow short-circuit most of
> the checks described in comment 8 when the source is an eval source. For
> instance, if we can assume that eval sources are never source mapped or
> blackboxed, we can eliminate the checks for that. I don't expect any big
> performance wins from this though. At best, it would give you the same
> slowdown at 2000 calls to eval, instead of a 1000 (or at least in that order
> of magnitude).

If there were some low hanging fruit here where we could speed things up even by just a constant I think it'd be worth spending a bit of time on it.  Given Comment 12 I don't know how possible that is, but if there were a way to limit property lookups / avoid some logic and it helped I'd be all for it.  AFAIK: 'eval sources are never source mapped or blackboxed' is a safe assumption but if you don't think that's the case then the same 'correctness over speed' comment above applies here too.

> Brian, do you have any other ideas on what we could do to improve things
> here? If not, I'm leaning towards resolving this bug as WONTFIX.

Would you be able to check and see if your idea above can give any improvement?  We should definitely timebox this work and I think it's safe to say we won't get near the normal runtime in this case, but anything we can do to be faster would help.

Comment 15

[Jim Blandy :jimb]

(In reply to Brian Grinstead [:bgrins] from comment #12)
> I spent a bit of time also profiling this and notice that sometimes even
> just accessing source.introductionType can take 1ms (in isEvalSource), and
> there are a number of other similar source lookups (introductionScript, 
> displayURL, etc).

Really? Isn't that just a call to Debugger.Source.prototype.introductionType? That's defined here:
http://searchfox.org/mozilla-central/rev/b38dbd1378cea4ae83bbc8a834cdccd02bbc5347/js/src/vm/Debugger.cpp#6994

and there is absolutely no reason that should take anything close to a millisecond.

Comment 16

[Jim Blandy :jimb]

(In reply to Jarda Snajdr [:jsnajdr] from comment #13)
> When profiling the page load, the FPS goes very clearly towards zero and the
> JS flame chart shows a mixture of actions (the netmonitor actor observing
> the Necko channel, debugger transport transporting, the frontend drawing and
> styling) where nothing dominates. So there seems to be no single place that
> can be identified as the culprit.

Perhaps there's a way to consolidate traffic into fewer, larger packets. Then we'd do less transmitting and less redrawing.

Comment 17

[Thayne]

Based on comment 8, my conclusion is that there is an inherent cost to evaluating new sources when the debugger is active. This cost, although small, is not negligible, and adds up as the number of calls to eval increases.

Because this cost is inherent, I can't really think of anything to improve the situation. One thing we could do is optionally turn of the newScript notification in the debugger API for eval sources. That would eliminate the increased cost to eval. Unfortunately, it also would make eval sources undebuggable.

If this is the case, I would really like to see the performance of adding additional sources while the dev tools is open improve. At work we have thousands of original sources. In an effort to improve load times, for development we combine all of them into a single file, with an eval for each original source with a // sourcemap comment in it so that each original source shows up as a separate source in the dev tools. With this setup, loading the page with dev tools open is painfully slow. Sourcemaps aren't an option, because it causes it to perform even worse and often crashes the browser (both firefox and chrome) with how many sources we have.

Comment 18

[Logan Smyth [:loganfsmyth]]

We recently implemented some improvements for this, so I'm going to close this. If anyone comes across this and feels they are still seeing a performance hit due to usage of eval, don't hesitate to file a new bug.