1252012 - YouTube is very slow when different tab has console open (STR: comment 11)

Status: RESOLVED FIXED

(DevTools :: Console, defect, P3)

Description

[sworddragon2]

User Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:44.0) Gecko/20100101 Firefox/44.0
Build ID: 20160209233610



Actual results:

Since Firefox is advanced enough that YouTube uses also on Linux at default the HTML video player I'm noticing that doing actions on a site on YouTube where a HTML video is embedded are very slow. Here are some details:

- It is not required that a video plays.
- The effect appears very randomly but is present about 50% of the time. Sometimes it happens shortly after Firefox is running and at other times it happens if Firefox is running for several days.
- Any actions will be delayed for up to a few seconds. For example moving over a running video to call its statusbar or even just scrolling sown through the comments will be delayed.


Expected results:

I would expect that YouTube would either run permanently slow (for example because of low system specs) or permanently fast.


System information:

Operating system: Linux 4.4.2 (x86_64)
CPU: AMD Phenom II X6 1045T @2.7 GHz
Memory 16 GiB @667 MHz
Display server: X.Org 1.17.3
Window manager: Openbox 3.6.1
Grahics card: GeForce GTX 650
Graphics driver: NVIDIA 352.63
----------------------------------------
- My Firefox profile got already reset.
- https://www.youtube.com/html5 shows that all 6 format combinations are supported.
- The only installed extensions/plugins are Adblock Plus, the default theme, Shockwave Flash and a german language pack.
- FFmpeg is used to provide H.264 support.

Comment 1

[Paul Pasca[Away. Please needinfo? Paul Oiegas [:pauloiegasSV]]]

Hi reporter,

I haven't managed to reproduce this issue on the latest release(44.0.2) nor latest Nightly(47.0a1). I've tested this in Ubuntu 14.04 x64, but YouTube never ran slow, regardless of any other website opened on other tabs or windows. I've played YouTube videos using both Flash and HTML5. Both latest release and latest Nightly ran smoothly during the test.

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:44.0) Gecko/20100101 Firefox/44.0
Build ID: 20160210153822

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:47.0) Gecko/20100101 Firefox/47.0
Build ID: 20160302030209

Can you please try to reproduce this on the latest release(44.0.2) and latest Nightly(47.0a1) and provide the results? When doing this, please try to reproduce with a new clean Firefox profile, maybe even in safe mode, as some of this issues may be caused by third party installed add-ons or custom settings(https://support.mozilla.org/en-US/kb/troubleshoot-and-diagnose-firefox-problems).

Thanks,
Paul.

Comment 2

[sworddragon2]

I'm on Firefox 44.0.2 where I have seen this issue and I have already reset my profile. The next time if this issue appears I can try to disable Adblock Plus to see if it changes anything (unfortunately testing this in safe mode for possibly several days is currently not possible for security reasons).

Comment 3

[sworddragon2]

Disabling Adblock Plus if this issue appears and refreshing the site does make no difference.

Comment 4

[Paul Pasca[Away. Please needinfo? Paul Oiegas [:pauloiegasSV]]]

Hi reporter,

I'm still unable to reproduce this issue on my end. Can you please try to reproduce this bug on the latest Nightly build(https://nightly.mozilla.org/) and provide the results? Also, can you please test this with all addons disabled so we can eliminate more possible reasons for this issue you encounter?

Thanks,
Paul.

Comment 5

[sworddragon2]

Since it can need days until this issue appears testing this with a nightly version in a productive environment would not be really possible. Also testing in safe mode is not possible as said in comment #2. Any other ideas how this issue can be analyzed (actually this issue had more or less an effect of my decision to make a Valgrind log which has its own ticket here: https://bugzilla.mozilla.org/show_bug.cgi?id=1236348 . But I don't know if it contains any useful related information)?

Comment 6

[Ryan VanderMeulen [:RyanVM]]

This sounds maybe-similar to bug 1220502. Does this reproduce on Fx46 or newer by chance?

Comment 7

[sworddragon2]

I'm not logged in into YouTube as required by the other report but maybe it is still related. I will test it for some days after Firefox 46 is out and reporting back the result.

Comment 8

[Ryan VanderMeulen [:RyanVM]]

Thanks, 46 beta builds should be available in the very near future as well if you want to try testing them. Otherwise, since you seem like a technically-inclined person, maybe you'd be interested in trying to grab a profile when it's running slowly? :)

