1650629 - Mozilla Firefox Nightly randomly hangs on opening website pages (TaskController busy-loops in background processes while one process is busy)

Status: VERIFIED FIXED

(Core :: Performance: General, defect, P2)

Description

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

STR:

1. Open Mozilla Firefox Nightly
2. Open Bugzilla website page

and enjoy hang for some time (0,5-3s)

If it's not reproducible, open various website pages, each website page in new tab.

Unfortunately capturing profile with Firefox Profiler is not possible for me, due to bug #1650627,
but I will try to search for regression range with mozregression-gui with my old Mozilla Firefox Nightly profile.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Comment 2

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

Profile - https://share.firefox.dev/2CaOuid

I'm still searching for regression range.

First searches shows that probably:
bad - 2020-07-03
good - 2020-07-04

Comment 3

[Mike Conley (:mconley) (:⚙️) (PTO Dec 22 - Jan 2)]

Looks like a really long (~3s) wait on the content process main thread waiting for async paints to flush.

Comment 4

[Kris Taeleman (:ktaeleman)]

@markus: Can you see something in the profile that would be causing this?

Putting severity to S2 for now.

Comment 5

[Kris Taeleman (:ktaeleman)]

@virtual_manPL: Can you attach your about:support information?

Comment 6

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

Attachment: about;support.txt

(In reply to Kris Taeleman (:ktaeleman) from comment #5)

@virtual_manPL: Can you attach your about:support information?

Sure.

Comment 7

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

https://share.firefox.dev/3e7eaJN - and here's profile of only same delay without no hang

Comment 8

[Mike Conley (:mconley) (:⚙️) (PTO Dec 22 - Jan 2)]

That looks different. Instead of a graphics issue, this looks like about 13s is spent waiting for a socket to access the network.

Comment 9

[Markus Stange [:mstange]]

I agree with Mike, two very different issues.

In the first profile, with the long "flushing async paints", I can see a very busy "Privileged content process" during the same time that seems to be caught spinning in the new task scheduler. Maybe it's starving CPU resources from the paint thread?

In the second profile, the network request to bugzilla is delayed by uBlock Origin, which seems to be waiting for another network request that it started earlier, to "https://hosts-file.net/.%5Cad_servers.txt?_=8". That network request then errors out after a long time. I don't know why the request would take so long, and the URL seems wrong, too. Maybe there's some corrupted state in the IndexedDB database, like there was for profiler.firefox.com .

Comment 10

[Kris Taeleman (:ktaeleman)]

Moving to performance team as these don't look like Graphics issues.

Comment 11

[Markus Stange [:mstange]]

The first issue is bug 1649976.

Comment 12

[Bas Schouten (:bas.schouten)]

I believe I've found the root cause of this issue, I haven't been able to reproduce yet myself but I have a patch. Still looking to find a way to reproduce it so I can verify my fix.

Comment 13

[Mike Conley (:mconley) (:⚙️) (PTO Dec 22 - Jan 2)]

Virtual, are you able to reproduce this reliably? If so, perhaps you could test a build from Bas to see if it helps.

Comment 14

[[e-mail]]

[uBlock Origin] seems to be waiting for another network request that it started earlier, to https://hosts-file.net/.%5Cad_servers.txt?_=8. That network request then errors out after a long time.

That resource has been removed from uBO's stock lists (it has never been enabled by default) a long while ago since the list no longer exists:
https://github.com/uBlockOrigin/uBlock-issues/issues/971

People should definitely remove it from their selection of lists.

Comment 15

[Markus Stange [:mstange]]

(In reply to Mike Conley (:mconley) (:⚙️) from comment #13)

Virtual, are you able to reproduce this reliably? If so, perhaps you could test a build from Bas to see if it helps.

Windows build is here: target.zip (try push)

Comment 16

[Bas Schouten (:bas.schouten)]

So, what's happening here is two-fold:

1. Because the TaskController can return its dummy event even when it only has idle tasks, i.e. isn't going to do any work. We can wrongly tell the callers that work has been done, this needs fixing.
2. If mayWait is true we should block inside TaskController waiting for non-idle events if it turns out there's only idle events, rather than just doing a no-op. This is the behavior as it was before.

Comment 17

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

(In reply to Markus Stange [:mstange] from comment #9)

[...]
In the second profile, the network request to bugzilla is delayed by uBlock Origin, which seems to be waiting for another network request that it started earlier, to "https://hosts-file.net/.%5Cad_servers.txt?_=8". That network request then errors out after a long time. I don't know why the request would take so long, and the URL seems wrong, too. Maybe there's some corrupted state in the IndexedDB database, like there was for profiler.firefox.com .

Looks like I had some issue with database of uBlock Origin extension too, as it's stayed for some time in 1.27.11b4 per-release version. It did not want to update itself by auto-update, even when I downloaded XPI file and installed it manually it did not help, as it did not update. I tried again to update it in disabled mode and fortunately it finally updated to latest version after I installed it manually by using downloaded earlier XPI file.

I also disabled few obsolete and outdated filter lists which are not working anymore, as Markus Stange [:mstange] above and Raymond Hill [:gorhill] below wrote:
(In reply to [e-mail] from comment #14)

[uBlock Origin] seems to be waiting for another network request that it started earlier, to https://hosts-file.net/.%5Cad_servers.txt?_=8. That network request then errors out after a long time.

That resource has been removed from uBO's stock lists (it has never been enabled by default) a long while ago since the list no longer exists:
https://github.com/uBlockOrigin/uBlock-issues/issues/971

People should definitely remove it from their selection of lists.

@ Bas Schouten (:bas.schouten) + Mike Conley (:mconley) (:⚙️) + Markus Stange [:mstange] - Awesome! Thank you very much! I will test this try test build deeply for few days and I will report back to you with results by end of weekend to make sure, as bug happens in most cases randomly, but still for my very long browser sessions I'm having over dozens of hangs, so definitely I will see difference if it's fixed or not.

Comment 20

[Bas Schouten (:bas.schouten)]

Attachment: Bug 1650629: Correctly wait when requested and report whether work was done by ProcessNextEvent when using TaskController. r=mstange

Comment 21

[Markus Stange [:mstange]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=8a41f25cb4cbe180ef9afc25018da19e86ae1b8e

Comment 22

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/63b8480782c8
Correctly wait when requested and report whether work was done by ProcessNextEvent when using TaskController. r=mstange

Comment 23

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/63b8480782c8

Comment 24

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1606706

Comment 26

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

Thank you very much for fixing this! \o/

I didn't notice anymore any hangs, so I'm confirming that bug looks fixed in this try test build, and as well starting in Mozilla Firefox Nightly 80.0a1 (2020-07-10). I'm only hoping, that performance is same or even better with patch from this bug with patch from bug #1606706, before landing both.