1362039 - Facebook home navigation start

Status: RESOLVED INCOMPLETE

(Core :: Graphics, defect, P3)

Description

[Filip Andrei]

Name:Firefox
Version:55.0a1
Windows 10 64 bit
Build ID:20170503030212


Using STR Facebook scenario https://docs.google.com/spreadsheets/d/1Kxn850VasyaG_WfRg3pMInW0hbIT8LP7pRPBYTIpdbM/edit#gid=679575660
 here is the Gecko profile.If more information is needed please contact me

Gecko profile: https://perfht.ml/2p9k7fB

Comment 1

[Jean Gong :jgong]

Randell,  Please analysis the attached Gecko profile. Thanks, Jean

Comment 2

[Randell Jesup [:jesup] (needinfo me)]

What exactly are the numbers in the spreadsheet?  They're basically unexplained.  Seconds?  Frames?  what are the larger numbers in white background, vs numbers in grey background?  Which line of the STR corresponds with which set of numbers?

Note: While this may have been repeatable for you, clearly I'll be unable to repeat it here, though I realize I'm not being asked to.

Thanks

Comment 3

[Filip Andrei]

Actually the numbers from the doc are frames and here is an example on how the numbers correspond:

Ex:
Facebook
1.home navigation start (autocomplete disappears) 623-it tooked 623 frames to get here from the point we start the browser and accessed a link
2.first nonblank -662-at frame 662 an element is first displayed or a picture/header for the requested site
3. "39" here we have a difference between these two steps 

We are running 5 measurements for each site and each step for Firefox and Chrome and in the end we are comparing them and if a step is slower than Chrome more than 20% we are logging a bug and add a Profile.

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

Is there a screencast recording of the exact run where the profile was taken?  Was it any of 1-4 in the spreadsheet?

It's hard to look a the profile, not knowing how long each step in the sequence took (or where in the 75 second profile it started).  Runs 1-4 had variations of 2x in times various steps took.  

Thanks!

Comment 5

[Randell Jesup [:jesup] (needinfo me)]

So, the only item here that's clearly slower than Chrome is the "first group item" step, after "group navigation start".

"user photo appears" appears slower, but that's largely due to 1 outlier and an "N/A" - the "median" is more like 15% slower - easily within the margin of noise here.  We're even user-noticeably faster on the first part.

part of why I want the info from comment 4 is so I can find what part of the profile matches "first group item".

Comment 6

[Filip Andrei]

Actually we don't have a screencast for the run but I collected another profile just now on the latest nightly and the only think that I record is the "first group item" action.The profile is collected with the Acer hardware that is a little slower but reflects the performance problem.




Profile link:https://perf-html.io/public/830842928218cd9298c70db69582695fc21e8b07/calltree/?thread=2

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

I looked at the "Load a user page" item in more detail (also using it to figure out how to run profiles myself).  This is on MUCH faster hardware, using linux64 Nightly and using Linux gtk-recordmydesktop set to 30fps (it maxes out at 50fps).  ctrl-shift-alt-r recording in gnome is non-fixed-rate; I may try it again now.  I build a dumb webpage to find the times in the recording (what are you using to get the frame numbers?)

I just used times instead of frame numbers, which appears to work fine.

In this case, we're 24% slower than chrome57.  The dividing it into two sections; one early (loading start until the user header with image is loaded, we're 34% slower.  Dividing further (which may be overkill), nav start until we see the blue bar we're ~50% slower -- from there until the user header with image is up we're faster than chrome by 20%.  So part of this might just be when things paint, but maybe in that first section we're slower on something significant.   From Header load until user page is fully loaded, we're 15% slower, which is near the margin of error in a test of this magnitude (average for the entire sequence is only around 0.5 seconds).

My profiles for that might be harder to interpret (fast machine), but I can try to grab one.  Might be interesting to compare to a target-machine (Acer) profile for the same-ish thing. (use some random group, and click the first user in the group).  I find starting with a warm browser is preferable; you avoid some things like addon update checks which are (still) timer-based after starting the browser.  Also you can measure N times using back, then click on the user again.

Here's my spreadsheet: https://docs.google.com/spreadsheets/d/1sCqHk35gcQS2EHvyZOSqz3Wtfa6DQtUWbCd6hK-93wo

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

