Firefox 50.0 64-bit on Windows 8.1 64-bit on a system with Intel i7-4700MQ (4 cores, 8 hyperthreads) After upgrading my default Firefox profile from Firefox 49.0.2 64-bit to 50.0 64-bit, the firefox.exe (e10s disabled due to addons) has now a thread which always consumes a whole thread. Filing it against Telemetry because TelemetryAccumulate is four times part of the stack according to Process Explorer > firefox.exe > Properties > Threads > ucrtbase.DLL > Stack Please redirect to the appropriate component if necessary. Here are stacks as returned by Process Explorer: xul.dll!XRE_IsContentProcess+0x24aba xul.dll!XRE_TelemetryAccumulate+0x36f55 xul.dll!XRE_TelemetryAccumulate+0x36e37 xul.dll!XRE_TelemetryAccumulate+0x36dfa xul.dll!XRE_TelemetryAccumulate+0x3777f nss3.dll!PR_JoinThread+0x1a6 nss3.dll!PR_NativeCreateThread+0x15a ucrtbase.DLL!crt_at_quick_exit+0x7d KERNEL32.DLL!BaseThreadInitThunk+0x22 ntdll.dll!RtlUserThreadStart+0x34 USER32.dll!PeekMessageW+0xfa USER32.dll!PeekMessageW+0x116 xul.dll!mozilla_dump_image+0x60f660 xul.dll!XRE_IsContentProcess+0x2344a xul.dll!XRE_IsContentProcess+0x2327e xul.dll!XRE_TelemetryAccumulate+0x36f01 xul.dll!XRE_TelemetryAccumulate+0x36e37 xul.dll!XRE_TelemetryAccumulate+0x36dfa xul.dll!XRE_TelemetryAccumulate+0x3777f nss3.dll!PR_JoinThread+0x1a6 nss3.dll!PR_NativeCreateThread+0x15a ucrtbase.DLL!crt_at_quick_exit+0x7d KERNEL32.DLL!BaseThreadInitThunk+0x22 ntdll.dll!RtlUserThreadStart+0x34 ntdll.dll!RtlLeaveCriticalSection nss3.dll!PR_Unlock+0x2c xul.dll!XRE_IsContentProcess+0x24ac8 xul.dll!XRE_TelemetryAccumulate+0x36f55 xul.dll!XRE_TelemetryAccumulate+0x36e37 xul.dll!XRE_TelemetryAccumulate+0x36dfa xul.dll!XRE_TelemetryAccumulate+0x3777f nss3.dll!PR_JoinThread+0x1a6 nss3.dll!PR_NativeCreateThread+0x15a ucrtbase.DLL!crt_at_quick_exit+0x7d KERNEL32.DLL!BaseThreadInitThunk+0x22 ntdll.dll!RtlUserThreadStart+0x34 xul.dll!XRE_IsContentProcess+0x24b2e xul.dll!XRE_IsContentProcess+0x24aba xul.dll!XRE_TelemetryAccumulate+0x36f55 xul.dll!XRE_TelemetryAccumulate+0x36e37 xul.dll!XRE_TelemetryAccumulate+0x36dfa xul.dll!XRE_TelemetryAccumulate+0x3777f nss3.dll!PR_JoinThread+0x1a6 nss3.dll!PR_NativeCreateThread+0x15a ucrtbase.DLL!crt_at_quick_exit+0x7d KERNEL32.DLL!BaseThreadInitThunk+0x22 ntdll.dll!RtlUserThreadStart+0x34 The issue and stack persist if turn off Telemetry in the settings and restart Firefox.

So this is caused by a kickstarter.com tab and reproducible with new profiles on release, beta, aurora and central (and still reproduces with latest Nightly). Last good nightly build is 20160628, first bas is 20160629. Pushlog is https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d87b76177b2f5cf0839d73becebb614ab8a9ef7f&tochange=e45890951ce77c3df05575bd54072b9f300d77b0 Steps to reproduce: 1. Load https://www.kickstarter.com/projects/415566154/the-deep-atlantic-canadas-long-form-magazine?ref=home_featured Actual result: One thread near 100% cpu usage (12.5% with 8 hyperthreads here) Expected result: Normal cpu usage (~0.6% total or ~13% with Firefox 49.0.2) The devtools Performance log shows mostly cycle collection and animation frames. Boris, Brian, could this be a regression from bug 1244590?

