Closed
Bug 1380449
Opened 7 years ago
Closed 7 years ago
Propagating clonable console message args to the parent process causes huge performance problems
Categories
(WebExtensions :: General, defect, P1)
Tracking
(firefox-esr52 unaffected, firefox55 unaffected, firefox56+ fixed, firefox57 fixed)
RESOLVED
FIXED
mozilla57
Tracking | Status | |
---|---|---|
firefox-esr52 | --- | unaffected |
firefox55 | --- | unaffected |
firefox56 | + | fixed |
firefox57 | --- | fixed |
People
(Reporter: gregtatum, Assigned: julienw)
References
Details
(Keywords: regression, testcase)
Attachments
(2 files, 1 obsolete file)
795 bytes,
text/html
|
Details | |
59 bytes,
text/x-review-board-request
|
lizzard
:
approval-mozilla-beta+
|
Details |
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
Comment 1•7 years ago
|
||
This is probably mostly X-ray overhead. Switching to using StructuredCloneHolder to do the cloning would likely fix the problem.
Assignee | ||
Comment 2•7 years ago
|
||
Here is a simpler testcase
Assignee | ||
Comment 3•7 years ago
|
||
On beta this is blazing fast, on Nightly this is crawling like a dog.
Assignee | ||
Updated•7 years ago
|
Keywords: regression,
testcase
Assignee | ||
Comment 4•7 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)
Assignee | ||
Comment 5•7 years ago
|
||
FTR here is my very simple patch: https://github.com/mozilla/gecko-dev/compare/master...julienw:structured-clone-holder
Comment 6•7 years ago
|
||
(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•7 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)
Comment 8•7 years ago
|
||
(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•7 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•7 years ago
|
Assignee: nobody → felash
Comment 10•7 years ago
|
||
Only cloning for non-web contexts makes sense to me
Assignee | ||
Comment 11•7 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
Comment 12•7 years ago
|
||
I imagine you have to use its deserialize function: http://searchfox.org/mozilla-central/source/dom/webidl/StructuredCloneHolder.webidl See the unit tests: http://searchfox.org/mozilla-central/source/dom/base/test/unit/test_structuredcloneholder.js#17
Assignee | ||
Comment 13•7 years ago
|
||
Ah I see, thanks a lot Alexandre! I believe this should be done in the Toolbox itself.
Comment 14•7 years ago
|
||
(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•7 years ago
|
Priority: -- → P1
Comment hidden (mozreview-request) |
Comment hidden (mozreview-request) |
Assignee | ||
Comment 17•7 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•7 years ago
|
Attachment #8888329 -
Flags: review?(kmaglione+bmo)
Attachment #8888330 -
Flags: review?(kmaglione+bmo)
Assignee | ||
Comment 18•7 years ago
|
||
There are crashes in the try build which I think are related to the patch. Removing the r? for now.
Assignee | ||
Updated•7 years ago
|
Attachment #8888329 -
Flags: review?(kmaglione+bmo)
Attachment #8888330 -
Flags: review?(kmaglione+bmo)
Assignee | ||
Comment 19•7 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•7 years ago
|
Attachment #8888329 -
Attachment is obsolete: true
Assignee | ||
Comment 20•7 years ago
|
||
BTW previous try run is: https://treeherder.mozilla.org/#/jobs?repo=try&revision=20f189fcd20d
Comment hidden (mozreview-request) |
Assignee | ||
Updated•7 years ago
|
Attachment #8888330 -
Attachment is obsolete: true
Assignee | ||
Comment 22•7 years ago
|
||
new try run is https://treeherder.mozilla.org/#/jobs?repo=try&revision=15e850234416bf7d0867bc38d1c8d2314e184cff talos run is https://treeherder.mozilla.org/perf.html#/comparechooser?newProject=try&newRevision=15e850234416bf7d0867bc38d1c8d2314e184cff
Assignee | ||
Comment 23•7 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 24•7 years ago
|
||
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•7 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) |
Assignee | ||
Comment 27•7 years ago
|
||
Rebased and pushed a new try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=22ad97a4b6a58932e25c63bcae348df7e83c2ea2 new talos: https://treeherder.mozilla.org/perf.html#/comparechooser?newProject=try&newRevision=22ad97a4b6a58932e25c63bcae348df7e83c2ea2
Comment hidden (mozreview-request) |
Assignee | ||
Comment 29•7 years ago
|
||
This try run looks much much better, let's land this !
Keywords: checkin-needed
Assignee | ||
Updated•7 years ago
|
tracking-firefox56:
--- → ?
Comment 30•7 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
Comment 32•7 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/d19acd0286a8
Status: NEW → RESOLVED
Closed: 7 years ago
status-firefox57:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla57
Assignee | ||
Comment 33•7 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?
Updated•7 years ago
|
status-firefox55:
--- → unaffected
status-firefox-esr52:
--- → unaffected
Comment 34•7 years ago
|
||
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+
Comment 35•7 years ago
|
||
bugherder uplift |
https://hg.mozilla.org/releases/mozilla-beta/rev/26e2d2cc365c
Comment 36•7 years ago
|
||
https://hg.mozilla.org/projects/date/rev/d19acd0286a87d87b54675b14fe073b448cd0987 Bug 1380449 - Do not clone when not in a Web Extension r=kmag
Updated•6 years ago
|
Product: Toolkit → WebExtensions
You need to log in
before you can comment on or make changes to this bug.
Description
•