browser permanently hangs when logging tons of stuff

NEW
Unassigned

Status

defect
P2
normal
5 years ago
7 months ago

People

(Reporter: fitzgen, Unassigned)

Tracking

(Blocks 3 bugs, {perf, regression})

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [console-papercuts][polish-backlog])

Attachments

(3 attachments)

STR:

1. Load http://fitzgen.github.io/ocean-noise/
2. Open a scratchpad
3. Paste attachment into the scratchpad
4. Run the scratchpad
5. Click the big "play" button

ER:

Stuff logs in the console. Failing that, when there are too many messages, some are displayed and the browser is still responsive. Seems like at minimum we could just put some loop inside a DevToolsUtils.yieldingEach[0] or queue up messages to be rendered so that the browser is still responsive.

[0]: http://dxr.mozilla.org/mozilla-central/source/toolkit/devtools/DevToolsUtils.js#171

AR:

Permanent beach ball. Need to force-quit firefox.
Note that if you modify the scrachpad so that `strace.logging = false;` before the `strace(window);` call, there are no issues, so it is definitely a problem with handling that many log messages.
Thanks for the bug report. This might be caused by recent changes/perf regressions. Needs investigation.
Keywords: perf
Priority: -- → P2
profile data from running this in the browser toolbox' profiler.
Screenshot of the profiler showing 35% of the time being spent in utils.js cloneObject method.

An additional 11% is being spent in the webconsole.js pruneOutput function.
s/pruneOutput/flushMessageQueue/
Whiteboard: [console-papercuts]
Whiteboard: [console-papercuts] → [console-papercuts][devedition-40]
Whiteboard: [console-papercuts][devedition-40] → [console-papercuts][polish-backlog]
Update: e10s helps a lot here. Instead of the browser beachballing in an unrecoverable way, instead you get the notificationbox popup and can kill the web content process and get the browser back.
Product: Firefox → DevTools
Using the initial STR, 2 segments from the profile:

Initial longer hangs for large amounts of warnings: with https://perfht.ml/2Bg6HGM
1. Expensive reflow caused by `scrollToBottom`
2. `Frame::render` is about 16% as most expensive component

Could React fiber methods help split up this work further and delay it?


Batches of logs: https://perfht.ml/2Bgp4v8
1. Suffers from expensive reflows (150ms+).

ni? Daniel if this links to a known bug.
Flags: needinfo?(dholbert)
I can't view the profiles in comment 8 -- I get:
====
Could not download the profile.

Error: Unserializing the profile failed: Error: Unable to parse a processed profile of version 19 - are you running an outdated version of perf.html? The most recent version understood by this version of perf.html is version 18.
====

Reloading (including w/ shift) doesn't help. Harald, do you know if there's anything special I need to do for those profiles to load?
Sorry, using the staging environment. After resolving the shortened link, switching out https://perf-html.io with https://master.perf-html.io should allow viewing the profiles.
(In reply to :Harald Kirschner :digitarald from comment #8)
> Using the initial STR, 2 segments from the profile:
> 
> Initial longer hangs for large amounts of warnings: with https://perfht.ml/2Bg6HGM
> 1. Expensive reflow caused by `scrollToBottom`

Here's a working direct link (fixed per comment 10), w/ "Call Tree" tab, filtered for "scrollToBottom":
https://master.perf-html.io/public/72303b387e1239196dae812877411828b9da0c1b/calltree/?globalTrackOrder=11-0-1-2-3-4-5-6-7-8-9-10&hiddenGlobalTracks=1-2-3-4-5-6-7-8-9-10&hiddenLocalTracksByPid=32522-1-0&localTrackOrderByPid=32522-1-0~32530-0~32526-0~32525-0~32671-0~32524-0~32527-0~&range=141.6189_163.4843&search=scrollToBottom&thread=0&v=3

Looks like we're spending ~2x as much time restyling as we are reflowing here.  I'm guessing we're just creating insane amounts of web content? (and when we finally get around to styling/reflowing it, it takes a while)

> Batches of logs: https://perfht.ml/2Bgp4v8
> 1. Suffers from expensive reflows (150ms+).

Working direct link for this one (in Call Tree tab):
https://master.perf-html.io/public/72303b387e1239196dae812877411828b9da0c1b/calltree/?globalTrackOrder=11-0-1-2-3-4-5-6-7-8-9-10&hiddenGlobalTracks=1-2-3-4-5-6-7-8-9-10&hiddenLocalTracksByPid=32522-1-0&localTrackOrderByPid=32522-1-0~32530-0~32526-0~32525-0~32671-0~32524-0~32527-0~&range=141.6189_177.4539~160.0979_177.4539&thread=0&v=3

Indeed, there seem to be repeated 150ms+ reflows for that window, which are the dominant slow thing for most of that period of time. I wonder what's triggering those reflows -- I do see hits for "appendChild" / "contentAppended" between many of the reflows (and you can see the scrollable area changing in the profile's screenshots).

So I suspect that between those reflows, we're just adding content to the backscroll area, which is invalidating the cached intrinsic sizes of the backscroll, and causing us to perform a more thorough layout of the flex items than we otherwise would have to do...

> ni? Daniel if this links to a known bug.

I don't know, offhand, but I'll tie this to Bug 1304473 (flexbox-perf-issues) for further investigation when time allows.
Flags: needinfo?(dholbert)
You need to log in before you can comment on or make changes to this bug.