Randell Jesup [:jesup] (needinfo me) Reporter
	Description • 7 years ago

+++ This bug was initially created as a clone of Bug #1362039 +++

Name:Firefox
Version:56 changeset e1e4a481b7e8
Fedora 25 x64
Build ID:local opt build
JSGC poisoning off

See STR and results here:  (chrome is chrome57; machine is a fast Lenovo desktop Fedora 25 x64)  

https://docs.google.com/spreadsheets/d/1eXKA1f8zRb98D42XB4uhSYt9JyElpX4QdOdM_hsbfLg

Note we're pretty bad compared to Chrome here, from bar (first paint) until first article visible we're 63% slower, and from there to pageload complete we're 40% slower.  The only thing we equal chrome on is the time from click until new-page-header is visible; if you ignore that part we're ~50% worse; if you include it we're 35% worse.

Profile: (fast machine!)
http://bit.ly/2sssFDt

	Randell Jesup [:jesup] (needinfo me) Reporter
	Comment 1 • 7 years ago

We could use a set of figures/profile for this case on Acer standard HW, standard test setup, etc - thanks!

	Filip Andrei
	Comment 2 • 7 years ago

Sorry for the late response but i was off a few days.Collected a new profile with the Acer hardware that includes only the group page load http://bit.ly/2tUvPyv 
Please let me know is the link is broken or something.

	Mats Palmgren (inactive)
	Comment 3 • 7 years ago

Spending 95ms (3.9%) on waiting to read in error messages kind of sucks.
Maybe we can preload string bundles that we expect to almost always be
used some time shortly after startup (as a background task)?  Or can we
make reporting errors to the console async?

... Facebook script code ...
a/j.prototype.getView
h
0x1f6f0dba4d5
mozilla::dom::GenericBindingMethod(JSContext *,unsigned int,JS::Value *)
mozilla::dom::DocumentBinding::getElementById
nsDocument::GetElementById(nsAString const &)
nsDocument::ReportEmptyGetElementByIdArg()
nsContentUtils::ReportToConsole(unsigned int,nsACString const &,nsIDocument const *,nsContentUtils::PropertiesFile,char const *,char16_t const * *,unsigned int,nsIURI *,nsString const &,unsigned int,unsigned int)
nsContentUtils::GetLocalizedString(nsContentUtils::PropertiesFile,char const *,nsXPIDLString &)
nsStringBundle::GetStringFromName(char16_t const *,char16_t * *)
nsStringBundle::LoadProperties()
nsPersistentProperties::Load(nsIInputStream *)
UTF8InputStream::ReadSegments(nsresult (*)(nsIUnicharInputStream *,void *,char16_t const *,unsigned int,unsigned int,unsigned int *),void *,unsigned int,unsigned int *)
UTF8InputStream::Fill(nsresult *)
NS_FillArray(FallibleTArray<char> &,nsIInputStream *,unsigned int,unsigned int *)
nsJARInputStream::Read(char *,unsigned int,unsigned int *)
0x7ffc6e88c387 (top of stack)

	Randell Jesup [:jesup] (needinfo me) Reporter
	Comment 4 • 7 years ago

As best I could tell looking at the critical part of this, we're simply slower on this pile of JS than Chrome is (though perhaps some bits like Mats flagged may cause some of the slowdown).    Note that I see lots of samples with JS 400+ levels deep I'd guess

Tentatively I'm assigning this to the JS team to investigate why this code takes longer than Chrome.

Mats - please file further spinoffs for things like the error messages.  Thanks!

Naveed - please revector to whomever should look at it.  thanks

	Randell Jesup [:jesup] (needinfo me) Reporter
	Comment 5 • 7 years ago

jonco, dholbert - cc'ing you on the bug we were looking at

	Bobby Chien
	Comment 6 • 7 years ago

Thomas, please advise us if you need more info/profiles. Thanks.

	Thomas Wisniewski
	Comment 7 • 7 years ago

