1304556 - nsTextFrame::GetRenderedText() spends a lot of time in nsBlockInFlowLineIterator() + nsLineBox::IndexOf for large plain text documents

Reporter

Description

•

3 years ago

firefox.exe is extremely slow to load large (1+MB) plain text documents like https://archive.mozilla.org/pub/firefox/try-builds/gszorc@mozilla.com-fbc7211e1be250a4b0061c22f258263f0755eed6/try-linux/try-linux-bm78-try1-build12660.txt.gz.

Using a combination of ETW+WPA and the Visual Studio debugger, I've traced the performance problem to the evaluation of .innerText (I think), triggered by an add-on (LastPass). The issue presents in an e10s Nightly. I've seen this performance issue for months. I've been looking at large text logs from Firefox automation and the constant hangs rendering large logs finally drove me to look into the problem in more detail.

The performance problem appears to start in nsTextFrame::GetRenderedText(). This function iterates over text frames and calls LineEndsInHardLineBreak(). This function constructs a nsBlockInFlowLineIterator. That hits the following branch/loop in nsBlockInFlowLineIterator::nsBlockInFlowLineIterator():

    for (mLine = aFrame->begin_lines(); mLine != line_end; ++mLine) {
      if (mLine->Contains(child)) {
        *aFoundValidLine = true;
        return;
      }
    }

This loop calls nsLineBox::Contains which calls nsLineBox::IndexOf. firefox.exe spends several seconds over multiple invocations in this loop.

I'm not an expert of this code, but it feels very sub-optimal that it takes Firefox a few dozen seconds on my i7-6700K to essentially return a string.

