1644138 - 2.5s content hangs caused by Inspector's `parseDeclarations`

Status: RESOLVED FIXED

(DevTools :: Inspector, defect, P2)

Description

[:Harald Kirschner :digitarald]

Reported via https://twitter.com/maxccarvalho/status/1269915251262308352 – User just navigates the markup tree and it's really slow: https://share.firefox.dev/3h8RY4u

https://firefox-devtools-testcase-1644138-tailwindcss.glitch.me/

STR: Inspect the box.
AR: 7s content hang on a high-end MBP: https://share.firefox.dev/2YwRpJi

The page uses https://tailwindcss.com/ , the issue only seems to reproduce on local dev builds, not production builds.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

Bugbug thinks this bug should belong to this component, but please revert this change in case of error.

Comment 2

[:Harald Kirschner :digitarald]

Brad, not sure if you can help, but I wanted to assess impact and how many users might experience this – do you have any ideas on what could cause this code path to explode in a severe hang like this?

…
Next
nextToken
parseDeclarationsInternal
parseDeclarations
parseNamedDeclarations
form
write
types.addArrayType/write/<
map
write
write
write
sendReturn

Comment 3

[Brad Werth [:bradwerth]]

I don't have great insight into this, but I'll summarize what I have been able to figure out:

1. This bug would benefit greatly from a testcase with Steps to Reproduce in the form of "Navigate to this site, open devtools, click on this element in the Inspector window, expand it by pressing the right arrow key, then press the down arrow key to select the first child element." I tried to reproduce on any of the sites I found on the tailwind CSS examples page and I couldn't get any significant delays to happen. We need a testcase that can reproduce this issue on demand.
2. The slow part of the parseNamedDeclarations code is the parsing done in lexer.js. We need a test case to determine if this is slow because there's a lot of CSS, or a certain type of CSS, or something else. It certainly seems to work adequately most of the time.
3. The call to parseNamedDeclarations is coming from the form method, which means -- I think -- that the parsing is happening when any method is called on the actor on the client side. We could avoid the hang if we made the call happen asynchronously. Since the form can't return a promise, one option would be to not do this work during form creation, but on-demand in response to a specific call, which could be made async.

Razvan, what do you think about making the work of parseNamedDeclarations into an async, on-demand call?

Comment 4

[:Harald Kirschner :digitarald]

This bug would benefit greatly from a testcase with Steps to Reproduce

I tried a few tailwind examples but this problem does probably not reproduce on production builds. The linked twitter exchange mentions the project that the profile comes from, a PHP-based site with is open source: https://github.com/maxacarvalho/fitnesspelomundo . I build the project and copied the dev CSS output into a glitch for testing:

https://firefox-devtools-testcase-1644138-tailwindcss.glitch.me/

STR: Inspect the box.
AR: 7s content hang on a high-end MBP: https://share.firefox.dev/2YwRpJi

(Added to the initial bug as STR as well)

Comment 5

[Brad Werth [:bradwerth]]

Harald, thanks for posting a simpler testcase. I still can't reproduce, but I'm using a production Nightly build, and you seem to say this isn't happening there? I'd appreciate you giving me even more detail on how to reproduce this problem. What method are you using to trigger inspection? What part of the content hangs?

When I look at your profile, I see that it's the lexer taking up all the time, as expected. I've already suggested in comment 3 that we might be able to avoid calling the lexer synchronously, but now I'm looking to see if there are things we can do to speed up the lexer itself.

Strangely, a lot of the lexer time is spent in functions that call IsOpenCharClass or IsClosedCharClass, but the profiler says it's the calling function that's taking all the time. But these functions: IsIdentStart, IsWhitespace, IsVertSpace do almost nothing besides call one of those two lookup functions. So why is the profiler showing so much self-time, around 80%? Super weird.

If I can figure out how to reproduce this bug, I can start tweaking the lexer to see if I can speed it up. But I still can't reproduce the bug.

Comment 6

[Brad Werth [:bradwerth]]

Okay, I've finally figured out what I'm supposed to watch during reproduction, and I now can reproduce this bug. I'll see if I can speed up the parser.