If so, one of our employees, Benoit Girard, wrote an addon that can collect a profile on-demand which would be interesting to see the results of in your case. You would just install the addon and start profiling when it gets slow. From that data, we might get a better idea of who to involve in investigating the issue further.
https://github.com/bgirard/Gecko-Profiler-Addon

Comment 9

[sworddragon2]

I have figured out a reason (and hopefully the only one here) that causes this problem. With Firefox 45.0.2 if I'm opening a new tab and then opening the web console in it YouTube reacts slow as pointed to in the startpost. The slowness accumulates if multiple tabs with the web console are opened and for example with 10 tabs the freezes take up to ~10+ seconds on my system. Maybe somebody can reproduce this issue on Firefox 45.0.2 or a higher version.

Comment 10

[Paul Pasca[Away. Please needinfo? Paul Oiegas [:pauloiegasSV]]]

Hi reporter,

I've tested this again on Ubuntu 14.04 x64 with FF 46.0.1(latest version) and latest Nightly(49.0a1), but I'm still unable to reproduce. I had more than 10 tabs opened with the "Web Console" opened as well. The browser didn't freeze and it didn't slow down. Memory consumption or CPU usage didn't go off the charts. Did a new profile or safe mode helped you with this issue?

Thanks,
Paul.

Comment 11

[sworddragon2]

I have tested this now with Firefox 46.0.1 with a clean profile and the issue doesn't exist there. On testing what in my old profile caused this behavior I have figured out that this issue only happens if javascript.options.strict is set to true.

So the STR are now:

1. Start Firefox, go to about:config and set javascript.options.strict to true.
2. Open an empty tab and open the web console in it.
3. In another tab open any video on YouTube.
4. Try now various things like hovering the mouse cursor over the video, stopping it, starting it, etc.


At step 4 Firefox reacts slow as the video bar of the video (and Firefox itself) needs some seconds to update which accumulates if step 2 is done with even more tabs.

Comment 12

[Ciprian Muresan [:cmuresan], Ecosystem QA]

User Agent  Mozilla/5.0 (X11; Linux i686; rv:49.0) Gecko/20100101 Firefox/49.0

I have managed to reproduce the issue with the STR from comment 11 on Ubuntu 14.04 x32 using the latest Nightly (49.0a1, Build ID 20160605030215). After restarting Nightly with the required pref set to true, the YouTube page and the browser itself is slow on every action, pausing the video, changing the quality, switching tabs take a few seconds to complete. 
I’m not sure if this should be in a more specific component like JS engine or DevTools Web Console, so I’m going for a more general one first.

Comment 13

[Naveed Ihsanullah [:naveed]]

Has anyone replicated this bug on Windows or OSX? I have not had any luck doing so. Don't have a Linux nearby atm.

Comment 14

[Naveed Ihsanullah [:naveed]]

@Hannes: It seems TraceLogger running while this slow down occurs could give us hints on what is going on. Can we give steps to have the filer try that and send us back the trace?

Comment 15

[Hannes Verschore [:h4writer]]

Looks like comment 11 describes a short enough scenario to try tracelogger. I'm on linux myself and will try this tomorrow myself. If it doesn't work I'll post some exact steps on how to get a log.

Comment 16

[Hannes Verschore [:h4writer]]

Attachment: TraceLog overview of last few seconds

Comment 17

[Hannes Verschore [:h4writer]]

Attachment: Overview of functions

Comment 18

[Hannes Verschore [:h4writer]]

Following the comment 11 I could get a tracelog on nightly.
Note: this is more visible when e10s is disabled.

