1427625 - Performance cliff loading a Taskcluster log

Status: RESOLVED FIXED

(Core :: Layout, defect, P3)

Description

[(Away)]

https://public-artifacts.taskcluster.net/IRyXyVAyT5yMylJITj1rfg/0/public/logs/live_backing.log

Opening that link sends all of Firefox 57, 58, 59 into a busy CPU loop for about 30 seconds. Windows Performance Analyzer says it's all in reflow.

I know that Taskcluster logs are always a bit sluggish to load, but I don't remember it being _this_ bad.

Comment 1

[(Away)]

Jet, do you have someone who can take a look at this before the log file ages out?

Comment 2

[Jet Villegas (inactive)]

Moved the log file to a server that won't expire under us.

Smells like bug 934770. (See also bug 1247080.)

(In reply to dmajor (offline) from comment #0)
> I know that Taskcluster logs are always a bit sluggish to load, but I don't remember it being _this_ bad.

Would you mind firing this up in a couple of older builds? I'd love to know when that started. Thx!

Comment 3

[Jet Villegas (inactive)]

[ Triage 2017/02/20: P3 ]

Comment 4

[Xidorn Quan [:xidorn] UTC+10]

I did a profile with the url in comment 2 with a local profiling build, and I record a ~190s range.

The total CPU time is ~98s, which can be roughly split into:
* layout: 28.8s (interruptible)
* style: 19.5s
* paint: 12.6s
* nsTextFrame::CharacterDataChanged: 18.1s
* nsTextFragment::Append: 1.1s (almost all of this is for allocation)
* PresShell::DoUpdateApproximateFrameVisibility: 1.3s

In the remaining ~16.6s, majority of time (~15.1s) are spent on waiting on the event loop.

The profile: https://perfht.ml/2CMcT85

The main reason that it keeps CPU busy seems to be that the log keeps coming, and we need to update the content and restyle, reflow, paint things over and over again. I'm a bit surprised at the time spent in those big four, actually. Maybe we can try to optimize the incremental reflow to handle this kind of case faster.

If I load this from file directly, the total time spent is ~17s, in which only layout shows up with 7.9s interruptible and 9.1s non-interruptible, style and paint both take less than 0.1s.

Given this, I suspect whether this really is a regression... The file is 109MB, which is quite large for a text file. And since majority of time when loading from remote is taken by incremental handling, the CPU usage depends a lot on the network speed and the file size itself. Maybe the reason it wasn't that bad is simply because files weren't that big, or the network was faster.

Comment 5

[Xidorn Quan [:xidorn] UTC+10]

This is the profile when loading from local: https://perfht.ml/2CKFKKh

Comment 6

[Alice0775 White]

Disabling stylo fixes the slowness.

user_pref("layout.css.servo.enabled", false);
(Needs restart. And also need to clear all history etc to prevent Bug 1384094)

Comment 7

[Xidorn Quan [:xidorn] UTC+10]

(In reply to Alice0775 White from comment #6)
> Disabling stylo fixes the slowness.

This doesn't seem to be true. I can reproduce this with or without stylo enabled.

But it does seem restyle is slower with stylo than the old style system in this case. A restyle in my new profile with stylo disabled near the end of the process usually takes 70~90ms, while in my previous stylo profile, that takes 120~140ms. The reflow after restyle seems to also take longer with stylo than the old style system.

It's probably worth some investigation.

Comment 8

[Xidorn Quan [:xidorn] UTC+10]

For comparison, this is a profile with stylo disabled: https://perfht.ml/2FaDsJs

(Since this is affected by network speed, the details in it could vary, so the most useful thing is probably the ticks near the end.)

Comment 9

[Emilio Cobos Álvarez (:emilio)]

Looks like most of the `Servo_` time is spent on ServoStyleContext refcount churn, and we're restyling a bunch of text styles. I'm not sure what would cause such a restyle in that page.

For the text to get restyled, its parent's style needs to change. I don't know what would dynamically change the style of the element in that page...

Comment 10

[Emilio Cobos Álvarez (:emilio)]

Attachment: Testcase that shows the spurious restyles.

This causes a couple PostRestyleEvent(<pre>, eRestyle_Subtree) to be posted, which explain the restyles shown above. I haven't debugged where they come from yet.

Comment 11

[Emilio Cobos Álvarez (:emilio)]

So that subtree restyle comes from RestyleForEmptyChange, which is a bug, since the node wasn't empty to begin with. But since only the character data has changed (we haven't created a new text node), we don't know that.

We should specialize CharacterDataChanged in the restyle manager to fix this, instead of deferring to ContentInserted / ContentAppended.

Comment 12

[Emilio Cobos Álvarez (:emilio)]

And the reason it has the slow node flag to begin with is because of https://searchfox.org/mozilla-central/rev/056a4057575029f58eb69ae89bc7b6c3c11e2e28/layout/style/res/quirk.css#122

Comment 13

[Xidorn Quan [:xidorn] UTC+10]

Sounds like we should probably just make it not quirk?

Comment 14

[Emilio Cobos Álvarez (:emilio)]

(In reply to Xidorn Quan [:xidorn] UTC+10 from comment #13)
> Sounds like we should probably just make it not quirk?

That is observable and all that... We'd need to push a spec change and such, which may end up being more work than fixing the actual bug :)

Comment 15

[(not currently active) Ted Mielczarek]

I was just noticing that loading a raw Taskcluster build log was basically unusable in my Nightly and dmajor pointed me here. It was bad enough that the tab seemed to be unresponsive, and when I restarted to apply an update the browser process actually killed the content process because it was unresponsive:
https://crash-stats.mozilla.com/report/index/7f038192-c501-4d34-931b-670ab0180227
https://crash-stats.mozilla.com/report/index/b75025dc-5bf1-4eca-ad66-965b30180227 (I got another update after restarting and it happened again)

Comment 16

[Emilio Cobos Álvarez (:emilio)]

Attachment: Bug 1427625: Optimize appends to avoid restyling unnecessarily.

This unfortunately doesn't fix my test-case (because we're replacing the text
content all the time and all that), but it's still worth it, since it fixes the
case we care about (the parser appending).

We could also optimize pure insertions (since in that case we can still figure
out what the old text was), but it's probably annoying and not worth the churn.

In any case, we cannot optimize anything that resembles any kind of removal,
because from there we don't know the old text in any way (and the text nodes
like to reuse string buffers and such).

