1479813 - Opening Console on Gmail causes 1sec hang on content thread

Status: RESOLVED FIXED

(DevTools :: Debugger, defect, P1)

Description

[:Harald Kirschner :digitarald]

Windows 10 on Surface Book. Nightly using Nvidia with WebRender on.

STR:
- Open Gmail
- Open Console

https://perfht.ml/2NW1Cs8

- 950ms onPacket, receiveMessage

Comment 1

[Alexandre Poirot [:ochameau]]

Is this with very latest nightly? Because I'm still seeing findScript (you have to switch to C++) with more than 100ms from the overall 419ms. (You say 950ms, but 950ms is the total recording time, it is better to always use the "running times" in the call tree. That, to always compare to the same metric: samples.)

Most of the time is spent in _discoverSources in the thread actor, so it sounds more like a debugger issue than a console one.

Otherwise, I see a lot of CrossCompartmentWrapper frames, I'm wondering if we are having a useless overhead while accessing the Debugger API. It is most likely attached to some weird jsm global scope and forces to have wrappers...

Comment 2

[:Harald Kirschner :digitarald]

Confirmed to be todays Nightly.

Comment 3

[Nicolas Chevobbe [:nchevobbe]]

I confirm that the webconsole impact is pretty low (< 100ms)
Moving to debugger.

Comment 4

[Alexandre Poirot [:ochameau]]

I'm not sure I reproduce this correctly?

Here is a profile of comment 0 STR:
  https://perfht.ml/2OnDyhP
On the content process, there is only 161ms of samples related to devtools. (out of a 4s record)
There is still a significant part being spent into DebuggerAPI.findScripts (52ms)
The rest seems to be also around the thread actor and `onSources` function.

Arai, is the time spent into findScripts expected for such STR (open gmail then open the web console)?
See this profile: https://perfht.ml/2KK7W40

Comment 5

[Tooru Fujisawa [:arai]]

do you have the number of scripts found there handy?
the ratio between wrapLazyScript/wrapScript isn't something surprising, and I think the time taken by it mostly depends on the number of found scripts.

I'll investigate this or next week.

Comment 6

[Alexandre Poirot [:ochameau]]

findScripts returns an array of 67587 elements, but there is "only" 268 distinct sources.
This is a bunch of scriptElement as well as eval.

Comment 7

[Alexandre Poirot [:ochameau]]

(See bug 1482090 for the unnecessary cross compartment wrappers when accessing the Debugger API.)

Comment 8

[Tooru Fujisawa [:arai]]

(In reply to Alexandre Poirot [:ochameau] from comment #6)
> findScripts returns an array of 67587 elements,

that's way many than I expect.
if most of the found scripts are lazy, this is somewhat expected.
I'll check the ratio between lazy/non-lazy scripts numbers.

> but there is "only" 268 distinct sources.

separate from the time taken by findScript itself for this case,
I feel we should provide more dedicated function (maybe findSources) for this use case (collect sources), if this happens everytime we open devtools.

Comment 9

[Tooru Fujisawa [:arai]]

here's the number of lazy/non-lazy scripts
  lazy: 61916
  non-lazy: 1871

so, most scripts are lazy.
in the perf above, wrapLazyScript taking longer than wrapScript is expected.
and also taking ~1 us for wrapping each lazy script is also not so much surprising I think (I may be calculating wrongly),
given that we create new object for each and put them into weak map.

anyway, if we have findSources or something that returns only the necessary info there, the number of wrapping operation can be reduced and we could get better performance.
I'll try.

Comment 10

[Tooru Fujisawa [:arai]]

maybe, we don't have to collect lazy script for this case?
lazy script should have ancestor non-lazy script and they share same source object.
so, if we need only one script per each source, we can completely skip lazy script.

Comment 11

[Tooru Fujisawa [:arai]]

Attachment: WIP: Add Debugger.findSourcesAndScripts.

(In reply to Tooru Fujisawa [:arai] from comment #10)
> maybe, we don't have to collect lazy script for this case?
> lazy script should have ancestor non-lazy script and they share same source
> object.
> so, if we need only one script per each source, we can completely skip lazy
> script.

this was wrong that the ancestor can already be GCed.


anyway, here's the patch that adds Debugger.findSourcesAndScripts method that returns the array of [source,script] pair.
with it, the time taken by `Debugger.find*` call is reduced from 80ms to 12ms, and constructing sourcesToScripts map is reduced from 82ms to 1ms.

Comment 12

[Tooru Fujisawa [:arai]]

Comment on attachment 8999074 [details] [diff] [review]
WIP: Add Debugger.findSourcesAndScripts.

Actually, it was unnecessary to collect scripts (I should've read how the map is used :P

Here's WIP patch that adds Debugger.findSources.
https://treeherder.mozilla.org/#/jobs?repo=try&revision=77dde0227e74ebbbe89f4d77d6c6eeda14f8ea7e

Comment 13

[Jim Blandy :jimb]

This looks fantastic. Debugger never evolved the way it should have to meet its users' needs, and changes like this are just what's called for.

Comment 14

[Tooru Fujisawa [:arai]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/d17c68d95b1630adf72fe81ff214b0acdf4cd590
Bug 1479813 - Remove unnecessary test for delazification. r=jimb

Comment 15

[Tooru Fujisawa [:arai]]

(In reply to Tooru Fujisawa [:arai] from comment #14)
> https://hg.mozilla.org/integration/mozilla-inbound/rev/
> d17c68d95b1630adf72fe81ff214b0acdf4cd590
> Bug 1479813 - Remove unnecessary test for delazification. r=jimb

oops, wrong bug number.
it's for bug 1482963.

Comment 16

[Raul Gurzau (:RaulG)]

https://hg.mozilla.org/mozilla-central/rev/d17c68d95b16

Comment 17

[Tooru Fujisawa [:arai]]

now bug 956376 is fixed, and onPacket takes 23ms (Debugger#findSources takes 15ms) for me, on MacBookPro 2017.
:Harald, can you verify on your environment as well?

Comment 18

[:Harald Kirschner :digitarald]

Confirmed, no noticeable delay. Thanks so much, :arai!