I'll let you know ASAP; I'm just getting into the profile now. (Sorry for the delay!)

	Thomas Wisniewski
	Comment 8 • 7 years ago

I agree with :jesup and Mats' assessments. The only clearly unreasonable thing I see Gecko doing in the profile is spending 96ms of the content processes' 825ms in nsContentUtils::ReportToConsole.

According to the profile, essentially all of the content script's runtime is devoted to handling the responses of XHRs which fetch and render JSON DOM templates, with the remaining few ms spent on actually setting up the XHR itself and on a sync cookie-read, each negligible-looking.

The rendering of the templates appears to be done with stock createElement type of DOM methods (their _displayPagelet/render/renderHeader methods), with only a couple of 4ms/6ms minor GCs appearing in the profile, and only a handful of spots where Gecko spends more than the 1ms resolution of the profile in C++ (4-7ms spots of restyles/reflows/script compilations). So there isn't much of note here.

That said, I did see that the summary tab of the profile says that 30.8% of the time is spend on GCs, so perhaps that's a lead?

The only other note I have is that of the 72ms spent in nsRefreshDriver::Tick, 67ms are spent running JS which calls getBoundedClientRect/offsetWidth/clientWidth, which need to build frame trees. I also see setTimeout in the profile, but not requestAnimationFrame. Perhaps that's a sign that they could benefit from using rAF as well?

	Bobby Chien
	Comment 9 • 7 years ago

Thanks, Thomas.

	Bobby Chien
	Comment 10 • 7 years ago

Tracking under [qf] for triage.

	Thomas Wisniewski
	Comment 11 • 7 years ago

Ah, I just realized that there was another profile in comment 0 (on non-reference hardware, but still). Looking over that profile, it looks like they're indeed using requestAnimationFrame (checking out nsRefreshDriver::RunFrameRequestCallbacks). Almost 5% of that profile is spent in their callback, and while I'm not clear on why they would be creating dom nodes and such during rAF callbacks, that's what the profiles are implying they do.

As with the overall profile the time is mostly spent in _displayPagelet, with the C++ engine time being spread all over. The summary tab doesn't show GC taking up nearly as much time, however.

Interestingly, the console logging doesn't take up any time at all in this version... could that be an OS-specific quirk, or the difference between debug and non-debug builds?

	Randell Jesup [:jesup] (needinfo me) Reporter
	Comment 12 • 7 years ago

Comment 0 was non-debug, as all profiles for analysis generally should be.  Perhaps os-specific (though I doubt it), or perhaps a console was open?  Or some var was enabled for logging?

	Mats Palmgren (inactive)
	Comment 13 • 7 years ago

(In reply to Thomas Wisniewski from comment #8)
> The only clearly unreasonable
> thing I see Gecko doing in the profile is spending 96ms of the content
> processes' 825ms in nsContentUtils::ReportToConsole.

FYI, I think that should be fixed now: bug 1377377.

	Mike Conley (:mconley) (:⚙️)
	Comment 14 • 7 years ago

Hey jesup, with bug 1377377 fixed, how bad is the remaining regression (assuming there is one)?

	Sean Feng [:sefeng]
	Comment 15 • 6 years ago

As of Oct 12, 2018, I did a new experiment for this ticket. 

I used https://www.facebook.com/groups/theboardgamegroup/, and the exact procedure and results can be found at https://docs.google.com/spreadsheets/d/15fXf37FiNfm37afi4vQBCDRv61cPp3imWkehEQhRcf0/edit?usp=sharing.

In summary, we were noticeably slower than Google Chrome, this was very obvious on the low-end machine I used. One important thing that's worth to mention is I observed Chrome had the ability to load the banner image way faster than us, it was able to show the image before the announcements and description sections were filled, whereas Firefox would always need to wait for announcements and description sections were filled, then showed the banner image.