Closed
Bug 1399836
Opened 7 years ago
Closed 7 years ago
Investigate harald slow profile when reloading slack against the console
Categories
(DevTools :: Console, defect, P2)
DevTools
Console
Tracking
(firefox57 wontfix)
RESOLVED
FIXED
Tracking | Status | |
---|---|---|
firefox57 | --- | wontfix |
People
(Reporter: ochameau, Unassigned)
References
Details
Attachments
(1 file)
2.35 MB,
image/gif
|
Details |
https://perfht.ml/2wn6RYD Expand the first line of the call tree until you see "render/messageNodes". It report the following code as being very costly (49%): http://searchfox.org/mozilla-central/source/devtools/client/webconsole/new-console-output/components/console-output.js#111-125 Here, it looks like we instanciate a new MessageContainer for each message and that on every render of ConsoleOuput. Which should happen everytime there is a new message. The second most costly code is React::renderComponent (14%) which includes calling MessageContainer.shouldComponentUpdate and propably rendering messages. I tried similar patch: https://hg.mozilla.org/try/rev/d7f63909545930af0080fb9a325af77ceb5c4c7f but can't see significant improvement as I can't reproduce this kind of profiles, where render/mesageNodes is the most significant code.
Reporter | ||
Comment 1•7 years ago
|
||
Do you have any particular STR for your profile? Do you have "persist logs" enabled? Do you have tons and tons of messages in the console?
Flags: needinfo?(hkirschner)
Reporter | ||
Comment 2•7 years ago
|
||
Here is a test document which tries to reproduce this slowness: data:text/html,<script>for(var i = 0; i < 5000; i++) console.log(i); setTimeout(()=>console.log("done"), 1000);</script> (be careful, it is going to freeze your browser for quite a while!) render/messageNodes appears but only up to 1.8%: https://perfht.ml/2h4iOQY But this profile is scary nonetheless. It seems to be mostly composed of React abstraction ran from batchedMessageAdd/throttledDispatchTimeout. Overall it is reported as over 1000ms, but the following render method, even if there don't have a big "self" duration, are operating all over batchedMessageAdd execution: devtools/client/shared/components/frame.js::render - 52ms devtools/client/shared/components/reps/reps.js::render - 9ms devtools/client/webconsole/new-console-output/components/message.js - 36ms devtools/client/webconsole/new-console-output/components/grip-message-body.js - 22ms I haven't seen any useless call to any render method. It looks like we call all of them once. So at first sight, I would say we only see React's overhead :/
Comment 3•7 years ago
|
||
Thanks for looking into this, Alex. Here another profile with long hangs caused by Console. https://perfht.ml/2yajqZe > Do you have "persist logs" enabled? No persistent log > Do you have tons and tons of messages in the console? Just the usual slightly spammy Slack logs (~40) but nothing ridiculous. STR: - Open Slack - Open Console - Switch to Debugger - Reload AR: Slow loading with the main process being janky Could the debugger cause the JS to run slower?
Flags: needinfo?(hkirschner)
Reporter | ||
Comment 4•7 years ago
|
||
This profiler is really différent from the first one. And better describe what I could see. OutputConsole.render is only 8%. And the main computation is now in messages reducer, which I haven't seen yet either... This is weird to get different profiles/stacks like that. I'll try to reproduce your exact STR.
Comment 5•7 years ago
|
||
Time spent in reducer is a known issue. We tried to optimize it as much as we could. Doing https://bugzilla.mozilla.org/show_bug.cgi?id=1371721 might help in case of batched messages.
Reporter | ||
Comment 6•7 years ago
|
||
(In reply to :Harald Kirschner :digitarald from comment #3) > Thanks for looking into this, Alex. > > Here another profile with long hangs caused by Console. > > https://perfht.ml/2yajqZe I was able to reproduce this against mozilla.slack.com and get very similar (and even slower) profile: https://perfht.ml/2x3nI4G The only minimal difference is that debugger "newSource" slowness is bigger than webconsole reducer. The debugger hangs has already been reported here: https://github.com/devtools-html/debugger.html/issues/3736 and I really don't get how this issue had been closed? Is perf-html really part of devtools? How can we ignore such report with actionnable profiles?! Good news is that bug 1371721 nicolas just linked is improving console performances. I rebased brian's patch and I see this console code go from 37% (13500ms) down to 19%(5600ms). From this profile https://perfht.ml/2x3nI4G down to this one https://perfht.ml/2x3LTjp. But the bad news is that bug 1399242 with panel visiblity trick doesn't really address the performance issue as this reducer/redux work happens way before react is involved and so the shouldComponentUpdate trick isn't so effective.
Comment 7•7 years ago
|
||
As I discussed this a bit with ochameau, I'm just sharing my experience. I tried two days ago to reproduce the issues mentioned in the original bug, and I never managed to get a profile where the console was the major offender regarding. As Alex mentioned, the Debugger was always the one using the most time. I also don't experience a significant slowdown when reloading. I will attach a GIF of what I see. I have tested this on a 2 yrs old Macbook pro 15 (i7 2,8 GHz, 16gb ram) and on a win7 desktop computer (i5 2,4 GHz, 8gb ram). Curious about which hardware Harald is using, maybe that can explain why the console shows up differently in his profiles?
Comment 8•7 years ago
|
||
I reload using cmd+R even though I hover on the reload button ; it's just for being self explanatory. I reloaded twice because the first time I forgot to hover on tabs all the time to check if the main process was freezing. As you can see it does freeze a bit, I just don't consider it as severe as other perf issues we have in DevTools.
Comment 9•7 years ago
|
||
Can you re-test this on Nightly and link to a new profile if you are still seeing it? It looks like most of the time was in the reducer so this may be fixed by Bug 1371721.
Comment 10•7 years ago
|
||
Tried a few times over the past weeks but could not reproduce this profile specifically. We have other bugs open on slow addMessage, so we should be good.
Status: NEW → RESOLVED
Closed: 7 years ago
Flags: needinfo?(hkirschner)
Resolution: --- → FIXED
Updated•6 years ago
|
Product: Firefox → DevTools
You need to log in
before you can comment on or make changes to this bug.
Description
•