Looking at which functions were running and taking the most time when I got no reaction was:
> devtools/server/actors/utils/webconsole-utils.js:262   ConsoleServiceListener.prototype.observe
> devtools/shared/layout/utils.js:32                     getTopWindow
> nsPrompter.js:336                                      openModalWindow (I was trying to close and it wanted to show: 'are you sure you want to quit'
> devtools/shared/layout/utils.js:68                     isWindowIncluded

Looking at the "Browser Console" instead of "Web Console" I see a lot of errors being reported whenever youtube becomes unresponsive.
These warnings are thrown because 'arguments' is not used correctly in strict mode.
And that are a lot.

As a test I closed all my "Browser Consoles" and "Web Consoles". When I did that the problems disappeared
and I could interact normally with the player again, instead of having delays.

Opening a "Web Console" (not on the youtube page) caused it to slow down again.

That is the reason I think this is related to the devtools.
I would assume that opening a "Web Console" in a not-related page shouldn't cause a slowdown on pages that throws a lot of warnings.
Now I don't know the inner workings and if this is actual achievable. Forwarding to Nick.
@Nick: can you forward this to somebody that can look into this and find a fix?

Comment 19

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Unfortunately, because of both (1) each tab isn't in its own thread/process, and (2) one can't subscribe to only those console messages from a specific same origin related browsing context, a lot of console activity from any tab will put load on everything. 

Hopefully in the longer term, the project quantum rearchitecting that is happening in gecko will alleviate this kind of issue by fixing (1) by design.

In the meantime, forwarding to console folks to see what we can do about this right now. I'm sure there's some fat we could trim in the webconsole server / observer.

Comment 20

[Brian Grinstead [:bgrins]]

Doing some profiling on those STR I do see that the call to ConsoleServiceListener.observe is indeed eating up some cycles - even though it never sends packets over RDP to frontend it's still doing a bit of work to call observe there and determine the message isn't important.  However on a clean profile with e10s on I'm not noticing much jank following STR from Comment 11.

Is this still a noticeable issue with nightly builds and e10s on?  If so, maybe Services.console.registerListener could somehow be optimized to take in a window id and only call back if a message originated from it (or one of it's frames).

I came up with an alternate STR to try and quantify the jank:
1. Open a new tab and open webconsole on it
2. Open another tab and load: data:text/html,<body><style>.moving-box {height: 10%;width:20%;margin: 2%;padding: 2%;background-color: blue;animation: move 4s infinite;}@keyframes move {0% {margin-left: 2%;}100% {margin-left: 74%;}}</style><div id='log'></div><div id="container"><div class="moving-box"></div><div class="moving-box"></div><div class="moving-box"></div></div><script>setInterval(() => { throw new Error(performance.now()); }, 1);var start = performance.now();var avgRAF = 0;function measure() {  var since = performance.now() - start;  if (!avgRAF) { avgRAF = since; }  else { avgRAF = avgRAF * .99 + since * .01; }  document.getElementById('log').textContent = "rolling average from last 100 rAF: " +    Math.round(avgRAF) + "ms";  start = performance.now();  requestAnimationFrame(measure);}measure();</script></body>

And I don't see particularly worse jank whether the first tab has the console opened or not (even if I open 5 background tabs with consoles or a page with a bunch of iframes).  Sort of unrelated to this bug but if I open the webconsole frontend on the tab running the test (or open the Browser Console) then the rAF climbs as the frontend tries to render the messages.

Comment 21

[sworddragon2]

(In reply to Nick Fitzgerald [:fitzgen] [⏰PDT; UTC-7] from comment #19)
> (2) one can't subscribe to only those console messages from a specific
> same origin related browsing context, a lot of console activity from any tab
> will put load on everything.

In my opinion that is a design issue.


(In reply to Brian Grinstead [:bgrins] from comment #20)
> maybe Services.console.registerListener could somehow be optimized to take
> in a window id and only call back if a message originated from it (or one of
> it's frames).

Basically the fix for that issue?


(In reply to Brian Grinstead [:bgrins] from comment #20)
> Is this still a noticeable issue with nightly builds and e10s on?

Even with Firefox 49 on my old profile and e10s enabled there is no noticeable performance impact anymore even with multiple empty tabs with the web console open. However, on disabling e10s the performance impact is huge again. Does this mean e10s mitigates this issue while it is technically still there and does still eat up extra cpu time? If yes I think in the long term this issue should be completely get fixed.

Comment 22

[Brian Grinstead [:bgrins]]

(In reply to sworddragon2 from comment #21)
> (In reply to Brian Grinstead [:bgrins] from comment #20)
> > Is this still a noticeable issue with nightly builds and e10s on?
> 
> Even with Firefox 49 on my old profile and e10s enabled there is no
> noticeable performance impact anymore even with multiple empty tabs with the
> web console open. However, on disabling e10s the performance impact is huge
> again. Does this mean e10s mitigates this issue while it is technically
> still there and does still eat up extra cpu time? If yes I think in the long
> term this issue should be completely get fixed.

Yes, this sounds right.  Thankfully e10s improves things such that the problem is not perceivable in this case, but we can see  if there are still reasonable optimizations to make.

> (In reply to Brian Grinstead [:bgrins] from comment #20)
> > maybe Services.console.registerListener could somehow be optimized to take
> > in a window id and only call back if a message originated from it (or one of
> > it's frames).
> 
> Basically the fix for that issue?

Andrea, it appears that the console listener (for console service messages) is eating up some time even when it's listening for a window other than the one producing the messages [0].  Can you think of a way to optimize our console service message listener so that messages from a different page don't slow it down?  Possibly either by making Services.console.registerListener not call back if it doesn't belong to the window or one of it's framer, or switching to a setConsoleEventHandler/retrieveConsoleEvents style API.  Not sure if the latter would help perf but it would be more consistent with the new API that was added for worker console API calls.

[0]: https://dxr.mozilla.org/mozilla-central/source/devtools/server/actors/utils/webconsole-utils.js#249

Comment 23

[Andrea Marchesini [:baku]]

What we could do is: when WarningOnlyErrorReporter() is executed because of some JS warning/error, if there is a window, we could let window.console deal with those errors/warning. In this way devtools can use setConsoleEventHandler/retrieveConsoleEvents methods for any kind of error messages (and eventually we could remove nsIConsoleService completely (or leave it only for window-less/chrome code).

But, in order to do this, we should move the current devtools error handling to setConsoleEventHandler/retrieveConsoleEvents approach also for main-thread. When workers and main-thread consoles work at the same way (from a devtools point of view) we could migrate JS errors to console too.

Comment 24

[Andrew Overholt [:overholt]]

FWIW the STR in comment 11 seems to not reproduce in our latest nightly on Windows 10.

baku, do we still want/plan to do the stuff you outline in comment 23?

Comment 25

[Andrea Marchesini [:baku]]

Comment 23 is mainly devtools work. I move the NI to bgrins.

Comment 26

[Brian Grinstead [:bgrins]]

Maybe this will be improved by Bug 1382968

Comment 27

[Alexandre Poirot [:ochameau]]

If bug 1382968 doesn't address console performancec, bug 1382377 certainly will.
But I suspect it isn't only a console issue, network monitor is known to be doing it wrong on youtube (bug 1297525).

Comment 28

[Brian Grinstead [:bgrins]]

Bug 1382968 appears to have fixed this (using Comment 11 STR). When I open the console in another tab the youtube tab no longer lags.

Comment 29

[sworddragon2]

I'm just curious if you did a test with or without e10s enabled as we figured more or less out in comment #20 - #22 that enabling e10s seems to hide this issue.

Comment 30

[Brian Grinstead [:bgrins]]

(In reply to sworddragon2 from comment #29)
> I'm just curious if you did a test with or without e10s enabled as we
> figured more or less out in comment #20 - #22 that enabling e10s seems to
> hide this issue.

I just tested non-10s and see the fix there as well. But if you'd be able to verify the fix on a Nightly build that would be excellent.