Comment 7

[Brad Werth [:bradwerth]]

I've been trying various ways to inline the functions that call IsOpenCharClass and IsClosedCharClass, under the assumption that the "self time" shown in the profile is real. Unfortunately, even manual inlining (copy-and-pasting all call sites with the function body) hasn't sped things up in my debug build. I may build an optimized build so I can run the profiler on that; not sure.

Comment 8

[Brad Werth [:bradwerth]]

I did make an opt build, with the calls to IsOpenCharClass and IsClosedCharClass inlined away and it made no meaningful difference to the overall run time: https://share.firefox.dev/2Vlbrps

I'll try some other approaches to speeding up the lexer. I can test them with an opt build now, so that makes direct comparison easier.

Comment 9

[Brad Werth [:bradwerth]]

My experiments in changing the parser have not yielded any speedups. My best idea is to remove the JavaScript CSS parser entirely and rely on the existing style system, as explained in Bug 1649189. I'm taking myself off the bug, for now.

Comment 10

[Razvan Caliman [:rcaliman]]

Attachment: Bug 1644138 - Messy instrumentation with ChromeUtils.addProfilerMarker

This patch adds a few profile markers in the StyleRuleActor and PageStyleActor to investigate the conditions for slow parsing.

Profile https://share.firefox.dev/2WKTe5u

Comment 11

[Razvan Caliman [:rcaliman]]

Attachment: styles-hang-profiler.mp4

Video of fast Rules view for narrow viewport / slow Rules view for wide viewport + profiler results overview.

Comment 12

[Razvan Caliman [:rcaliman]]

I spent some time with this issue and got to the bottom of it.

TL;DR

DevTools has some inefficient code paths regarding parsing CSS, but they're exacerbated by very large stylesheets.
The test case contains a stylesheet of ~4MB and 185.000 lines of code. 😱 There are four very large CSS blocks for media queries, ~800kb each, which apply to all elements and need to be parsed, thus leading to parsing most of that stylesheet for each inspected element.

Profiler link: https://share.firefox.dev/2WKTe5u
See Marker Chart tab for Isolated Web Content timeline and search for PageStyleActor and StyleRuleActor custom markers.

The long explanation

The amount of hang of the Rules view when clicking between <body> and the <div> in test case depends on the viewport width.
At narrow sizes, it is almost instant. It gets progressively slower at wider sizes. Intuition says more CSS is processed at wider sizes, which, it turns out, it's true.

I instrumented the code with ChromeUtils.addProfilerMarker() at important points where the stylesheet text is processed. See the previously attached video for an overview of the profiler result.

I was confused to see four blocks of the exact same size, ~790.000 characters, being read, then parsed in succession. Upon closer inspection, they turn out to be 4 x ~800kb blocks of CSS which contain almost identical CSS declarations:

@media (min-width: 640px) { ... }
@media (min-width: 1024px) { ... }
@media (min-width: 1280px) { ... }
@media (min-width: 1536px) { ... }

They contain CSS rules with identical CSS declarations (using CSS variables), but keyed by a selector to represent viewport size, .sm, .md , .lg, .xl.

Parsing each block takes about ~1 second, which is not particularly slow for 800kb of text. But it's not lightning fast either. The need to parse t4 of those blocks in succession (JS is single-threaded) adds up ~4s to the UI freeze. Ouch! 😖

Basically, for every element, the wider the viewport, the more CSS media queries match and the more CSS text needs to be parsed, then marked overwritten. This explains the difference in performance of the Rules view at different viewport sizes.

I will refrain judgement on whether this is sensible web development. 🤐

Things we can do

1. DevTools has shortcomings which are exacerbated by this extreme sample. The JS-based CSS parser is invoked twice for every CSS Rule:

• once in StyleRuleActor.getAuthorderCssText() to get the substring of CSS text from the stylesheet corresponding to the CSS rule
• and once in StyleRuleActor.form() -> parseNamedDeclarations() to extract each CSS declaration as authored.

