Closed Bug 1427625 Opened 2 years ago Closed 2 years ago

Performance cliff loading a Taskcluster log

Categories

(Core :: Layout, defect, P3)

defect

Tracking

()

RESOLVED FIXED
mozilla60
Tracking Status
firefox-esr52 --- unaffected
firefox58 --- wontfix
firefox59 --- wontfix
firefox60 --- fixed

People

(Reporter: dmajor, Assigned: emilio)

References

()

Details

(Keywords: perf, regression, regressionwindow-wanted)

Attachments

(3 files)

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.
Jet, do you have someone who can take a look at this before the log file ages out?
Flags: needinfo?(bugs)
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!
Flags: needinfo?(bugs)
[ Triage 2017/02/20: P3 ]
Priority: -- → P3
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.
This is the profile when loading from local: https://perfht.ml/2CKFKKh
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)
(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.
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.)
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...
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.
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.
Sounds like we should probably just make it not quirk?
Depends on: 1441547
(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 :)
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)
Attachment #8954345 - Attachment mime type: text/plain → text/html
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.
Attachment #8954407 - Flags: review?(xidorn+moz) → review+
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.
Assignee: nobody → 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.
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.
Attachment #8954588 - Flags: review?(xidorn+moz)
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`.
Attachment #8954588 - Flags: review?(xidorn+moz) → review+
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 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 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!
Attachment #8954407 - Flags: review+ → review?(xidorn+moz)
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.
Attachment #8954407 - Flags: review?(xidorn+moz)
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.
Attachment #8954407 - Flags: review?(xidorn+moz) → review+
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 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.
Pushed by ecoal95@gmail.com:
https://hg.mozilla.org/integration/autoland/rev/06e5de2e31ac
Optimize appends to avoid restyling unnecessarily. r=xidorn
https://hg.mozilla.org/mozilla-central/rev/06e5de2e31ac
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla60
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...
See Also: → 1442478
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.
You need to log in before you can comment on or make changes to this bug.