We could do two other optimizations to replace / extend this one, in that order:

 * Pass the buffer and length to CharacterDataWillChange, and use that to get
   the exact old text and the new one in RestyleManager. That would make the
   optimization exact.

 * Pass some sort of Maybe<bool> mWasWhitespace down the CharacterDataChangeInfo
   which is computed like:

    HasFlag(NS_CACHED_TEXT_IS_ONLY_WHITESPACE)
      ? Some(NS_TEXT_IS_ONLY_WHITESPACE)
      : Nothing()

It's not clear to me it's going to be completely worth the churn, so I haven't
done those yet, if we see code in the wild which resembles my testcase, we can
think of doing it.

Review commit: https://reviewboard.mozilla.org/r/223494/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/223494/

Comment 17

[Xidorn Quan [:xidorn] UTC+10]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review229696

r=me with nits below addressed.

::: dom/base/nsGenericDOMDataNode.cpp:932
(Diff revision 1)
>  
>    while (cp < end) {
>      char ch = *cp;
>  
> +    // NOTE(emilio): If you ever change the definition of "whitespace" here, you
> +    // need to change it to in RestyleManager::CharacterDataChanged.

Redundant "to" here, or you mean "too" here?

::: layout/base/RestyleManager.h:166
(Diff revision 1)
>    // Restyling for a ContentAppended (notification after insertion) or
> -  // for a CharacterDataChanged.  |aContainer| must be non-null; when
> +  // for some CharacterDataChanged.  |aContainer| must be non-null; when
>    // the container is null, no work is needed.

This is never called for `CharacterDataChanged` with this patch, is it?

::: layout/base/RestyleManager.h:173
(Diff revision 1)
>    // the container is null, no work is needed.
>    void RestyleForAppend(nsIContent* aContainer, nsIContent* aFirstNewContent);
>  
> +  // Restyle for a CharacterDataChanged notification. In practice this can only
> +  // affect :empty / :-moz-only-whitespace.
> +  void CharacterDataChanged(nsIContent*, const CharacterDataChangeInfo&);

I think the `nsIContent*` should have its name `aTextNode` present in the declaration as well, since that provides extra information. Otherwise it isn't clear immediately what is this param for without looking at its definition, especially given `nsIContent*` can mean container in similar functions around.

::: layout/base/RestyleManager.cpp:233
(Diff revision 1)
> +
> +  if (!changed) {
> +    return;
> +  }
> +
> +  RestyleForEmptyChange(parent->AsElement());

Probably add a note here mentioning that there may be significant siblings around which makes this restyle unnecessary, but that's probably not a common case we need to deal with.

Comment 18

[Xidorn Quan [:xidorn] UTC+10]

Thanks for working on this.

I guess if we care about the performance of looking at long plain text files, we may want to add a talos to ensure we never regress it again. The talos may need some custom server impl to generate long content with speed throttled to simulate real-world case without needing to put a large plain text file in the tree.

Comment 19

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review229712

::: layout/base/RestyleManager.h:166
(Diff revision 1)
>    // Restyling for a ContentAppended (notification after insertion) or
> -  // for a CharacterDataChanged.  |aContainer| must be non-null; when
> +  // for some CharacterDataChanged.  |aContainer| must be non-null; when
>    // the container is null, no work is needed.

Indeed, I'll fix.

::: layout/base/RestyleManager.h:173
(Diff revision 1)
>    // the container is null, no work is needed.
>    void RestyleForAppend(nsIContent* aContainer, nsIContent* aFirstNewContent);
>  
> +  // Restyle for a CharacterDataChanged notification. In practice this can only
> +  // affect :empty / :-moz-only-whitespace.
> +  void CharacterDataChanged(nsIContent*, const CharacterDataChangeInfo&);

Yup, will do.

::: layout/base/RestyleManager.cpp:233
(Diff revision 1)
> +
> +  if (!changed) {
> +    return;
> +  }
> +
> +  RestyleForEmptyChange(parent->AsElement());

Actually, it probably is worth handling, I think. It's definitely an oversight on my side, you don't want a random parser append in:

```
<div>
 <!-- Tons of stuff here -->
 some whitespace below
 <br>
 
 non whitespace
</div>
```

To restyle the `<div>`.

So will fix that.

Comment 20

[Emilio Cobos Álvarez (:emilio)]

Attachment: Address comments and handle pre-existing significant siblings.

Mozreview is not on the mood when I use it from my crappy internet at home apparently :)

