Propagating clonable console message args to the parent process causes huge performance problems

RESOLVED FIXED in Firefox 56

Status

defect
P1
normal
RESOLVED FIXED
2 years ago
10 months ago

People

(Reporter: gregtatum, Assigned: julienw)

Tracking

({regression, testcase})

56 Branch
mozilla57
Dependency tree / graph

Firefox Tracking Flags

(firefox-esr52 unaffected, firefox55 unaffected, firefox56+ fixed, firefox57 fixed)

Details

Attachments

(2 attachments, 1 obsolete attachment)

(Reporter)

Description

2 years ago
In perf.html development mode we console.log our full application state for any state change. This means that we are really slamming the console hard with lots of information, including entire performance profiles. So we are pretty much the worse case usage of console.log(). Bug 1357486 added a patch to propagate clonable console messages args to the parent process. I did a mozregression and performance profile to find this as the issue that is causing the development mode of our web app to be completely unusable due to performance issues.

Revision causing issue: https://hg.mozilla.org/integration/mozilla-inbound/rev/312a55aa2bcc

Performance profile showing a single console.log message with the changed function, with a 1.6 second jank: https://perfht.ml/2t4S2Nz

STR:

* git clone git@github.com:devtools-html/perf.html.git
* cd perf.html
* yarn install
* yarn start
* visit http://localhost:4242/public/2d2847d84c8ef954897b837a490956ecfb806b39/calltree
* interact with the call tree, everything is really really slow as we console.log
(Reporter)

Updated

2 years ago
Blocks: 1357486
This is probably mostly X-ray overhead. Switching to using StructuredCloneHolder to do the cloning would likely fix the problem.
(Assignee)

Comment 2

2 years ago
Posted file testcase
Here is a simpler testcase
(Assignee)

Comment 3

2 years ago
On beta this is blazing fast, on Nightly this is crawling like a dog.
(Assignee)

Updated

2 years ago
Keywords: regression, testcase
(Assignee)

Comment 4

2 years ago
I tried using StructuredCloneHolder, it's a lot faster but still slower than on current beta. I think it would be good enough it wasn't synchronous...

