Closed Bug 1479813 Opened Last year Closed Last year

Opening Console on Gmail causes 1sec hang on content thread

Categories

(DevTools :: Debugger, defect, P1)

defect

Tracking

(Not tracked)

RESOLVED FIXED

People

(Reporter: Harald, Assigned: arai)

References

(Blocks 1 open bug)

Details

Attachments

(1 obsolete file)

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

STR:
- Open Gmail
- Open Console

https://perfht.ml/2NW1Cs8

- 950ms onPacket, receiveMessage
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...
Confirmed to be todays Nightly.
I confirm that the webconsole impact is pretty low (< 100ms)
Moving to debugger.
Component: Console → Debugger
Priority: -- → P1
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
Flags: needinfo?(arai.unmht)
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.
findScripts returns an array of 67587 elements, but there is "only" 268 distinct sources.
This is a bunch of scriptElement as well as eval.
(See bug 1482090 for the unnecessary cross compartment wrappers when accessing the Debugger API.)
(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.
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.
Flags: needinfo?(arai.unmht)
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.
(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 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
Attachment #8999074 - Attachment is obsolete: true
Depends on: 956376
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.
(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.
https://hg.mozilla.org/mozilla-central/rev/d17c68d95b16
Status: NEW → RESOLVED
Closed: Last year
Resolution: --- → FIXED
Target Milestone: --- → Firefox 63
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Target Milestone: Firefox 63 → ---
Status: REOPENED → NEW
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?
Flags: needinfo?(hkirschner)
Confirmed, no noticeable delay. Thanks so much, :arai!
Status: NEW → RESOLVED
Closed: Last yearLast year
Flags: needinfo?(hkirschner)
Resolution: --- → FIXED
Assignee: nobody → arai.unmht
You need to log in before you can comment on or make changes to this bug.