1398605 - Long load time (20secs+) on Github PR with ~100 comments

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect, P1)

Description

[:gerard-majax]

STR:
 1. Load PRs https://github.com/mozilla/DeepSpeech/pull/805 or https://github.com/mozilla/DeepSpeech/pull/810

Expected:
 It is not slow

Actual:
 It takes 20+ secs to complete the loading, we see painting progressing slowly.

No visible networking issue with Github. Reproduced 100% for several days, running Nightly/Linux (amd64, ubuntu 17.04, core i7 5600U, 20GB RAM) ; no perf issue whatsoever.

I tried with a clean profile running mozregression, and could not reproduce. I tried as well disabling all my extensions on my current profile, and it would not fix anything.

Two profiles captures with GeckoProfiler:
 - https://perf-html.io/public/6bec57d2643f43322869cdcf388095ccf5619e8c/calltree/?hiddenThreads=&thread=0&threadOrder=0-2-3-4-5-6-7-8-9-10-11-12-13-14-15-16-1
 - https://perf-html.io/public/45b7f56adc8ad96b9b1a2919455976d9ea886285/calltree/?hiddenThreads=&thread=0&threadOrder=0-2-3-4-5-6-7-8-9-10-11-12-13-14-15-16-17-1

Disabling Stylo does not help either.

Comment 1

[:gerard-majax]

Attachment: github-pr2.json

Profile from the web console "performance" tab while reloading PR 805

Comment 2

[:gerard-majax]

I verified if it could be long load time from all the image assets. According to the web dev console, it all gets fetched from the cache (bunch of 304).

One it is all loaded, the following is displayed at the bottom:
> DOMContentLoaded: 25,53 s
> load: 29,86 s

Comment 3

[Sylvestre Ledru [:Sylvestre]]

Do you know what could be the source of this issue?

Comment 4

[:gerard-majax]

New profile, with the dom.ipc.processCount back to default value (problem still reproduced):
> https://perf-html.io/public/fe18f5dcf0ac462bff1c9242e2308dfc25d4fb25/calltree/?hiddenThreads=&thread=0&threadOrder=0-2-3-4-5-1

Comment 5

[:gerard-majax]

I do actually reproduce under mozregression with some recent builds, as long as I do authenticate on Github. Anonymously, no reproduction of the issue.

Comment 6

[:gerard-majax]

36:03.55 INFO: Running mozilla-inbound build built on 2017-08-29 12:00:30.415000, revision ac41abda
36:22.19 INFO: Launching /tmp/tmpOjVCK_/firefox/firefox
36:22.19 INFO: Application command: /tmp/tmpOjVCK_/firefox/firefox -profile /tmp/tmpJyHTxU.mozrunner
36:22.19 INFO: application_buildid: 20170829113103
36:22.19 INFO: application_changeset: ac41abda3dd90ff4dba808a56f23ff88c64ee2b7
36:22.19 INFO: application_name: Firefox
36:22.19 INFO: application_repository: https://hg.mozilla.org/integration/mozilla-inbound
36:22.19 INFO: application_version: 57.0a1
Was this inbound build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry', 'back' or 'exit' and press Enter): bad
38:07.87 INFO: Narrowed inbound regression window from [5d8fdaa9, 12d69143] (13 builds) to [5d8fdaa9, ac41abda] (7 builds) (~2 steps left)
38:07.87 INFO: Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=5d8fdaa9efc827fa1bf532ce6c92fbb6b39b5e28&tochange=ac41abda3dd90ff4dba808a56f23ff88c64ee2b7

38:07.87 INFO: Using local file: /tmp/tmpkK0JYW/a5f36a073139--mozilla-inbound--target.tar.bz2 (downloaded in background)
38:07.87 INFO: Running mozilla-inbound build built on 2017-08-29 10:39:32.959000, revision a5f36a07
38:26.36 INFO: Launching /tmp/tmpMcExYQ/firefox/firefox
38:26.36 INFO: Application command: /tmp/tmpMcExYQ/firefox/firefox -profile /tmp/tmp1Z5gaB.mozrunner
38:26.36 INFO: application_buildid: 20170829101631
38:26.36 INFO: application_changeset: a5f36a07313911f1b700960115a944ac68108a3c
38:26.36 INFO: application_name: Firefox
38:26.37 INFO: application_repository: https://hg.mozilla.org/integration/mozilla-inbound
38:26.37 INFO: application_version: 57.0a1
Was this inbound build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry', 'back' or 'exit' and press Enter): good
40:03.72 INFO: Narrowed inbound regression window from [5d8fdaa9, ac41abda] (7 builds) to [a5f36a07, ac41abda] (4 builds) (~2 steps left)
40:03.72 INFO: Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=a5f36a07313911f1b700960115a944ac68108a3c&tochange=ac41abda3dd90ff4dba808a56f23ff88c64ee2b7

