1359341 - Experiencing slow page notifications on https://pastebin.com/EpK0Z41P

Status: RESOLVED FIXED

(Core :: Layout: Positioned, defect)

Description

[mdew]

User Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:55.0) Gecko/20100101 Firefox/55.0
Build ID: 20170424103021

Steps to reproduce:

Visit: https://pastebin.com/EpK0Z41P
Wait of the page to load/attempt to load.
Will cause firefox to report slow page issues


Actual results:

Causes browsing to slow, and report slow page issues.


Expected results:

Should load instantly.

Comment 1

[mdew]

Interesting to note; 

Syntax highlight off: https://pastebin.com/CUNH8Jt9   Seems to load, as expected, without issues.

Comment 2

[Jim Jeffery not reading bug-mail 1/2/11]

Confirming the issue, setting to 'NEW'

Comment 3

[Emil Pasca [:emilpasca]]

User Agent:  Mozilla/5.0 (Windows NT 10.0; WOW64; rv:53.0) Gecko/20100101 Firefox/53.0

I have tested this issue on Windows 10 x64 with the latest Firefox release (53.0) and the latest Nightly (55.0a1-20170427030231) and managed to reproduce it.
After visiting https://pastebin.com/EpK0Z41P, the browser becomes slow, and reports slow page issues.

I had captured a performance profile: https://perfht.ml/2powhTK

Mike, when you got the time, can you please have a look at this?

Thank you.

Comment 4

[Mike Conley (:mconley) (:⚙️)]

The profile seems to suggest that some ad-tech JavaScript being served up on the page from https://s.tribalfusion.com/real/tags/Pastebincom/Unsure/tags.js is causing a layout flush, and a pretty bad one too.

Not sure if there's much we can do here, but needinfo'ing ehsan to see if he knows where we should put this.

Comment 5

[(no longer active)]

Jet, can you please find someone on the layout team to take a look at this to see if there's something to be improved on Gecko's side?

Comment 6

[Jet Villegas (inactive)]

The text highlighting in PasteBin appears to set selection state and caret position in a loop: 
https://pastebin.com/js/pastebin.js

The C++ profile spends a lot of time in AreAllEarlierInFlowFramesEmpty:
http://searchfox.org/mozilla-central/source/layout/generic/ReflowInput.cpp#1226

Mats: can you trace how we're getting into this worst-case state? It seems the AreAllEarlierInFlowFramesEmpty traversal is visiting every node from the top to the end here, and coming up empty in each case. Perhaps we can cache some state and add a fast-path here.

Comment 7

[Mats Palmgren (inactive)]

I'll take a look...

Comment 8

[Mats Palmgren (inactive)]

Attachment: Testcase

So, there's two problem with this page.  First, the root problem on this page
is that it creates 75000 of these elements:

<div role="log" aria-live="assertive" aria-relevant="additions" class="ui-helper-hidden-accessible"></div>

and inserts them on the same line, and while doing so manages to trigger
a reflow for each inserted element.

Secondly, the above <div>s are abs.pos. boxes with a static position and
triggers this code:
http://searchfox.org/mozilla-central/rev/15edcfd962be2c8cfdd0b8a96102150703bd4ac5/layout/generic/ReflowInput.cpp#1395-1400
which is O(n^2) for n boxes on the same line which are empty (which is
true here).

We can fix the second part of the problem, but probably not the first.

Comment 9

[Mats Palmgren (inactive)]

BTW, AreAllEarlierInFlowFramesEmpty by itself doesn't do much on these boxes.
We do two virtual calls (IsSelfEmpty() and PrincipalChildList()) and then return.
It's doing this on all siblings in a loop that kills it.
http://searchfox.org/mozilla-central/rev/15edcfd962be2c8cfdd0b8a96102150703bd4ac5/layout/generic/ReflowInput.cpp#1227

Comment 10

[Mats Palmgren (inactive)]