The extra handling was worth another look. Will squash both commits before
landing.

Comment 21

[Xidorn Quan [:xidorn] UTC+10]

Comment on attachment 8954588 [details] [diff] [review]
Address comments and handle pre-existing significant siblings.

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

r=me with the nits addressed.

It is a lot harder to review without MozReview especially for code moves :/

Also, please set "diff.context" to 8 in your git config so that patches provide more context. That would help a lot for reviewing.

::: layout/base/RestyleManager.cpp
@@ +174,5 @@
>    return !WhitespaceOnly(aBuffer + aOldLength, aNewLength - aOldLength);
>  }
>  
> +static bool
> +HasAnySignificantSiblingOtherThan(Element* aContainer, nsIContent* aChild)

`HasAnySignificantSibling` should be more correct here.

From the container's point of view, it should be `HasAnySignificantChildOtherThan`, and from the children's point of view, it's just `HasAnySignificantSibling` because one is not a sibling of itself.

@@ +175,5 @@
>  }
>  
> +static bool
> +HasAnySignificantSiblingOtherThan(Element* aContainer, nsIContent* aChild)
> +{

Probably assert that `aChild->GetParent() == aContainer`.

Comment 22

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223494/diff/1-2/

Comment 23

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review229696

> I think the `nsIContent*` should have its name `aTextNode` present in the declaration as well, since that provides extra information. Otherwise it isn't clear immediately what is this param for without looking at its definition, especially given `nsIContent*` can mean container in similar functions around.

I ended up reverting this suggestion since the node can also be a comment / processing instruction. Damn, I always forget about those.

Comment 24

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review229696

> I ended up reverting this suggestion since the node can also be a comment / processing instruction. Damn, I always forget about those.

I also forgot to handle `:-moz-first-node` / `:-moz-last-node`, so I also added handling for them... Sigh.

Comment 25

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

Mind taking a last look to check the :-moz-first-node / :-moz-last-node changes? Thanks!

Comment 26

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223494/diff/2-3/

Comment 27

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

Not sure what mozreview did there... This is actually green and should get all the interactions with the other selectors fine.

Comment 28

[Xidorn Quan [:xidorn] UTC+10]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review230110

r=me with nits addressed.

::: commit-message-0862a:3
(Diff revision 3)
> +This unfortunately doesn't fix my test-case (because we're replacing the text
> +content all the time and all that), but it's still worth it, since it fixes the
> +case we care about (the parser appending).

Actually I have an idea that we can probably do somthing smarter at DOM level to compare new text content and old text content, and when the old text and new text share the same prefix, we can optimize it to behave as if only part of the text is replaced, and in case the old is the prefix of the new, treat it as append.

That should make your test case work much better, and I believe that is a common pattern for dumping log.