Kris, could you elaborate about what the added code is for ? Maybe we don't need this for normal webpages, but only for extensions ?
Flags: needinfo?(kmaglione+bmo)
(In reply to Julien Wajsberg [:julienw] from comment #4)
> Kris, could you elaborate about what the added code is for ? Maybe we don't
> need this for normal webpages, but only for extensions ?

Well, the most immediate problem it fixed was that some devtools tests relied on being able to access logged objects from console storage in the parent. I initially just changed those tests to log strings instead, but a lot of extension developers rely on the browser console during development, and I don't think that simple logged objects appearing as "<unavailable>" is really acceptable at this point.

I'm not opposed to only cloning objects from non-web contexts, though.

(In reply to Julien Wajsberg [:julienw] from comment #4)
> I tried using StructuredCloneHolder, it's a lot faster but still slower than
> on current beta. I think it would be good enough it wasn't synchronous...

There isn't really a way to make it asynchronous. JS objects can only be accessed on the main thread, so we'd need to block the main thread in order to clone regardless. I suppose we could theoretically try to do it from an idle callback, though, since logged objects aren't really meant to be treated as a snapshot in any case.
Flags: needinfo?(kmaglione+bmo)
(Assignee)

Comment 7

2 years ago
> I don't think that simple logged objects appearing as "<unavailable>" is really acceptable at this point.

We have an Addon Console for addons, that the user can start from about:debugging. We think this should work for OOP too because they use actors, but TBH we haven't tried yet. (I don't know how to enable OOP on Linux)

> I'm not opposed to only cloning objects from non-web contexts, though.

This is one way. Another way is to never run the code when the browser console isn't open. Or both :)

> There isn't really a way to make it asynchronous. JS objects can only be accessed on the main thread, so we'd need to block the main thread in order to clone regardless.

I think the Addon Console uses an actor to make it work in a performant way. I understand the browser console doesn't work in the same way though.


What do you think of backing out this patch, and filing a separate bug to log objects through the browser console ? I think regressing console.log is a big deal unfortunately...
Flags: needinfo?(kmaglione+bmo)
(In reply to Julien Wajsberg [:julienw] from comment #7)
> > I don't think that simple logged objects appearing as "<unavailable>" is really acceptable at this point.
>
> We have an Addon Console for addons, that the user can start from
> about:debugging. We think this should work for OOP too because they use
> actors, but TBH we haven't tried yet. (I don't know how to enable OOP on
> Linux)

We do, and it should work for OOP add-ons (the tests pass, at any rate), but a
lot of developers still default to the browser console (we've already gotten
bug reports about other issues with OOP browser console logging, e.g., bug
1380646 and bug 1381212), and I don't want to make things more difficult for
them than necessary.

> > I'm not opposed to only cloning objects from non-web contexts, though.
>
> This is one way. Another way is to never run the code when the browser
> console isn't open. Or both :)

We could do that, but I'm a bit worried that people will tend to open the
browser console after some issue has happened, or they've tested some change,
and the data they need won't be there. And it wouldn't even be obvious why.

> > There isn't really a way to make it asynchronous. JS objects can only be
> > accessed on the main thread, so we'd need to block the main thread in
> > order to clone regardless.
>
> I think the Addon Console uses an actor to make it work in a performant way.
> I understand the browser console doesn't work in the same way though.

Right, but in that case, the object is never actually cloned to the parent.
The debugger protocol is just used to retrieve information about it when
necessary.

> What do you think of backing out this patch, and filing a separate bug to
> log objects through the browser console ? I think regressing console.log is
> a big deal unfortunately...

I think that's a non-starter. I'd be happy to limit the cloning to non-web
contexts and switch to StructuredCloneHolder for the cloning, though.
Flags: needinfo?(kmaglione+bmo)
(Assignee)

Comment 9

2 years ago
> We could do that, but I'm a bit worried that people will tend to open the browser console after some issue has happened, or they've tested some change, and the data they need won't be there. And it wouldn't even be obvious why.

Actually, this is already the case :)

OK I'll look into what you propose tomorrow. We can revisit this once the Addon Toolbox is more prevalent
(Assignee)

Updated

2 years ago
Assignee: nobody → felash
Only cloning for non-web contexts makes sense to me
(Assignee)

Comment 11

2 years ago
StructuredCloneHolder doesn't seem to pass OOP :/ When logging an object, I get "StructuredCloneHolder { }" in the console... Maybe I'm using it badly ? Here is my current patch: https://github.com/mozilla/gecko-dev/compare/master...julienw:structured-clone-holder
(Assignee)

Comment 13

2 years ago
Ah I see, thanks a lot Alexandre! I believe this should be done in the Toolbox itself.
(In reply to Julien Wajsberg [:julienw] from comment #11)
> StructuredCloneHolder doesn't seem to pass OOP :/ When logging an object, I
> get "StructuredCloneHolder { }" in the console... Maybe I'm using it badly ?
> Here is my current patch:
> https://github.com/mozilla/gecko-dev/compare/master...julienw:structured-
> clone-holder

There are two options here: 1) deserialize in the web content side, or 2) deserialize on the parent side. Or, ideally, 3) deserialize on the parent side at the last minute, when the data needs to be displayed.

Any of the three should work. The main benefit we get from using StructuredCloneHolder here as opposed to cloneInto is that it enters the object compartment before cloning, and therefore doesn't go through X-rays or cross-compartment proxies.

But if we can avoid deserializing on the parent side before the object is needed, that's a bit less overhead we have to worry about in a lot of cases. And the StructuredCloneHolder should take up a lot less memory in console storage than an actual complex object tree.

Updated

2 years ago
Priority: -- → P1
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 17

2 years ago
I requested a review from :kmag on Mozreview (first time I use it :) ), but maybe I should get reviews from devtools console developers too ?
(Assignee)