Attachment: part 1 - Make PresShell::GetPlaceholderFrameFor return a nsPlaceholderFrame.

nsFrameManager already return the concrete type so I see no reason
for PresShell to destroy that type info.  nsPlaceholderFrame is
final so this can help the compiler devirtualize some calls.

Comment 11

[Mats Palmgren (inactive)]

Attachment: part 2 - Add a couple of private frame state bits to nsPlaceholderFrame to be used for propagating "line emptiness" during reflow.

Comment 12

[Mats Palmgren (inactive)]

Attachment: part 3 - Propagate AreAllEarlierInFlowFramesEmpty() state on placeholders down the line. We can stop iterating siblings if we find a placeholder with a stored state.

This fixes the O(n^2) problem in CalculateHypotheticalPosition for this page
because we'll find a state on aPlaceholderFrame's prev-sibling every time.

Comment 13

[Mats Palmgren (inactive)]

Attachment: part 4 - Optimize initializing a nsBlockInFlowLineIterator for single-line blocks by skipping the search for aFindFrame.

This should also help in some cases (probably not the pastebin URL though).
It avoids doing a "line->Contains(child)" which is a linear search
up to 200 siblings, or a hash table lookup in the >=200 siblings case.
(It helps for the attached testcase for example.)

Comment 14