::: layout/base/RestyleManager.cpp:248
(Diff revision 3)
> +                                     const CharacterDataChangeInfo& aInfo)
> +{
> +  nsINode* parent = aContent->GetParentNode();
> +  MOZ_ASSERT(parent, "How were we notified of a stray node?");
> +
> +  uint32_t slowSelectorFlags = parent->GetFlags() & NODE_ALL_SELECTOR_FLAGS;

I have a feeling that this `&` is actually meaningless... Just using the flags itself everywhere below should work as well.

But it's not a big issue so I'm fine as well if you like it.

::: layout/base/RestyleManager.cpp:249
(Diff revision 3)
> +{
> +  nsINode* parent = aContent->GetParentNode();
> +  MOZ_ASSERT(parent, "How were we notified of a stray node?");
> +
> +  uint32_t slowSelectorFlags = parent->GetFlags() & NODE_ALL_SELECTOR_FLAGS;
> +  if (!(slowSelectorFlags & (NODE_HAS_EMPTY_SELECTOR | NODE_HAS_EDGE_CHILD_SELECTOR))) {

This line is too long, please wrap it after `&` or `|`.

::: layout/base/RestyleManager.cpp:267
(Diff revision 3)
> +    // This is an anonymous node and thus isn't in child lists, so isn't taken
> +    // into account for selector matching :empty / :-moz-only-whitespace on the
> +    // parent.

If you want to list selectors here, you should probably also mention `:-moz-{first,last}-node` as well, otherwise, you can just say it doesn't affect any selector matching.

::: layout/base/RestyleManager.cpp:275
(Diff revision 3)
> +  // whitespace (thus changing the meaning of :-moz-first-node and
> +  // :-moz-last-node).

"thus not changing the meaning" is probably less ambiguous here?

::: layout/base/RestyleManager.cpp:278
(Diff revision 3)
> +  // TODO(emilio): This could be made much more general if :-moz-only-whitespace
> +  // didn't exist. In that case we only need to know whether we went from empty
> +  // to non-empty, and that's trivial to know, with CharacterDataChangeInfo...
> +  //
> +  // Though it'd also need to handle :-moz-first-node / :-moz-last-node, see
> +  // bug 373298 :-(

That requires all of these `-moz-`prefixed pseudo-classes not to exist, so probably you should revise the TODO here to include all of them.

Comment 29

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/223494/diff/3-4/

Comment 30

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review230110

> I have a feeling that this `&` is actually meaningless... Just using the flags itself everywhere below should work as well.
> 
> But it's not a big issue so I'm fine as well if you like it.

I think it's slightly nice to see which flags do we actually care about... Though not too important I guess.

Comment 31

[Emilio Cobos Álvarez (:emilio)]

Comment on attachment 8954407 [details]
Bug 1427625: Optimize appends to avoid restyling unnecessarily.

https://reviewboard.mozilla.org/r/223494/#review230110

> Actually I have an idea that we can probably do somthing smarter at DOM level to compare new text content and old text content, and when the old text and new text share the same prefix, we can optimize it to behave as if only part of the text is replaced, and in case the old is the prefix of the new, treat it as append.
> 
> That should make your test case work much better, and I believe that is a common pattern for dumping log.

Yeah, it's true, but it's a matter of doing the work eagerly or not... Most of the callers don't need it anyway I suspect (except maybe nsTextFrame). We should probably check with Olli and Jonathan and see if there's something that we almost-always need around these lines.

Comment 32

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/06e5de2e31ac
Optimize appends to avoid restyling unnecessarily. r=xidorn

Comment 33

[Tiberius Oros[:tiberius_oros]]

https://hg.mozilla.org/mozilla-central/rev/06e5de2e31ac

Comment 34

[Xidorn Quan [:xidorn] UTC+10]

So, it seems to me that the style part goes away with emilio's patch, but there are still significant reflow and display list building in the profile.

I guess this problem is especially significant when the file is served from jet's server, because it is uncompressed. The file when compressed with gzip, only have ~3.7MB (when use the highest compress level, only ~2.9MB). When it is compressed, the retrieving time should be shorter, and we should also reflow fewer times.

And did another profile with local file... I started suspecting that comment 0 and comment 15 are actually complaining about it also takes a long time to reflow the file as a whole (i.e. even when served from local), because that seems to take quite a bit of time as well (my profile in comment 5 indeed takes ~30s), and that is the case where the tab becomes completely unresponsive (when serving from the net, the tab is still quite responsive as far as I can see).

So maybe we should have another bug about it taking long to reflow it...

Comment 35

[Itiel]

Not sure if this has anything to do with this bug, but *reloading* the log file mentioned in the first comment simply showes blank white content.
Ctrl+F5 fixes it, until you normal F5 again.