Updated

2 years ago
Attachment #8888329 - Flags: review?(kmaglione+bmo)
Attachment #8888330 - Flags: review?(kmaglione+bmo)
(Assignee)

Comment 18

2 years ago
There are crashes in the try build which I think are related to the patch. Removing the r? for now.
(Assignee)

Updated

2 years ago
Attachment #8888329 - Flags: review?(kmaglione+bmo)
Attachment #8888330 - Flags: review?(kmaglione+bmo)
(Assignee)

Comment 19

2 years ago
I think I lack the knowledge to make the StructuredCloneHolder change work reliably -- currently it seems to crash when using logs in a Worker, and there are also weird failures around threads -- I don't understand this properly but it may be the same thing.

I'll push a patch keeping cloneInto but doing it only for web extensions. I think this will do it for now and I can file a separate bug, pushing my WIP patch there, and let somebody else make it work.
(Assignee)

Updated

2 years ago
Attachment #8888329 - Attachment is obsolete: true
Comment hidden (mozreview-request)
(Assignee)

Updated

2 years ago
Attachment #8888330 - Attachment is obsolete: true
(Assignee)

Updated

2 years ago
See Also: → 1383100
(Assignee)

Comment 23

2 years ago
FYI I'm in PTO next week so please take my patch and finish it. I don't know if the try failures are expected...
Comment on attachment 8888329 [details]
Bug 1380449 - Do not clone when not in a Web Extension

I think we can proceed with this patch for 56, to at least avoid the recent regression.
I haven't tried the WebExtension usecase, but this patch looks good to me.

Kris, would you mind reviewing this patch or forward to whoever makes sense.
Attachment #8888329 - Flags: review?(kmaglione+bmo)

Comment 25

2 years ago
mozreview-review
Comment on attachment 8888329 [details]
Bug 1380449 - Do not clone when not in a Web Extension

https://reviewboard.mozilla.org/r/159276/#review168434
Attachment #8888329 - Flags: review?(kmaglione+bmo) → review+
Comment hidden (mozreview-request)
Comment hidden (mozreview-request)
(Assignee)

Comment 29

2 years ago
This try run looks much much better, let's land this !
Keywords: checkin-needed
(Assignee)

Updated

2 years ago

Comment 30

2 years ago
Pushed by ryanvm@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/d19acd0286a8
Do not clone when not in a Web Extension r=kmag
Keywords: checkin-needed
Track 56+ as performance issue.

Comment 32

2 years ago
bugherder
https://hg.mozilla.org/mozilla-central/rev/d19acd0286a8
Status: NEW → RESOLVED
Last Resolved: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
(Assignee)

Comment 33

2 years ago
Comment on attachment 8888329 [details]
Bug 1380449 - Do not clone when not in a Web Extension

Approval Request Comment
[Feature/Bug causing the regression]:
[User impact if declined]: logging big objects slow down firefox a lot.
[Is this code covered by automated tests?]: no -- but this is only used to show logs in various consoles.
[Has the fix been verified in Nightly?]: yes
[Needs manual test from QE? If yes, steps to reproduce]: Check that console.log calls (both in web pages and in web extensions) actually show up in the devtools' console and in the browser console.
[List of other uplifts needed for the feature/fix]: none
[Is the change risky?]: no
[Why is the change risky/not risky?]: if there is a problem, impact would be that console logs aren't displayed. So low impact, and easily discoverable.
[String changes made/needed]: none
Attachment #8888329 - Flags: approval-mozilla-beta?
Comment on attachment 8888329 [details]
Bug 1380449 - Do not clone when not in a Web Extension

Sounds like a reasonable compromise, let's uplift this for 56 beta 1.
Attachment #8888329 - Flags: approval-mozilla-beta? → approval-mozilla-beta+

Updated

10 months ago
Product: Toolkit → WebExtensions
You need to log in before you can comment on or make changes to this bug.