40:03.72 INFO: Downloading build from: https://queue.taskcluster.net/v1/task/Vx2Ft53HQI2AuRa2dc2mdQ/runs/0/artifacts/public%2Fbuild%2Ftarget.tar.bz2
===== Downloaded 100% =====
40:08.52 INFO: Running mozilla-inbound build built on 2017-08-29 11:52:02.763000, revision 05066c02
40:25.79 INFO: Launching /tmp/tmp7mxJiJ/firefox/firefox
40:25.79 INFO: Application command: /tmp/tmp7mxJiJ/firefox/firefox -profile /tmp/tmpyxnHHG.mozrunner
40:25.79 INFO: application_buildid: 20170829112926
40:25.79 INFO: application_changeset: 05066c02aca871b5f49fe4bbe1d669181dad8b7b
40:25.79 INFO: application_name: Firefox
40:25.79 INFO: application_repository: https://hg.mozilla.org/integration/mozilla-inbound
40:25.79 INFO: application_version: 57.0a1
Was this inbound build good, bad, or broken? (type 'good', 'bad', 'skip', 'retry', 'back' or 'exit' and press Enter): good
41:45.90 INFO: Narrowed inbound regression window from [a5f36a07, ac41abda] (4 builds) to [05066c02, ac41abda] (2 builds) (~1 steps left)
41:45.90 INFO: No more inbound revisions, bisection finished.
41:45.90 INFO: Last good revision: 05066c02aca871b5f49fe4bbe1d669181dad8b7b
41:45.90 INFO: First bad revision: ac41abda3dd90ff4dba808a56f23ff88c64ee2b7
41:45.90 INFO: Pushlog:
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=05066c02aca871b5f49fe4bbe1d669181dad8b7b&tochange=ac41abda3dd90ff4dba808a56f23ff88c64ee2b7

Comment 7

[:gerard-majax]

After playing a while with mozregression, it does points to https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=05066c02aca871b5f49fe4bbe1d669181dad8b7b&tochange=ac41abda3dd90ff4dba808a56f23ff88c64ee2b7 which is only bug 1392891

Comment 8

[Julien Cristau [:jcristau]]

(In reply to Alexandre LISSY :gerard-majax from comment #6)
> 41:45.90 INFO: Last good revision: 05066c02aca871b5f49fe4bbe1d669181dad8b7b
> 41:45.90 INFO: First bad revision: ac41abda3dd90ff4dba808a56f23ff88c64ee2b7
> 41:45.90 INFO: Pushlog:
> https://hg.mozilla.org/integration/mozilla-inbound/
> pushloghtml?fromchange=05066c02aca871b5f49fe4bbe1d669181dad8b7b&tochange=ac41
> abda3dd90ff4dba808a56f23ff88c64ee2b7

Olly, you reviewed the above changes, maybe you can help while Ehsan is out?

Comment 9

[:gerard-majax]

(In reply to Alexandre LISSY :gerard-majax from comment #4)
> New profile, with the dom.ipc.processCount back to default value (problem
> still reproduced):
> > https://perf-html.io/public/fe18f5dcf0ac462bff1c9242e2308dfc25d4fb25/calltree/?hiddenThreads=&thread=0&threadOrder=0-2-3-4-5-1

Re-captured, using a 360MB buffer in GeckoProfiler (instead of the 9MB default), as it seemed a lot of informations were missing:
> https://perf-html.io/public/a8575d90ddd5abeeb7a2dfcb3a5af8d84eca191e/calltree/?hiddenThreads=&thread=0&threadOrder=0-2-3-4-5-6-7-8-9-10-11-12-1

Comment 10

[Olli Pettay [:smaug][[e-mail]]]

So how do I reproduce this? I'm logged in to github, but loading is fast.
I have a patch which might help, but can't really test it.

Comment 11

[:gerard-majax]

Well, sadly, for me the 100% STR was to be logged on github and have a "big" PR like https://github.com/mozilla/DeepSpeech/pull/805 to reproduce, but others would not reproduce as well, so I'm not too surprised.

If you have a patch with a try builds and linux 64 bits binaries included I surely can grab then to test, given that on a clean mozregression profile I was able to reproduce it as well :)

Does the profile and the regression window seems consistent to you at least?

Comment 12

[Olli Pettay [:smaug][[e-mail]]]

The performance profile makes totally sense, and that is what I based my fix on.

Comment 13

[Olli Pettay [:smaug][[e-mail]]]

Attachment: keep_form_lists_alive_for_awhile.diff

remote: View your change here:
remote:   https://hg.mozilla.org/try/rev/e4b4c5b53d322bbb707c05ae2c53cabca46283e8
remote: 
remote: Follow the progress of your build on Treeherder:
remote:   https://treeherder.mozilla.org/#/jobs?repo=try&revision=e4b4c5b53d322bbb707c05ae2c53cabca46283e8

Comment 14

[Olli Pettay [:smaug][[e-mail]]]

Alexandre, want to test the tryserver builds? Takes a bit time before they are ready.

Comment 15

[:gerard-majax]

Sure, looks like it is built now. I will retest on clean profile, with:
 - https://queue.taskcluster.net/v1/task/IX5hDky-TNygwR2FWbgpvQ/runs/0/artifacts/public/build/target.tar.bz2 which seems to be the latest linux 64 opt build out of m-c (https://treeherder.mozilla.org/#/jobs?repo=mozilla-central&revision=e5f80a639bfe68b68693a5be610f9d36b6c5ad00&filter-searchStr=linux%2064%20opt%20tc)
 - yours :)

Comment 16

[:gerard-majax]

Awesome. I can confirm there is a huge perf improvement with your patch applied, against what I can see on latest m-c as documented above. I would be picky to find some little latency over previous runs from what I remember of the bisect this afternoon, but that may be just my mind.

It's more or less back to normal performances, from what I can judge :)

Thanks!

Comment 17

[Olli Pettay [:smaug][[e-mail]]]

Thanks.

Ehsan, if you're back tomorrow, want to review the change?

Comment 18

[(no longer active)]

Sure!

Comment 19

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/90dd92f271f5
keep nsContentList objects alive for awhile when generating state keys so that new objects don't need to be created all the time, r=ehsan

Comment 20

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/90dd92f271f5

Comment 21

[:gerard-majax]

Fix is available in today's nightly, and I do confirm the good impact :)