1466704 - trying to View Source on twitter.com stalls out entire content process (spending lots of time in nsBidiPresUtils::TraverseFrames->nsBidiPresUtils::ResolveParagraph->SplitInlineAncestors)

Status: NEW

(Core :: Layout: Text and Fonts, defect, P3)

Description

[Potch [:potch]]

Using Nightly 62.0a1 (2018-06-04) (64-bit)

STR:
* Load twitter.com (logged in)
* View Source

Observed:
* View Source does not load
* All tabs sharing the content process are spinner'd

Comment 1

[Ben Kelly [:bkelly, not reviewing]]

Here is a profile showing a 4.5 second reflow:

https://perfht.ml/2sIWzC6

Emilio, does this look like a layout issue or a view source page issue?

Comment 2

[Emilio Cobos Álvarez [:emilio]]

I'd start with Layout, looks like more of the time is spent in bidi resolution... I'm not that familiar with that code, Xidorn or Jonathan may.

Comment 3

[Daniel Holbert [:dholbert]]

(In reply to Potch [:potch] from comment #0)
> * View Source does not load

FWIW, it loads for me, though it takes a few seconds to do so.

Most of the 4.5 second reflow in comment 1's profile is in nsBidiPresUtils::ResolveParagraph, so this is likely the same issue as bug 1261648. --> Adding dependency.

Fun fact: the un-logged-in Twitter contains a single line with 95,000 - 100,000 characters, near the bottom of the page. It looks like this, with a giant "value" attribute:

<input type="hidden" id="init-data" class="json-data" value="{&quot;keyboardShortcuts&quot;:[{&quot;name&quot;:&quot;Actions&quot;[...]ttft_navigation&quot;:true}}">

I suspect that value is involved here (as in bug 1261648 which notes it's also got a lot of content on a single line)

Comment 4

[Daniel Holbert [:dholbert]]

Attachment: testcase 1: Unreduced source of twitter dot com (not logged in) -- view the source of this page

Comment 5

[Daniel Holbert [:dholbert]]

Attachment: testcase 2: partially reduced (view my source)

The key lines from the original source seem to be 
    <meta charset="utf-8">
and the long <input> tag (which does contain some Arabic characters, e.g. كن_سباقا_لعلاج_المرضى_الفقراء )

Comment 6

[Jonathan Kew [:jfkthame]]

This doesn't seem to be primarily about text (as in bug 1164189); looking at the 4591ms-long reflow (which has 2299ms of samples) in comment 1, there's only 239ms in total under nsTextFrame::EnsureTextRun, or just over 10%.

By far the dominant issue is the 2022ms in nsBidiPresUtils::Resolve, of which the vast majority is spent in nsContainerFrame::InsertFrames, called from SplitInlineAncestors. Fixing this may require a serious re-think of how we handle frame splitting, continuations, and all that...

Comment 7

[Cameron McCormack (:heycam)]

Since view source documents are basically one big <pre>, is this essentially bug 330350?

In lieu of that, can we change how we build the view source document, e.g. by making each line actually a separate block?

Comment 8

[J. Ryan Stinnett [:jryans] (Use needinfo, replies may be slow)]

(In reply to Cameron McCormack (:heycam) from comment #7)
> In lieu of that, can we change how we build the view source document, e.g.
> by making each line actually a separate block?

It seems reasonable to try.  View Source is built while parsing via https://searchfox.org/mozilla-central/source/parser/html/nsHtml5Highlighter.cpp and friends.

For comparison, Chrome Canary's View Source appears to use a <table> with each line in a <tr>.

Comment 9

[Bobby Holley (:bholley)]

Yeah, seems like there might be some long-term bidi performance work we want to do here, but that may not be immediately actionable without further investigation.

However, it does seem like we could probably tweak view-source to generate something with less of an impedence mismatch with our layout engine. Adding to the actionable performance queue for that reason, and tracking separately for the bidi stuff.

Comment 10

[Boris Zbarsky [:bzbarsky]]

We used to have more than one <pre> in view-source.  There's a tradeoff there: more blocks means more memory; fewer means more layout/bidi suck.  Digging up the blame for this is hard unless you know the filenames we used to have, but https://searchfox.org/mozilla-central/rev/95fb13c8d338f9248b37706bf2c71cd7760bdcbc/parser/htmlparser/src/nsViewSourceHTML.cpp is the pre-HTML5-parser view-source impl.  See the NS_VIEWSOURCE_TOKENS_PER_BLOCK define in there and so forth.

The new code was at least trying to do the same.  See NS_HTML5_HIGHLIGHTER_PRE_BREAK_THRESHOLD in parser/html/nsHtml5Highlighter.cpp.  But it looks like it's completely unused?

Comment 11

[Boris Zbarsky [:bzbarsky]]

Um.  So we certainly used to create multiple <pre> here in the new parser.  See https://searchfox.org/mozilla-central/rev/4600ed7a018fb53c5e60617811f9900bb71eaf80/parser/html/nsHtml5Highlighter.cpp#633-645

Now to find out when this went away...

Comment 12

[Boris Zbarsky [:bzbarsky]]

Oh.  Bug 695640.  That was after we changed bidi to not cross preformatted newline boundaries in bug 263359.  Did we back that out at some point or something, and go back to being super-slow on large <pre> with bidi?

Comment 13

[Boris Zbarsky [:bzbarsky]]

nsBidiPresUtils sure thinks we still do resolution on each line separately.

Anyway, we should try backing out bug 695640 and seeing whether that helps.

Comment 15

[Vicky Chin [:vchin]]

Tagging this for re-triage since it blocks the async-tab-switcher meta.

Comment 16

[Daniel Holbert [:dholbert]]

This came up in QF triage, and some folks couldn't reproduce, but I actually am still seeing several-second load times and reflows when view-sourc'ing the attached testcases (and the not-logged-in twitter.com front page), so I think this is still a valid bug.

[:darkspirit], why is this connected to async-tab-switcher? AFAICT, this is just one possible (and particularly-niche) way to trigger a slow reflow (and hang the content process in question. Is every "hang-the-content-process-for-a-bit" bug an async-tab-switcher blocker?

Comment 17

[Daniel Holbert [:dholbert]]

For reference (and just to have up-to-date data), here's a profile of me doing view-source on testcase 2 here: https://perfht.ml/2LMpYVM

Comment 18

[Darkspirit]

(In reply to Daniel Holbert [:dholbert] from comment #16)

[:darkspirit], why is this connected to async-tab-switcher?

I don't know: https://bugzilla.mozilla.org/show_bug.cgi?id=1460123#a1173614_219124

Comment 19

[Daniel Holbert [:dholbert]]

Thanks, darkspirit.

dao, looks like this bug here is marked as blocking async-tab-switcher by virtue of you having marked bug 1460123 as blocking async-tab-switcher (below bug 1460123 comment 2), and then that bug later being duped to this one.

Do you still think it makes sense for these bugs to be tied to async-tab-switcher? Put another way: does it make sense for the async-tab-switcher metabug to depend on every bug that's filed for a content-process-hang that's long enough to manifest in a spinner on tab-switch, if the switched-to-tab happens to share the hung content process?

(My guess is "no" -- if the reason for a spinner is just that a background tab is temporarily hanging your content process, I don't think that's the fault of or related to async-tab-switcher... though I suppose it does manifest in the tab-switch operation taking longer to get to a usable state.)

Comment 20

[Dão Gottwald [:dao]]

(In reply to Daniel Holbert [:dholbert] from comment #19)

(My guess is "no" -- if the reason for a spinner is just that a background tab is temporarily hanging your content process, I don't think that's the fault of or related to async-tab-switcher... though I suppose it does manifest in the tab-switch operation taking longer to get to a usable state.)

👍

Comment 21

[Mayank Bansal]

On partially reduced testcase :
Nightly: https://share.firefox.dev/4dxW82X (734ms, wrapping) / https://share.firefox.dev/3ZddHkD (720ms, no wrapping)
Chrome: Instant. The chrome profiler didnt even capture this.

Comment 22

[Daniel Holbert [:dholbert]]

This seems to have gotten much better last year, using testcase 2.

Fix range:
First good revision: a26e51291acad88b8964d4a96ecbcbdce6c0667b (2023-05-15)
Last bad revision: 9ca5d595c22d6b38d5802c9282ef6e54bffa464b (2023-05-14)
Pushlog:
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=9ca5d595c22d6b38d5802c9282ef6e54bffa464b&tochange=a26e51291acad88b8964d4a96ecbcbdce6c0667b

Here's a profile of reloading the partially-reduced testcase (view-source:https://bug1466704.bmoattachments.org/attachment.cgi?id=8986199) twice with...

• The "last bad" Nightly 2023-05-14 -- reflow bars are 2.1s long:
  https://share.firefox.dev/4fZ46DV

• The "first good" Nightly 2023-05-13 -- reflow bars are 665ms long:
  https://share.firefox.dev/4dx1rzn

So that was a 68% reduction in reflow time for this scenario.

Looking at the "bad" profile, I do see that a huge amount of time was spent in nsIFrame::SchedulePaint, so this improvement probably came from bug 1832684.

Comment 23

[Daniel Holbert [:dholbert]]

(In reply to Mayank Bansal from comment #21)

Chrome: Instant. The chrome profiler didnt even capture this.

I see a little time spent in layout in Chrome when viewing the source of testcase 2. Here's a Chrome profile of loading that view-source 4 times:
https://share.firefox.dev/3XeM9ty

Each load has a ~21-23ms marker for "Layout".

That's substantially lower than our 600-700ms layouts, so perhaps still worth keeping this bug open to track that.

Comment 24

[Timothy Nikkel (:tnikkel)]

(In reply to Mayank Bansal from comment #21)

On partially reduced testcase :
Nightly: https://share.firefox.dev/4dxW82X (734ms, wrapping) / https://share.firefox.dev/3ZddHkD (720ms, no wrapping)
Chrome: Instant. The chrome profiler didnt even capture this.

Looks like the majority of time is spent running some diagnostic asserts that don't seem to be providing much value now. I filed bug 1914682 to downgrade those.

Comment 25

[Mayank Bansal]

(In reply to Timothy Nikkel (:tnikkel) from comment #24)

(In reply to Mayank Bansal from comment #21)

On partially reduced testcase :
Nightly: https://share.firefox.dev/4dxW82X (734ms, wrapping) / https://share.firefox.dev/3ZddHkD (720ms, no wrapping)
Chrome: Instant. The chrome profiler didnt even capture this.

Looks like the majority of time is spent running some diagnostic asserts that don't seem to be providing much value now. I filed bug 1914682 to downgrade those.

With latest Nightly that contains the fix from bug 1914682 :
with wrapping: https://share.firefox.dev/3T2aX5n (700ms)
Without wrapping: https://share.firefox.dev/4czlXyg (720ms)

Comment 26

[Timothy Nikkel (:tnikkel)]

Hmm, looks like all the time spent in those asserts just got moved to the HasAnyStateBits calls on the next line. The HasInvalidFrameInSubtree() call lower down has much less samples, but that is also just a call to HasAnyStateBits. I think what might be happening is that the time spent is in reading the contents of |this| from memory, so the first line that reads will incur that cost.

Comment 27

[Mayank Bansal]

Profile with latest Nightly: https://share.firefox.dev/4hpVffe . This did not improve with the patches from bug 1926512,bug 1927062, bug 1927114