Closed Bug 1330565 Opened 4 years ago Closed 4 years ago

We spend 1 second reflowing a google slide when loading

Categories

(Core :: Layout, defect)

defect
Not set
normal

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: ehsan, Unassigned, NeedInfo)

References

(Blocks 1 open bug)

Details

(Keywords: perf)

See the test case in bug 1326346.  This can be easily reproduced by just loading the page.  Here is a profile: <https://clptr.io/2jGUqET>

This takes 1 second out of the total 9 seconds that we spend loading the page.

Jet, can you please find somebody to investigate this?
Flags: needinfo?(bugs)
See Also: → 1330218
Flags: needinfo?(dbaron)
Testcase URL (from bug 1326346 comment 4): https://docs.google.com/presentation/d/1VvEZ9DSIlbjXXXY01wAccMdaF2q9wA1Zx21-nuH3KQc

I'll take a look here and see what I can find out...
Flags: needinfo?(dholbert)
Blocks: FastReflows
Er, that might not be a good testcase actually. (The original testcase has been removed due to having confidential info, and this new testcase might not have enough contents to usefully trigger the problem.)

Anyway, for now I'll just look at ehsan's profile, without an active testcase.  Here are a few things I see:
 - 651ms is spent in layout flushes (in PresShell::DoReflow)  https://perfht.ml/2l0H1DR

And the main reasons for those flushes seem to be:
 - 405ms is spent in "getNumberOfChars" https://perfht.ml/2l0Dy8m  (which is SVGTextContentElement::GetNumberOfChars, which flushes reflow in its call to GetSVGTextFrame)
 - 186ms is spent in "get_offsetWidth"  https://perfht.ml/2l0fWAW

So for this testcase, SVGTextContentElement::GetNumberOfChars would probably be the thing to optimize, if it's possible to avoid flushing reflow there sometimes...
(In reply to Daniel Holbert [:dholbert] from comment #2)
> Er, that might not be a good testcase actually. (The original testcase has
> been removed due to having confidential info, and this new testcase might
> not have enough contents to usefully trigger the problem.)
> 
> Anyway, for now I'll just look at ehsan's profile, without an active
> testcase.  Here are a few things I see:
>  - 651ms is spent in layout flushes (in PresShell::DoReflow) 
> https://perfht.ml/2l0H1DR

Anything catching your eyes there?  Based on a quick look, I see expensive textrun construction, some stuff from gfxFontEntry/gfxMacFont doing some kind of synchronous wait on the system, nsIFrame::StyleDisplay again, some slow hashtable lookups from HTMLScrollFrame::Reflow and others, etc.

> And the main reasons for those flushes seem to be:
>  - 405ms is spent in "getNumberOfChars" https://perfht.ml/2l0Dy8m  (which is
> SVGTextContentElement::GetNumberOfChars, which flushes reflow in its call to
> GetSVGTextFrame)

That's bug 1330236.

>  - 186ms is spent in "get_offsetWidth"  https://perfht.ml/2l0fWAW

Another synchronous reflow.
Keywords: perf
(In reply to :Ehsan Akhgari from comment #3)
> >  - 651ms is spent in layout flushes (in PresShell::DoReflow) 
> > https://perfht.ml/2l0H1DR
> 
> Anything catching your eyes there?

Inside the reflows? Haven't looked in detail yet. Will add more after I have. (So far I've been focusing more on "why are we reflowing")

> Based on a quick look, I see expensive
> textrun construction, some stuff from gfxFontEntry/gfxMacFont doing some
> kind of synchronous wait on the system,

This seems to be in the native function "availableMembersOfFontFamily", which occupies 30ms of the profile: https://perfht.ml/2lH1aTK

Bug 517045 comment 12 says "the time attributed to availableMembersOfFontFamily is the time needed to enumerate faces within a given family."  I'm guessing this has to do with web fonts that are used by this page, which are being rendered for the first time, though I'm not too sure.  Unless we discover this getting hit repeatedly, I'm betting this isn't something we can do anything about.

> > And the main reasons for those flushes seem to be:
> >  - 405ms is spent in "getNumberOfChars" https://perfht.ml/2l0Dy8m  (which is
> > SVGTextContentElement::GetNumberOfChars, which flushes reflow in its call to
> > GetSVGTextFrame)
> 
> That's bug 1330236.

Oh, awesome! That helped a lot here, then, I expect.  (Looks like ehsan confirmed that it cut out ~300ms from the load time here, in bug 1330236 comment 7.  That sounds about right, given my measurements of 400ms being spent in this function, in comment 2. I assume it didn't cut out the full 400ms, simply because some of that was real layout work that we still have to do -- we just do it some other time.)
Depends on: 1330236
Looking at profiles from before & after bug 1330236 landed, it looks like some of the SVG "getNumberOfChars()" layout flushes were likely just punted to be slightly-later SVG "getSubStringLength()" layout flushes.

At least, getSubStringLength barely shows up (6ms) in a profile of a build from before bug 1330236 landed:
  https://perfht.ml/2lHovo0
...whereas it's 92ms in a profile of a build from just after:
  https://perfht.ml/2lHiDeu
(This is using a MoCo-private recreation of the doc with some confidential info, which is here [login required]: https://docs.google.com/presentation/d/1KfZvm4NWE496Sjwrfm33PqzY6BRiBf8RN06OTJILUNc/edit )
Flags: needinfo?(dholbert)
I suspect there's not much more to be done here (nothing that'll buy us any noticeable wins, at least).

In my latest profile from comment 5, I'm only seeing 151ms of reflowing, during an 8.5-second period of near-continuous jank:
https://perf-html.io/public/cf9d39e809390e60ea50f1425bf841a8d90accf0/calltree/?range=1.4473_9.0846&search=DoReflow&thread=2

So, for me at least, the time in reflow is now ~2% of this jank time (as opposed to 11% back in comment 0 -- 1 second out of 9 seconds).

ehsan, if you're still seeing reflow take up a significant portion of the jank time here in recent Nightlies (using the password-protected slide from comment 5), please let me know! Otherwise, I suspect this has become fixed by bug 1330236 & perhaps other bugs, and we should probably resolve it as largely-fixed-by bug 1330236 (per end of comment 4).  There's still quite a bit of jank :-/ but hardly any of it is in reflow -- and bug 1326346 still covers that.
Flags: needinfo?(ehsan)
I just reprofiled the new document and now I get a 10ms total reflow.  I'm quite skeptical that the new version of the document is different in some important way, but sadly there seems to be no way of actually testing with the same thing as comment 0.  Let's close this.
Status: NEW → RESOLVED
Closed: 4 years ago
Flags: needinfo?(ehsan)
Resolution: --- → INCOMPLETE
A large part of the reflow times in the profile are inside platform font handling, which is probably at least partially cached, so I wouldn't be surprised if these reflows are slower the first time you load this page in a given session.
(In reply to Markus Stange [:mstange] from comment #9)
> A large part of the reflow times in the profile are inside platform font
> handling, which is probably at least partially cached, so I wouldn't be
> surprised if these reflows are slower the first time you load this page in a
> given session.

The 10ms was the first time I measured.
Duplicate of this bug: 1326346
Flags: needinfo?(bugs)
You need to log in before you can comment on or make changes to this bug.