This aggravates the hang in the Rules view, from 4 seconds (4 x 1s) to 8 seconds (4 x 1s + 4 x 1s).

This is probably a place where we could work to do just one pass. Either we could grab the authored text from CSSRule.cssText via the CSSOM (need to investigate why that's is not used; perhaps there is a good reason), or we could build the CSS declarations array in the same parsing pass.

2. There's been some discussion about leveraging the platform CSS parser instead of using the JS-based CSS parser. It's not immediately clear what the implications are for that or the scope of the work. :nchevobbe has ideas here.

3. It is inevitable that the single-threaded JS-based CSS parser will be slow as a function of the amount of text it has to parse. I wonder whether we could leverage workers to split parsing per rule across multiple threads to parallelize the work.

---

There are other circumstances where the Rules view is slowed by misuse of CSS, like very large amounts of CSS Custom Properties applied on :root which apply to all elements (bug 1623988). It makes sense to organize this thinking about CSS inspection performance into a bigger theme.

CSS and the way developers write/generate it, has changed substantially since the original architecture of the DevTools. It pays to revisit this for contemporary use cases and expectations.

Comment 13

[Razvan Caliman [:rcaliman]]

Attachment: Four large chunks of CSS being parsed in succession taking ~1s each, twice = 8s hang

Comment 14

[Nicolas Chevobbe [:nchevobbe]]

I did some profiling today on https://firefox-devtools-testcase-1644138-tailwindcss.glitch.me/ , and we can see that modifying a property in a rule takes a long time: https://share.firefox.dev/4bbnYB3 . We spend a lot of time in the lexer, so Bug 1410184 could help here.

Another small thing we see is that if you click on a property value (for example the body rule padding) , modifying it (e.g. from 2 to 3em), and hit Enter, we're calling parseStylesheet twice: https://share.firefox.dev/4b7XHUm
it's probably because we're doing it first time for the preview, when we're still editing, and then another when we "commit" the value. But we could check if the last preview we did is the same than the commit value, and then not parsing again (which would be helpful on those big stylesheets)

Comment 15

[Nicolas Chevobbe [:nchevobbe]]

Modifying a single rule, before and after Bug 1882964:

• before, getRuleText takes 527ms on my machine: https://share.firefox.dev/49UOjSI
• after, getRuleText takes 9ms on my machine: https://share.firefox.dev/3SV6Gjz

Now the main offender is InspectorUtils.parseStyleSheet (~70%) , which we actually need.
Then getStyleSheetRuleCountAndAtRules (~13%), which we don't need in the case of the Inspector. Bug 1888079 will look into this.
#getRegisteredProperties comes next, with ~5%. Most of the time seems to be spent updating stylesheet information (added in Bug 1873207), which probably isn't needed at this point since the stylesheet was already parsed here. I'll try to handle this in Bug 1883832

Comment 16

[Nicolas Chevobbe [:nchevobbe]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #15)

#getRegisteredProperties comes next, with ~5%. Most of the time seems to be spent updating stylesheet information (added in Bug 1873207), which probably isn't needed at this point since the stylesheet was already parsed here. I'll try to handle this in Bug 1883832

actually, when not updating the stylesheet information from getRegisteredProperty, it's still done from another place of the code (refreshObservedRules), so maybe the update is needed after all (and anyway we won't get perf improvement from it), so I'll close the bug

Comment 17

[Nicolas Chevobbe [:nchevobbe]]

(In reply to Nicolas Chevobbe [:nchevobbe] from comment #14)

Another small thing we see is that if you click on a property value (for example the body rule padding) , modifying it (e.g. from 2 to 3em), and hit Enter, we're calling parseStylesheet twice: https://share.firefox.dev/4b7XHUm
it's probably because we're doing it first time for the preview, when we're still editing, and then another when we "commit" the value. But we could check if the last preview we did is the same than the commit value, and then not parsing again (which would be helpful on those big stylesheets)

I'll handle that in Bug 1888081

Comment 18

[Nicolas Chevobbe [:nchevobbe]]

Closing as we fixed all relevant blockers