(In reply to Filip Andrei from comment #6)
> Actually we don't have a screencast for the run but I collected another
> profile just now on the latest nightly and the only think that I record is
> the "first group item" action.The profile is collected with the Acer
> hardware that is a little slower but reflects the performance problem.
> 
> 
> 
> 
> Profile
> link:https://perf-html.io/public/830842928218cd9298c70db69582695fc21e8b07/
> calltree/?thread=2

This sub-profile shows 3.4% in DoesLayerHaveOutOfDateFrameMetrics()
https://perf-html.io/public/830842928218cd9298c70db69582695fc21e8b07/calltree/?invertCallstack&range=41.0154_44.2149&thread=5

We're also spending a fair bit of time (18ms, 1.7%) in dom::cryptoBinding::getRandomValues(), all ending up in GetServiceByContractID

And a fair bit (13ms, 1.2%) in AssignASCII(), from HTMLTextAreaElement::GetType()

12ms in JS::NumberValue


In this range (the 20375ms event delay for Content), there are some interesting ones:
https://perf-html.io/public/830842928218cd9298c70db69582695fc21e8b07/calltree/?range=5.5772_25.9528&thread=5

WalkRuleTree is 50ms
RuleHash_ClassCSMatchEntry is 20ms
JSDefineProperties() is 246ms(!)  (inside HTMLTableElement::WrapNode)
Even 22ms inside nsGlobalWindow::SetTimeout() - for a single call.  

But most of the time Content is idle.... :-(  It appears it's waiting on IPC for something, or other non-tracked threads are eating the time (more likely, or in addition).

Comment 9

[Randell Jesup [:jesup] (needinfo me)]

I think there's a problem with that profile.... mstange does as well.  Filip, can you try again?

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

Profile (on a hot machine) of a user profile page load.  We're slowest on the click -> blue header part, which is about 10.130 to 10.150 or so, and gets painted around 10.210.   In the first part (before rendering/painting/compositing), it's almost all HidePopupCallback(), which runs panelRemover() in panelUI.js.  Most of that is in ReplaceOrInsertBefore()->...->RemoveScriptBlocker() (50%), plus some destroying a DocShell, and RemoveChildAt(), which interestingly talks to the addon manager... - though this appears to be the Gecko Profiler!

http://bit.ly/2rWPYSk

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

So, RemoveScriptBlocker looks expensive there (though it's only ~10ms).  

Looking at the entire remove->paint process, there's a lot of painting (10.170s to 10.210s) (40ms, 10ms of which nsDisplayBackgroundColor::Paint) -- all just to remove the popup before erasing the page.  7ms is in DrawBufferWithRotation(?) -> FillRect->memmove

Comment 12

[Randell Jesup [:jesup] (needinfo me)]

Tentatively assigning to gfx, but there's a parallel issue with the code that runs before painting starts (panelUI.js, RemoveScriptBlocker(), etc).  I'm focusing on this because this was the area we fell a long way behind Chrome in my spreadsheet (50% slower).  

Discussing with billm/bz about the ScriptBlocker/insert/remove/etc parts on IRC

There's still more to do with Facebook...  and even with this profile likely, so feel free to make spinoff bugs.

Comment 13

[Randell Jesup [:jesup] (needinfo me)]

Per IRC, that was due to the popup for the profiler getting erased... new profile is here:
http://bit.ly/2ss3HnH

Comment 14

[Filip Andrei]

This profile should be good,tooked from Acer reference hardware on the latest nightly build nr:20170627030209

http://bit.ly/2tlK0zw

Comment 15

[Randell Jesup [:jesup] (needinfo me)]

Is this the "first group item" action?  (as in comment 6)

What sequence of actions were captured in this profile?  Thanks

Comment 16

[Filip Andrei]

Here we captured the navigation from the first group to facebook home.

Comment 17

[Bobby Chien]

Randell, do we have more action here? Or do you need any other profiles/info? Thanks.

Comment 18

[Ionut Budeanu]

Providing the new profile based on the latest benchmark measurements.

Name: Firefox
Version: 57.0a1
Windows 10 64 bit
buildID: 20170910220126


Steps to reproduce:
1. Launch browser.
2. Record with Gecko Profile:
   Fill facebook.com in Navigation Start while you are already logged in, then press enter.
3. Capture the profile.
4. Share the profile.

Gecko profile: https://perfht.ml/2w0MFjT