[Tracking Requested - why for this release]: Performance regression, page uses one virtual processor on idle, a performance decrease by factor ~20 compared to Firefox 49.0.2

Just FYI, 'requestAnimationFrame' on devtools is not related to DOM animation code in most cases. In case DOM animation, 'Recalculate Style' with 'Restyle Hint: CSS Animations' or 'CSS Transitions' will be shown up.

(In reply to Sebastian Hengst [:aryx][:archaeopteryx] (needinfo on intermittent or backout) from comment #1) > So this is caused by a kickstarter.com tab and reproducible with new > profiles on release, beta, aurora and central (and still reproduces with > latest Nightly). > > Last good nightly build is 20160628, first bas is 20160629. Pushlog is > https://hg.mozilla.org/mozilla-central/ > pushloghtml?fromchange=d87b76177b2f5cf0839d73becebb614ab8a9ef7f&tochange=e458 > 90951ce77c3df05575bd54072b9f300d77b0 > > Steps to reproduce: > 1. Load > https://www.kickstarter.com/projects/415566154/the-deep-atlantic-canadas- > long-form-magazine?ref=home_featured > Actual result: > One thread near 100% cpu usage (12.5% with 8 hyperthreads here) > Expected result: > Normal cpu usage (~0.6% total or ~13% with Firefox 49.0.2) > > The devtools Performance log shows mostly cycle collection and animation > frames. > > Boris, Brian, could this be a regression from bug 1244590? I'm not sure if it is related to Bug 1244590. Bug 1244590 supports keyframes paced spacing, but it is protected by a pref which is disabled in release build. Is it related to the refactoring part in Bug1244590? I need more information. Hiro, Brian, do you guys have any hint or suggestion about this bug? Thanks.

I don't think this is related to bug 1244590. The callback function of the rAF is: function s() { var e = h.video.duration; e && (h.$c.find(".total_time").text(t(e)).attr("datetime", "PT" + Math.floor(e) + "S"), b.attr("aria-valuenow", h.video.currentTime).attr("aria-valuemin", "0").attr("aria-valuemax", e)) } Something related to media or DOM manipulations? Sebastian, could you please narrow down the regression bug?

This doesn't appear to be DOM: Animation related. The requestAnimationFrame callbacks are not doing anything with DOM animations and don't appear to be very expensive either (they're well within frame budget) so I don't think it's that either. Running the Gecko Profiler doesn't show up anything either--both main thread and compositor are mostly idle so I guess this is some other thread (perhaps media-related since the rAF callback is constantly querying the video's currentTime etc?) Dan, is there anything in the regression range in comment 1 that you know that might be related to this?

This is a regression from bug 1221730. The page contains this script: https://static.kickstarter.com/assets/packages/base-ae94faecc8d5d9500af6446cbfaa26e54a4a40cda082600844a7672261c2f353.js which contains function o() { var e = navigator.getGamepads ? navigator.getGamepads() : []; return _.chain(e).filter(_.identity).map(function (e) { return [e.index, e.id].join('|') }).value() } Sorry for the confusion of the Animation peers.

Calling navigator.getGamepads() is sufficient to reproduce the issue on this device.

This has been reproduced e.g. by :madperson on both 32-bit and 64-bit on a Windows 7 machine. I reproduced it on another Windows 8.1 one. A Xubuntu VM seems to be unaffected.

Because we moved gamepad event monitoring backend out of main thread, we have to polling the events manually, maybe it is the reason causing high CPU usage. This patch add an interval for this polling action, which reduces its CPU cycle occupation.

Setting P1 due to it's a regression and has sever performance impact. Hi Michael, looks you've been working on this, so assign this to you. Thank you!

Comment on attachment 8813079 [details] [diff] [review] Add Polling interval for DirectInput interface. Review of attachment 8813079 [details] [diff] [review]: ----------------------------------------------------------------- I originally wanted to make the message handling part be blocking so we can conserve more CPU cycles. However, we have to deal with 2 API -- directinput and xinput simutaneously, the former one can be implemented both blocking and non-blocking, but the latter can only be non-blocking. I don't want to mess around with mixing blocking and non-blocking interface, it would add too much complexity. This patch limits the polling speed of DirectInput and device enumeration part to prevent occupy 100% CPU usage.

Comment on attachment 8813079 [details] [diff] [review] Add Polling interval for DirectInput interface. Review of attachment 8813079 [details] [diff] [review]: ----------------------------------------------------------------- ::: dom/gamepad/windows/WindowsGamepad.cpp @@ +978,5 @@ > } > if (!sIsShutdown) { > + nsCOMPtr<nsIRunnable> runnable = new WindowGamepadMessageLoopOnceRunnable(); > + NS_DelayedDispatchToCurrentThread(runnable.forget(), > + kRawInputPollInterval); Nit: You can probably just use the same constant for both raw/xinput, just name it something more general.

Comment on attachment 8815144 [details] [diff] [review] Add Polling interval for DirectInput interface. r=qdot Merge kDirectInputPollInterval and kXInputPollInterval into one constant variable.

Here is try result https://treeherder.mozilla.org/#/jobs?repo=try&revision=1a4efc4ccda9eee4e8b0e918306515ced1beb566&selectedJob=32005827

Pushed by cbook@mozilla.com: https://hg.mozilla.org/integration/mozilla-inbound/rev/313bd77f0900 Add polling interval for direct input polling r=qDot

Thank you, I can't reproduce the issue anymore with the Try build.

Hi :lenzak800, Can you help nominate this for Aurora/Beta approval if it's not too risky?

Comment on attachment 8815144 [details] [diff] [review] Add Polling interval for DirectInput interface. r=qdot Review of attachment 8815144 [details] [diff] [review]: ----------------------------------------------------------------- [Feature/regressing bug #]:bug1318839 [User impact if declined]: User will encounter bad performance when using gamepad api [Describe test coverage new/current, TBPL]:Hand testing by physical gamepad [Risks and why]: Low risk, this patch just add a delay interval for gamepad polling interface without changing its behavior. [String/UUID change made/needed]: none

Comment on attachment 8815144 [details] [diff] [review] Add Polling interval for DirectInput interface. r=qdot Hi :lenzak800, The "Feature/regressing bug" should not be bug itself. It should a feature or regression. I'll take the patch this time, please put a correct bug in the template next time. Thanks. Fix a performance issue. Beta51+ and Aurora52+. Should be in 51 beta 6.

Backed out from Beta for Windows build bustage. NS_DelayedDispatchToCurrentThread only exists on 52+. https://hg.mozilla.org/releases/mozilla-beta/rev/aef032ba201c027510f804901477113748db6681 https://treeherder.mozilla.org/logviewer.html#?job_id=2029310&repo=mozilla-beta

Hi Andrew, do we need this in 50.1.0?

(In reply to Ritu Kothari (:ritu) from comment #26) > Hi Andrew, do we need this in 50.1.0? Seems like we do if I'm reading comment 0 correctly. Hopefully Michael can get to this soon (it's his morning now).

Hi Andrew, It seems that my patch depends on Bug1198381 which is only available after 52. And Bug1198381 is a big patch that is unlikely to uplift. This means that my patch can only uplift to Aurora. Do you have any suggestion about this situation? Thank you :)

Oh, yeah, we're not going to uplift requestIdleCallback beyond 52. Maybe Andreas would feel comfortable uplifting NS_DelayedDispatchToCurrentThread? If not, is there some mitigation we can do just on 51? Maybe back something out?

I spoke with Andreas. He's now away until next week but he thought Nathan could chime in about uplifting NS_DelayedDispatchToCurrentThread to beta. Alternatively, you could perhaps just lift the implementation of NS_DelayedDispatchToCurrentThread (which is just a convenience method) into WindowGamepadMessageLoopOnceRunnable.

(In reply to Andrew Overholt [:overholt] from comment #30) > I spoke with Andreas. He's now away until next week but he thought Nathan > could chime in about uplifting NS_DelayedDispatchToCurrentThread to beta. > > Alternatively, you could perhaps just lift the implementation of > NS_DelayedDispatchToCurrentThread (which is just a convenience method) into > WindowGamepadMessageLoopOnceRunnable. I think I would rather uplift NS_DelayedDispatchToCurrentThread to beta, rather than trying to extract its implementation into the gamepad bits.

There is an alternative way to use Timer Callback but it would add more complexity. I think the best solution is to uplift NS_DelayedDispatchToCurrentThread or just implement a windows gamepad dedicated version as a temporary workaround.

I took a quick stab at backporting NS_DelayedDispatchToCurrentThread but got into a bit of a mess requiring large parts of rIC. I'll needinfo Andreas to see if he can help with a more surgical backport when he's back next week.

I haven't got beta checked out (I think), but I can give some detailed steps to porting: 1) Add: extern nsresult NS_DelayedDispatchToCurrentThread( already_AddRefed<nsIRunnable>&& aEvent, uint32_t aDelayMs); to xpcom/glue/nsThreadUtils.h 2) Add: nsresult NS_DelayedDispatchToCurrentThread(already_AddRefed<nsIRunnable>&& aEvent, uint32_t aDelayMs) { nsCOMPtr<nsIRunnable> event(aEvent); #ifdef MOZILLA_INTERNAL_API nsIThread* thread = NS_GetCurrentThread(); if (!thread) { return NS_ERROR_UNEXPECTED; } #else nsresult rv; nsCOMPtr<nsIThread> thread; rv = NS_GetCurrentThread(getter_AddRefs(thread)); if (NS_WARN_IF(NS_FAILED(rv))) { return rv; } #endif return thread->DelayedDispatch(event.forget(), aDelayMs); } Both preferably below NS_DispatchToMainThread in both files. I'll figure out how to get a hold of beta and provide you with a patch if you need me to.

Is it risky if we make these changes and uplift to beta?

It shouldn't be, as far as I can tell.

Andreas said thoughts and I typed them and the attached patch is what resulted. Does this work for you, Michael?

Hi Andrew, I have no windows computer and gamepad in my hands for now. I will test it as soon as possible when I have these things ready.

Hi Michael, Per our offline discussion, do any dependent bugs need to uplift for beta?

Sorry for late reply. I have tested my patch applied to 51 with Andrew's patch which backport NS_DelayedDispatchToCurrentThread from bug1198381 and it got no problem. And I have read Andrew's patch which just add a new function encapsulating nsIThread::DelayedDispatch. Since nsIThread::DelayedDispatch has been exist inside gecko prior to the release, maybe uplifting this patch is not as risky as we think before?

Michael, Ok, let's take this in Beta51. Do you need to create uplift request for the patch?

[Feature/regressing bug #]:Presense of NS_DelayedDispatch in ThreadUtils [User impact if declined]: We will unable to land bug1318839 in beta and people will encounter bad performance when using gamepad under Windows [Describe test coverage new/current, TBPL]:Hand testing by physical gamepad [Risks and why]: Low risk, this patch just add a function which encapsulates an old interface nsIThread::DelayedDispatch, no current behavior is changed. [String/UUID change made/needed]: none

Comment on attachment 8817733 [details] [diff] [review] 0001-Bug-1318839-Backport-NS_DelayDispatchToCurrentThread.patch Fix a performance issue when using gamepad in Windows. Beta51+. Should be in 51 beta 8.

Backed out for build bustage (redefinition in nsThreadUtils.cpp): https://hg.mozilla.org/releases/mozilla-beta/rev/ae5275b8c53ba76cb98576e4e2a3031b0d659ba3 Push with failures: https://treeherder.mozilla.org/#/jobs?repo=mozilla-beta&revision=61d9cd6239b2a1eb6ec3fd16f0a4ffe57c6ecf73 Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=2086392&repo=mozilla-beta

I don't know what happened but somehow my patch was already landed on beta and the most recent attempt to do so causes compilation errors.

https://hg.mozilla.org/releases/mozilla-beta/rev/f8ebf5a3bd78 seems to be when it first landed and https://hg.mozilla.org/releases/mozilla-beta/rev/9c5f97295bb524035ee20aed657c9001ccc6ca59 is adding a second instance of the backported method.

The log shown in treeherder indicates NS_DelayedDispatchToCurrentThread is redefined, maybe it's because Andrew's patch is landed twice for some reason?

yeah seems this was my bad, sorry

What are the next steps here?

Sorry, I mistakenly thought this patch has been landed. Hi Tomcat, it seems that if we don't land Andrew's patch twice, the uplift will success. Is there still any problem that blocks the uplift?

In bug1324592, it seems that using NS_DelayedDispatchToCurrentThread will result in leak under Mochitest.

But I have no idea why it leak, I will try using timer cand callback function and test it again.

Too late for 50.

Lenzak so letting you investigate the leak before uplifting again ?

Yes, I will rewrite this patch with Timer callback function and test it again, it should mitigate the leak problem.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=5e9e42191c9ac26f3fd8b7379c303932a9924d75&selectedJob=33304458 I think this version should mitigate the leak.

Comment on attachment 8821039 [details] [diff] [review] Using nsITimer instead of DelayedDispatch to control DirectInput polling Review of attachment 8821039 [details] [diff] [review]: ----------------------------------------------------------------- The previous version using DelayedDispatch is reported a memory leak in Mochitest. I think it is because we cannot cancel our dispatched event when gecko is closed. I change the delayed dispatch implementation to nsITimer so we can manually cancel the runnable when gecko is closed.

Hi Tomcat. Can you backout previous patch and apply this one after the review is granted? This version doesn't need Andrew's backport anymore and it should be no leak problem.

yeah sure, does this need to be backed out also from trunk / aurora ?

Yes, since they exhibit same leak issue

Can we please put the leak fix in a separate bug with tracking flags and where someone may notice it needs checking in? The current setup here doesn't seem to be working, and it's _very_ unclear to me which branches things need to be landed on or backed out of or whatever. Using bug 1324592 for this is probably fine.

Yes, please use bug 1324592, it has the proper tracking flags set (for the record, this needs to land on 52 and 53).

OK, it seems that the patch is not backout yet. I will rebase this patch and make it land in bug1324592.

I've reproduced the issue described in comment 1 using 50.0a1 old Nightly (Build Id:20160629030209). I have also verified this issue across platforms (macOS 10.12.1,macOS 10.11.6, Windows 10 64 bit and Ubuntu 16.04 64bit) and noticed the following CPU usage: Windows 10 64 bit 51.0.1 (Build Id:20170125094131): -Around 30% of CPU usage with/without performing any interactions on the website. 52.0b8 (Build Id:20170220070057): -Around 0.7% of CPU usage without performing any interactions on the website. -Around 8% of CPU usage if interactions are performed on the website. 53.0a2 (Build Id:20170221004019): -Around 0.4% -0.5% of CPU usage without performing any interactions on the website. -Around 3% of CPU usage if interactions are performed on the website. Ubuntu 16.04 64bit: 51.0.1 (Build Id:20170125094131): -Around 12% of CPU usage without performing any interactions on the website. -Around 20% of CPU usage if interactions are performed on the website. 52.0b8 (Build Id:20170220070057): -Around 3% - 6% of CPU usage without performing any interactions on the website. -Around 24-30 % of CPU usage if interactions are performed on the website. 53.0a2 (Build Id:20170221004019): -Around 2% of CPU usage without performing any interactions on the website. -Around 20% of CPU usage if interactions are performed on the website. Mac 10.12.1: 51.0.1 (Build Id:20170125094131): -Around 20% of CPU usage without performing any interactions on the website. -Up to 100% of CPU usage if interactions are performed on the website. 52.0b8 (Build Id:20170220070057): -Around 2.4 % of CPU usage without performing any interactions on the website. -Around 50% - 60% of CPU usage if interactions are performed on the website. 53.0a2 (Build Id:20170221004019): -Around 2.6% of CPU usage without performing any interactions on the website. -Around 46% of CPU usage if interactions are performed on the website. I have also verified the CPU usage on 45.7.0esr (which is marked as unaffected): Mac 10.11.6: -Around 70% CPU usage without performing any interactions on the website. -Up to 155% CPU usage if interactions are performed on the website. Windows 10 64bit: -Around 14% CPU usage without performing any interactions on the website. -Up to 30% usage if interactions are performed on the website. Michael, can you please have a look into this and provide me a feedback regarding the expected CPU usage?

My patch here only modified Windows backend to reduce CPU usage by limiting the polling frequency of DirectInput driver. So CPU usage change in other OSes is not relevant to it. I think the CPU usage change between 51 and 52 is caused by other changesets. And I am sure that the high CPU usage in 45.7.0esr is not caused by moving Gamepad API to PBackground because it lands in 50.

Thank you Michael! Considering comment 66, I think it is safe to say that this issue is verified fixed in 52 latest beta and 53 latest aurora. Should I make a follow up issue regarding the high CPU usage in Ubuntu and Mac OSes?

Sure, but I don't think the issue on Mac and Ubuntu is a regression by moving Gamepad API to PBackground since the Linux and Mac backend is almost unchanged.