Here is an example stack from a stalled (content) process.

 	xul.dll!nsLineBox::IndexOf(nsIFrame * aFrame) Line 304	C++
 	xul.dll!nsLineBox::Contains(nsIFrame * aFrame) Line 588	C++
 	xul.dll!nsBlockInFlowLineIterator::nsBlockInFlowLineIterator(nsBlockFrame * aFrame, nsIFrame * aFindFrame, bool * aFoundValidLine) Line 5541	C++
 	xul.dll!LineEndsInHardLineBreak(nsTextFrame * aFrame) Line 9601	C++
 	xul.dll!nsTextFrame::GetRenderedText(unsigned int aStartOffset, unsigned int aEndOffset, nsIFrame::TextOffsetType aOffsetType, nsIFrame::TrailingWhitespace aTrimTrailingWhitespace) Line 9639	C++
 	xul.dll!nsRange::GetInnerTextNoFlush(mozilla::dom::DOMString & aValue, mozilla::ErrorResult & aError, nsIContent * aStartParent, unsigned int aStartOffset, nsIContent * aEndParent, unsigned int aEndOffset) Line 3474	C++
 	xul.dll!nsGenericHTMLElement::GetInnerText(mozilla::dom::DOMString & aValue, mozilla::ErrorResult & aError) Line 3119	C++
 	xul.dll!mozilla::dom::HTMLElementBinding::get_innerText(JSContext * cx, JS::Handle<JSObject *> obj, nsGenericHTMLElement * self, JSJitGetterCallArgs args) Line 249	C++
 	xul.dll!mozilla::dom::GenericBindingGetter(JSContext * cx, unsigned int argc, JS::Value * vp) Line 2752	C++
 	xul.dll!js::InternalCallOrConstruct(JSContext * cx, const JS::CallArgs & args, js::MaybeConstruct construct) Line 458	C++
 	xul.dll!InternalCall(JSContext * cx, const js::AnyInvokeArgs & args) Line 503	C++
 	xul.dll!js::Call(JSContext * cx, JS::Handle<JS::Value> fval, JS::Handle<JS::Value> thisv, const js::AnyInvokeArgs & args, JS::MutableHandle<JS::Value> rval) Line 522	C++
 	xul.dll!JS::Call(JSContext * cx, JS::Handle<JS::Value> thisv, JS::Handle<JS::Value> fval, const JS::HandleValueArray & args, JS::MutableHandle<JS::Value> rval) Line 2836	C++
 	xul.dll!JS::Call(JSContext * cx, JS::Handle<JS::Value> thisv, JS::Handle<JSObject *> funObj, const JS::HandleValueArray & args, JS::MutableHandle<JS::Value> rval) Line 3289	C++
 	xul.dll!xpc::XrayWrapper<js::SecurityWrapper<js::CrossCompartmentWrapper>,xpc::DOMXrayTraits>::get(JSContext * cx, JS::Handle<JSObject *> wrapper, JS::Handle<JS::Value> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 2217	C++
 	xul.dll!js::Proxy::get(JSContext * cx, JS::Handle<JSObject *> proxy, JS::Handle<JS::Value> receiver_, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 310	C++
 	xul.dll!js::proxy_GetProperty(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 583	C++
 	xul.dll!js::GetProperty(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 1497	C++
 	xul.dll!js::Proxy::get(JSContext * cx, JS::Handle<JSObject *> proxy, JS::Handle<JS::Value> receiver_, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 306	C++
 	xul.dll!js::proxy_GetProperty(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 583	C++
 	xul.dll!js::GetProperty(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 1497	C++
 	xul.dll!js::Proxy::get(JSContext * cx, JS::Handle<JSObject *> proxy, JS::Handle<JS::Value> receiver_, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 306	C++
 	xul.dll!js::proxy_GetProperty(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 583	C++
 	xul.dll!js::GetProperty(JSContext * cx, JS::Handle<JSObject *> obj, JS::Handle<JSObject *> receiver, JS::Handle<jsid> id, JS::MutableHandle<JS::Value> vp) Line 854	C++
 	xul.dll!js::jit::GetPropertyIC::update(JSContext * cx, JS::Handle<JSScript *> outerScript, unsigned int cacheIndex, JS::Handle<JSObject *> obj, JS::Handle<JS::Value> idval, JS::MutableHandle<JS::Value> vp) Line 2283	C++

Gregory Szorc [:gps]

Reporter

Comment 1

•

3 years ago

FWIW, a fresh profile renders the reported problem URL in a few seconds. It even appears to render faster than Chrome.

Disabling LastPass (and thus preventing the .innerText access) makes Firefox fast again.

While it may be tempting to blame this perf issue on LastPass, I feel that accessing .innerText shouldn't take 30+s.

Gregory Szorc [:gps]

Reporter

Updated

•

3 years ago

Blocks: e10s-lastpass

Gregory Szorc [:gps]

Reporter

Comment 2

•

3 years ago

It's worth noting that LastPass 4.1.29a (a pre-release version) doesn't exhibit the massive performance slowdown that the latest available version on AMO (3.3.1) does.

Cosmin Muntean, Experiments QA (in PTO until October 18)

Updated

•

3 years ago

tracking-e10s: --- → ?

Jim Mathies [:jimm]

Updated

•

3 years ago

tracking-e10s: ? → +

David Baron :dbaron: (away October 5-21)

Comment 3

•

3 years ago

What does this have to do with e10s?

I've also heard the claim that Edge doesn't need this linebreak information for .innerText at all, so it might be Web-compatible to have a different behavior.

But, barring that, there are various approaches possible to making this code faster.  I suspect the caller is probably iterating through all the text frames, which means that if each .innerText is O(N) in the number of previous siblings, the overall algorithm is O(N^2).  We could fix that by caching the last line found somewhere.  But it would also be nice if we could either (a) make getting the line faster or (b) make this code not require the line iterator at all.

The trivial patch to reorder the && conditions in:
    TrimmedOffsets trimmedOffsets = textFrame->GetTrimmedOffsets(textFrag,
       textFrame->IsAtEndOfLine() && LineEndsInHardLineBreak(textFrame) &&
       aTrimTrailingWhitespace == TrailingWhitespace::TRIM_TRAILING_WHITESPACE);
in nsTextFrame::GetRenderedText would also speed up some cases, but it wouldn't help here.

Xidorn Quan [:xidorn] UTC+10

Assignee

Comment 4

•

3 years ago

It seems to me nsTextFrame::GetRenderedText() itself is already O(N^2), because nsBlockInFlowLineIterator used in LineEndsInHardLineBreak is O(N) when line cursor is not setup.

It seems line cursor has been used in places other than what its comment described. Its comment should really be updated. And I guess we should either have a nestable line cursor, or an assertion that line cursor is never nested set.

Xidorn Quan [:xidorn] UTC+10

Assignee

Comment 5

•

3 years ago

And it seems line cursor would be setup during building display list when number of line is large enough. Consequently, if you query innerText after the page is rendered, everything works just fine. So this seems like an edge case that innerText is queried before the page is rendered.

I guess we can make a utility around line cursor to setup it temporary when needed.

Xidorn Quan [:xidorn] UTC+10

Assignee

Comment 6

•

3 years ago

Attached file testcase — Details

Looks like my guess is correct. This is a simplified testcase of this performance issue, which tries to query innerText before we start rendering. And in this testcase, if I wrap the innerText query into two levels of requestAnimationFrame, everything would go just fine.

Comment hidden (mozreview-request)

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

Comment hidden (mozreview-request)

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

Xidorn Quan [:xidorn] UTC+10

Assignee

Comment 9

•

3 years ago

mozreview-review

Comment on attachment 8795986 [details]
Bug 1304556 part 2 - Use AutoLineCursorSetup to optimize pre-render innerText query.

https://reviewboard.mozilla.org/r/81970/#review80526

::: layout/generic/nsTextFrame.cpp:9642
(Diff revision 1)
> +    } else {
> +      if (nsBlockFrame* thisLc = do_QueryFrame(FindLineContainer(textFrame))) {
> +        if (thisLc != lineContainer) {
> +          // Setup line cursor when needed.
> +          lineContainer = thisLc;
> +          autoLineCursor.emplace(lineContainer);

This should call autoLineCursor.reset() first.

David Baron :dbaron: (away October 5-21)

Comment 10

•

3 years ago

If this is a mistake that the caller should have done something differently, should there be assertions pointing out that mistake?

Assignee: nobody → xidorn+moz

Flags: needinfo?(xidorn+moz)

Xidorn Quan [:xidorn] UTC+10

Assignee

Comment 11

•

3 years ago

The caller of what method you mean? Are you concerned about unexpected usage of SetupLineCursor()?

Flags: needinfo?(xidorn+moz) → needinfo?(dbaron)

David Baron :dbaron: (away October 5-21)

Comment 12

•

3 years ago

comment 4 and 5 made it sound like there was a performance problem resulting from failing to set up the line cursor.  Is that the case?  If so, should that assert?

Flags: needinfo?(dbaron)

Xidorn Quan [:xidorn] UTC+10

Assignee

Comment 13

•

3 years ago

No, and no.

The initial use of line cursor is for searching lines contains a certain y position, so that we know which lines are in the dirty area quickly by moving the cursor. It is an optional optimization, and its correctness depends on the fact that the y position of overflow area of all lines is not decreasing anywhere. (See its use in [1], and its traditional setup in [2])

That said, line cursor can only be set up in a limited condition, and it is perfectly valid that it is not set for some reason.

But the optimization here doesn't have the same requirement as the rendering optimization, so we can set up it temporary as a local cursor just for speeding up nsBlockInFlowLineIterator.

So actually we need two different line cursors... And we are mixing them together here. But as far as one is local only, I think it is fine. Probably also see bug 1235321 comment 11.


[1] https://dxr.mozilla.org/mozilla-central/rev/66a77b9bfe5dcacd50eccf85de7c0e7e15ce0ffd/layout/generic/nsBlockFrame.cpp#6708
[2] https://dxr.mozilla.org/mozilla-central/rev/66a77b9bfe5dcacd50eccf85de7c0e7e15ce0ffd/layout/generic/nsBlockFrame.cpp#6574-6597

David Baron :dbaron: (away October 5-21)

Comment 14

•

3 years ago

mozreview-review

Comment on attachment 8795985 [details]
Bug 1304556 part 1 - Add AutoLineCursorSetup RAII class for local line cursor setup.

https://reviewboard.mozilla.org/r/81968/#review86414

r=dbaron, although I wonder if, in the case where the frame already has a line cursor, it would be useful to restore the old line cursor state in ~AutoLineCursorSetup.  (I wonder if this is as simple as removing the frame property in the constructor and restoring it afterwards?)

Attachment #8795985 - Flags: review?(dbaron) → review+

David Baron :dbaron: (away October 5-21)

Comment 15

•

3 years ago

mozreview-review

Comment on attachment 8795986 [details]
Bug 1304556 part 2 - Use AutoLineCursorSetup to optimize pre-render innerText query.

https://reviewboard.mozilla.org/r/81970/#review86418

::: layout/generic/nsTextFrame.cpp:9637
(Diff revision 1)
> +    } else {
> +      if (nsBlockFrame* thisLc = do_QueryFrame(FindLineContainer(textFrame))) {
> +        if (thisLc != lineContainer) {
> +          // Setup line cursor when needed.
> +          lineContainer = thisLc;
> +          autoLineCursor.emplace(lineContainer);
> +        }
> +        trimAfter = LineEndsInHardLineBreak(textFrame, lineContainer);
> +      } else {
> +        // Weird situation where we have a line layout without a block.
> +        // No soft breaks occur in this situation.
> +        trimAfter = true;
> +      }

probably better to use "else if" at the top of this chunk, and then have 2 spaces less indent for the rest of it

::: layout/generic/nsTextFrame.cpp:9642
(Diff revision 1)
> +    } else {
> +      if (nsBlockFrame* thisLc = do_QueryFrame(FindLineContainer(textFrame))) {
> +        if (thisLc != lineContainer) {
> +          // Setup line cursor when needed.
> +          lineContainer = thisLc;
> +          autoLineCursor.emplace(lineContainer);

don't forget the reset(), as you already noted

Attachment #8795986 - Flags: review?(dbaron) → review+

Comment hidden (mozreview-request)

Comment on attachment 8795985 [details]
Bug 1304556 part 1 - Add AutoLineCursorSetup RAII class for local line cursor setup.

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

Comment hidden (mozreview-request)

Comment on attachment 8795986 [details]
Bug 1304556 part 2 - Use AutoLineCursorSetup to optimize pre-render innerText query.

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

Pulsebot

Comment 18

•

3 years ago

Pushed by xquan@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7e8d0d68f550
part 1 - Add AutoLineCursorSetup RAII class for local line cursor setup. r=dbaron
https://hg.mozilla.org/integration/autoland/rev/df0022e05784
part 2 - Use AutoLineCursorSetup to optimize pre-render innerText query. r=dbaron

Ryan VanderMeulen [:RyanVM]

Comment 19

•

3 years ago

bugherder

https://hg.mozilla.org/mozilla-central/rev/7e8d0d68f550
https://hg.mozilla.org/mozilla-central/rev/df0022e05784

Status: NEW → RESOLVED

Closed: 3 years ago

status-firefox52: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla52

testcase 3 years ago Xidorn Quan [:xidorn] UTC+10 338 bytes, text/html		Details
Bug 1304556 part 1 - Add AutoLineCursorSetup RAII class for local line cursor setup. 3 years ago Xidorn Quan [:xidorn] UTC+10 58 bytes, text/x-review-board-request	dbaron : review+	Details
Bug 1304556 part 2 - Use AutoLineCursorSetup to optimize pre-render innerText query. 3 years ago Xidorn Quan [:xidorn] UTC+10 58 bytes, text/x-review-board-request	dbaron : review+	Details

Bugzilla

nsTextFrame::GetRenderedText() spends a lot of time in nsBlockInFlowLineIterator() + nsLineBox::IndexOf for large plain text documents

Categories

(Core :: Layout: Block and Inline, defect)

Tracking

()

People

(Reporter: gps, Assigned: xidorn)

References

Details

(Keywords: perf)

Crash Data

Security

(public)

User Story

Attachments

(3 files)

Description

Comment 1

Updated

Comment 2

Updated

Updated

Comment 3

Comment 4

Comment 5

Comment 6

Comment 7

Comment 8

Comment 9

Comment 10

Comment 11

Comment 12

Comment 13

Comment 14

Comment 15

Comment 16

Comment 17

Comment 18

Comment 19