[Mats Palmgren (inactive)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=1026905452ec01347b49fa07f0988648871dee7f

Comment 15

[Mats Palmgren (inactive)]

So, these patches removes AreAllEarlierInFlowFramesEmpty from the perf stats and
CalculateHypotheticalPosition is now at 1.5%.  I'm not sure if it's worth spending
more time on optimizing this case.  The root cause is that the page triggers a huge
amount of reflows, which should be easy to avoid.

The page seems a lot faster in Chrome though.  It also has the above 75k abs.pos.
elements, so I wonder if there's some other optimization we could make to avoid
reflowing so much in this case.

Comment 16

[mdew]

how much of a performance improvement is it with these patches?

Comment 17

[Mats Palmgren (inactive)]

Not enough, I'm afraid.  With these patches the perf log is still dominated
by reflow and while we can probably trim a few percent off of that (hash table
lookups associated with the frame property table and placeholder map for example)
it still wouldn't make the performance acceptable on this page.

The root problem is that the page is triggering reflow on O(n^2 / 2) boxes
and with n>75000 it's hard to make that not noticeable.  I don't see any
easy solutions for that, so we should probably reach out to Pastebin to
ask them not to do that.  The empty <div role="log"> elements might be a bug
in their code, but if they still need them for some reason the right way to
insert them is to first collect them in a document fragment and then insert
that after they are done generating the elements.

Comment 18

[Mats Palmgren (inactive)]

Attachment: Testcase

A testcase with visibility:hidden to remove painting from obscuring the layout perf results.

A local optimized build with these patches displays "6.601 seconds"
and without the patches "9.968 seconds".  Chrome displays "0.332 seconds"
on the same machine.  (this test has n=1000)

Comment 19

[Mats Palmgren (inactive)]

Note that I have --enable-optimize="-O1 -g" in that optimized build though,
so the numbers are much better with our default (more aggressive) flags.
For comparison, I get "1.76 seconds" with a stock Firefox 53.

Comment 20

[Mats Palmgren (inactive)]

Here's a better testcase comparison using the Try build from comment 14:

Chrome Canary on Linux64 (60.0.3100.0 (Official Build) dev (64-bit)):
500  0.095
1000 0.33
2000 1.215
3000 2.669
4000 4.654
5000 7.415
6000 10.307
7000 14.006
8000 19.542

Firefox Linux64 PGO w. patches (try build from comment 14):
500  0.217
1000 0.808
2000 3.162
3000 7.069
4000 12.516
5000 19.718
6000 28.129
7000 38.344
8000 49.886

current Nightly on Linux64:
500  0.371
1000 2.038
2000 12.936
3000 39.835
4000 90.236

Firefox 53 on Linux64:
500  0.335
1000 1.779
2000 11.289
3000 36.106
4000 81.774

So while the patches is a big improvement we're still behind Chrome by a factor of ~2.5.
I was also surprised to see that the current Nightly is slightly slower than 53. :-(

Comment 21

[mdew]

Possible regression somewhere?

Comment 22

[Mats Palmgren (inactive)]

It's quite possible, yes.  But I'd recommend comparing a Nightly v53 build first
if we still have those around, just to rule out that the difference comes from
some code that is permanently #ifdef'ed out in release builds.

Comment 23

[Jonathan Kew [:jfkthame]]

Comment on attachment 8869859 [details] [diff] [review]
part 3 - Propagate AreAllEarlierInFlowFramesEmpty() state on placeholders down the line.  We can stop iterating siblings if we find a placeholder with a stored state.

Review of attachment 8869859 [details] [diff] [review]:
-----------------------------------------------------------------

Looks a nice optimization, thanks for tracking this down.

Comment 24

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/ac1e17e452ba
part 1 - Make PresShell::GetPlaceholderFrameFor return a nsPlaceholderFrame.  r=jfkthame
https://hg.mozilla.org/integration/mozilla-inbound/rev/18e3dfae96fa
part 2 - Add a couple of private frame state bits to nsPlaceholderFrame to be used for propagating "line emptiness" during reflow.  r=jfkthame
https://hg.mozilla.org/integration/mozilla-inbound/rev/08e64a7a7495
part 3 - Propagate AreAllEarlierInFlowFramesEmpty() state on placeholders down the line.  We can stop iterating siblings if we find a placeholder with a stored state.  r=jfkthame
https://hg.mozilla.org/integration/mozilla-inbound/rev/3cc5123e9147
part 4 - Optimize initializing a nsBlockInFlowLineIterator for single-line blocks by skipping the search for aFindFrame.  r=jfkthame

Comment 25

[Mats Palmgren (inactive)]

I filed bug 1367151 to see if we can get pastebin.com to fix this on their side too.

Comment 26

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/ac1e17e452ba
https://hg.mozilla.org/mozilla-central/rev/18e3dfae96fa
https://hg.mozilla.org/mozilla-central/rev/08e64a7a7495
https://hg.mozilla.org/mozilla-central/rev/3cc5123e9147

Comment 27

[Jet Villegas (inactive)]

(In reply to Mats Palmgren (:mats) from comment #8)
> Created attachment 8869856 [details]
> Testcase
> 
> So, there's two problem with this page.  First, the root problem on this page
> is that it creates 75000 of these elements:
> 
> <div role="log" aria-live="assertive" aria-relevant="additions"
> class="ui-helper-hidden-accessible"></div>
> 
> and inserts them on the same line, and while doing so manages to trigger
> a reflow for each inserted element.

		// Append the aria-live region so tooltips announce correctly
		this.liveRegion = $( "<div>" )
			.attr({
				role: "log",
				"aria-live": "assertive",
				"aria-relevant": "additions"
			})
			.addClass( "ui-helper-hidden-accessible" )
			.appendTo( this.document[ 0 ].body );

I wonder if Chromium correctly evaluates "ui-helper-hidden-accessible" as having no size contribution and skips the reflow. Is there a logical place we can add a similar fast path?

Comment 28

[Mats Palmgren (inactive)]

I suspect Chrome is also reflowing the page in response to .offsetHeight (or whatever
the page is doing) after each abs.pos. is inserted.  It just seems that they are faster
in this case and that they generally give a better impression even if the page is slow,
i.e. they paint the first page sooner and it's easier to interact with the page while
it's still reflowing (as I noted bug 827937 comment 18).

One thing that would help here is making reflowing placeholders faster.
(roughly half the boxes we're reflowing on this page are placeholders)
I filed bug 1367711 on this.