1131661 - Add styles markers invalidation location

Status: RESOLVED INVALID

(DevTools :: Performance Tools (Profiler/Timeline), defect, P3)

Description

[Tom Tromey :tromey]

This idea came up on irc:

<timeless> wondering if you guys have plans to capture js stack traces for
	   RestyleTracker::AddPendingRestyle


The idea is to capture the stack trace at the point at which a modification
is made which then requires restyling; then display this on the timeline.

Comment 1

[Victor Porof [:vporof][:vp]]

Moving into the Profiler component. Filter on GUTHRIE'S WAVY CAKES.

Comment 2

[Jordan Santell [:jsantell] [@jsantell]]

Would these be attached to the Styles marker, or a different marker?

Comment 3

[Tom Tromey :tromey]

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #2)
> Would these be attached to the Styles marker, or a different marker?

I tend to think a new marker would be better, because there may be many
calls to AddPendingRestyle before any restyling occurs.  Each such call
would come with its own element and stack trace, so collapsing all this
data into a single marker would be difficult.

That said I'm not all that familiar with this code.

Comment 4

[Jordan Santell [:jsantell] [@jsantell]]

We have stacks for our Styles markers, which occurs in DoProcessRestyles, one for each element invalidated. AddPendingRestyle seems to just push a marker onto that queue to be subsequently restyled.

I think what we have is sufficient, unless we have specific reasoning and/or help from layout why and how this would be used beyond the Styles markers (which are different now than when this bug was last updated), since it's not clear why or how this would be used that is not covered by the Styles stacks.

Closing; reopen if I'm wrong

Comment 5

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

The idea is to know what set of operations triggered a restyle that happened later.

Comment 6

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

(In reply to Tom Tromey :tromey from comment #3)
> (In reply to Jordan Santell [:jsantell] [@jsantell] from comment #2)
> > Would these be attached to the Styles marker, or a different marker?
> 
> I tend to think a new marker would be better, because there may be many
> calls to AddPendingRestyle before any restyling occurs.  Each such call
> would come with its own element and stack trace, so collapsing all this
> data into a single marker would be difficult.
> 
> That said I'm not all that familiar with this code.

I think we should just queue up the stacks and then add them as metadata to the next restyle.

Comment 7

[Benoit Girard (:BenWa)]

We already have an implementation of this for the GeckoProfiler+Cleopatra. I would use this at a starting point.

We support capturing the stack of the first, and only the first, thing to invalidate the flow/style of the document. We capture it when the dirty bit is flipped  and thus we can get what caused it.

I'd suggest using this as a starting point. If you capture most causes you will have more data but it will be harder to display and cause a bigger performance overhead.

I wrote a few blog entries about this. In particular the second heading of this:
https://benoitgirard.wordpress.com/2014/05/05/profiler-frame-performance-and-debugging/

Comment 8

[Jordan Santell [:jsantell] [@jsantell]]

Are the markers in nsRefreshDriver.cpp the areas we want to look at, doing the flushing?

profiler_tracing("Paint", "Reflow", mReflowCause, ...)
profiler_tracing("Paint", "Styles", mStyleCause, ...)

We originally had "Recalculate Styles" markers in the same place as these, but this wasn't accurate to what was actually happening ("Recalculate Styles" is a marker now handled in DoProcessRestyles, to match Chrome's markers for recalculating style); this seems like it should be either a specific Flush marker (for both restyle and reflow maybe?), that has this information attached.

Going to keep digging around your blog, Benwa, a lot of useful stuff here :)

Comment 9

[Benoit Girard (:BenWa)]

Yes, once they are capturing this is how we emit to cleopatra. it's possible I messed up the range of them because it's not code I know particularly well.

Comment 10

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

My understanding is that this method does not actually do any restyling, but queues it up for later. When that work *does* happen, it would sure be useful to know what triggered it / queued it up, ie what JS was on the stack when AddPendingRestyle was called.

Because this method isn't actually *doing* the work, it doesn't make sense to trace it.

It *does* make sense to save a stack and add it as metadata to the work that actually *does* get done (ie the restyle we trace sometime later), as comment 6 suggested, and as BenWa says the SPS profiler does already (but only for the first call to AddPendingRestyle).

ni? dholbert for clarification / confirmation / correction on the above.

BenWa, what is the API that exists now? Where would we get access to this existing data?

Comment 11

[Jordan Santell [:jsantell] [@jsantell]]

To make sure I'm understanding correctly, we originally have "Recalc styles" markers the same place as Gecko Profiler -- when we Flush_Style. I see where the mStyleCause stack is captured (and wrestling with needing a docshell there for the ProfilerTimelineMarkers...), but how does that relate to DoProcessRestyles (where our new "Styles" marker is now, to match Chrome)?

It seems that a flush is sometimes (usually?) followed by 1-2 DoProcessRestyles (within the time range of the flush). Should the stack capturing (where mStyleCause is captured) always have a stack, or only in the case of sync invalidations? Couldn't seem to get a test scenario to trigger this (but could be some other issue), and some recalc styles occur without/before the Flush_Style marker -- thoughts on the marker extending from where the stack is captured until Flush_Style completes? Not sure if I understand the relationship/expected flow/pipeline between these 3 chunks of code (DoProcessRestyle, Flush_Style, and nsRefreshDriver::AddStyleFlushObserver, where the stack is captured in the case of Gecko Profiler)

You mention, and I see in the GP marker code, only the first thing to invalidate the style due to cost -- hopefully using ProfileTimelineMarker stacks won't be too costly, as the frames aren't deduped like GP's markers were a few weeks ago.

Comment 12

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 1131661-test.patch

Ugly patch for debugging. 3 new markers:
Flush::Style (same as GP "Styles")
Flush::Reflow (same as GP "Reflow")
Flush::Style::Stack (where GP collects the stack info, this is an attempt just to dump out a single timestamp with stack for ProfileTimelineMarker)

Just to see how these areas all relate. Something with Flush::Style::Stack causes a crash, seems like the docshell is not yet ready

Comment 13

[Daniel Holbert [:dholbert]]

(following up on my ni? -- I believe comment 10 is correct, yeah.)

Comment 14

[Benoit Girard (:BenWa)]

Comment 10 explains this very well. To emphasize what Comment 10 is saying with an example:

1) The page will make a change like myDomElement.classList.add("myClass"); in foo.js:21 which makes changes to styles.

2) This calls into the gecko platform C++ code will mark the styles as being dirty and needing flush. This computation is not performed now, it is *defered* and a dirty bit is noted.

3) I added an instruction that will capture a backtrace here. This backtrace will include foo.js:21 so we will know foo.js:21 made a change that required a change to the style system.

4) We return to foo.js:21, which may make more changes. All of those changes are also deferred and not yet processed. foo.js will finish executing.

5) OPTIONAL: We may process several more events here.

6) The refresh driver will 'fire' and go to paint the page, this will notice that the styles are dirty and that the pending changes need to be flushed/resolved. This execution is what shows up in the devtools timeline as 'Styles' currently. Because we recorded the backtraces in 3) we now that foo.js:21, which may have happened 10ms ago and 100s of events in the past, is responsive for this work that we're performing. If we didn't log a backtrace in 3) we will have no idea what the cause is.

Comment 15

[Benoit Girard (:BenWa)]

Comment on attachment 8614139 [details] [diff] [review]
1131661-test.patch

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

::: layout/base/nsRefreshDriver.cpp
@@ +1658,5 @@
>  
> +          nsRefPtr<nsDocShell> docShell = GetDocShell(shell->GetPresContext());
> +          if (docShell) {
> +            docShell->AddProfileTimelineMarker("Flush::Style",
> +                                               TRACING_INTERVAL_START);

You should be able to access mReflowCause in here. Ideally you should extend AddProfileTimelineMarker to access a 'cause' object. This is how GP does this.

Comment 16

[Jordan Santell [:jsantell] [@jsantell]]

Comment on attachment 8614139 [details] [diff] [review]
1131661-test.patch

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

What I have now is generating a stack nearby for each invalidation (not just the first) and attach it to the subsequent Styles marker. Not sure how to convert GP's stacks to what the TimelineMarker uses as stacks, though I did discover those stacks are also deduped. Easy way to do this? Also, is there a strong perf hit for getting stack on each invalidation?

Comment 17

[Benoit Girard (:BenWa)]

I don't know.

Comment 18

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 1131661-test.patch

Hey Tom, when the stack for this marker is being captured, it fails to get the JS context so it bails out in TimelineMarker::CaptureStack:

`JSContext* ctx = nsContentUtils::GetCurrentJSContext();`

Any idea why that is or what causes it? I understand this shouldn't always succeed, but if a docshell is recording, and I'm assuming where this is hooked in should have a stack (as where Gecko Profiler generates the stack is nearby); any ideas?

Comment 19

[Tom Tromey :tromey]

Comment on attachment 8614420 [details] [diff] [review]
1131661-test.patch

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

I'm afraid I don't know the answer to your question :(
You'll have to ask someone else.

::: layout/base/RestyleManager.cpp
@@ +1830,5 @@
> +    // invalidation stacks.
> +    nsDocShell* docShell = static_cast<nsDocShell*>(mPresContext->GetDocShell());
> +    bool isTimelineRecording = false;
> +    if (docShell) {
> +      docShell->GetRecordProfileTimelineMarkers(&isTimelineRecording);

This can be written more straightforwardly:

isTimelineRecording = docShell->GetRecordProfileTimelineMarkers();

Comment 20

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 1131661-style-invalidations.patch

First patch that works -- attaches "invalidation" stacks on styles markers. Gotta play around with it some more to see how it handles real scenarios, make sure performance is alright, etc

Comment 21

[Jordan Santell [:jsantell] [@jsantell]]

Attachment: 1131661-style-invalidations.patch

Pretty frequently this'll crash. Looks like some sort of GC stuff going on. Any ideas?

Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0   XUL                           	0x00000001041600d2 js::gc::TenuredCell::arenaHeader() const + 338
1   XUL                           	0x00000001040afe71 void js::GCMarker::traverseEdge<js::LazyScript*, JSString*>(js::LazyScript*, JSString*) + 145
2   XUL                           	0x00000001040887d2 void js::GCMarker::traverse<js::LazyScript*>(js::LazyScript*) + 146
3   XUL                           	0x00000001047abb1a JSFunction::trace(JSTracer*) + 410
4   XUL                           	0x00000001040a823b js::GCMarker::processMarkStackTop(js::SliceBudget&) + 1291
5   XUL                           	0x0000000104089765 js::GCMarker::drainMarkStack(js::SliceBudget&) + 69
6   XUL                           	0x00000001046f6478 js::gc::GCRuntime::drainMarkStack(js::SliceBudget&, js::gcstats::Phase) + 88
7   XUL                           	0x00000001046fa93b js::gc::GCRuntime::incrementalCollectSlice(js::SliceBudget&, JS::gcreason::Reason) + 795
8   XUL                           	0x00000001046fb627 js::gc::GCRuntime::gcCycle(bool, js::SliceBudget&, JS::gcreason::Reason) + 423
9   XUL                           	0x00000001046fbf81 js::gc::GCRuntime::collect(bool, js::SliceBudget, JS::gcreason::Reason) + 657
10  XUL                           	0x00000001046fc4c2 js::gc::GCRuntime::gcSlice(JS::gcreason::Reason, long long) + 194
11  XUL                           	0x00000001015ae426 nsJSContext::GarbageCollectNow(JS::gcreason::Reason, nsJSContext::IsIncremental, nsJSContext::IsShrinking, long long) + 230
12  XUL                           	0x0000000100630c33 nsTimerImpl::Fire() + 995
13  XUL                           	0x0000000100630f9e nsTimerEvent::Run() + 334
14  XUL                           	0x000000010062c5d5 nsThread::ProcessNextEvent(bool, bool*) + 1461
15  XUL                           	0x0000000100664eef NS_ProcessPendingEvents(nsIThread*, unsigned int) + 79
16  XUL                           	0x0000000102bdb147 nsBaseAppShell::NativeEventCallback() + 119
17  XUL                           	0x0000000102c303ee nsAppShell::ProcessGeckoEvents(void*) + 190
18  com.apple.CoreFoundation      	0x00007fff84949a01 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17
19  com.apple.CoreFoundation      	0x00007fff8493bb8d __CFRunLoopDoSources0 + 269
20  com.apple.CoreFoundation      	0x00007fff8493b1bf __CFRunLoopRun + 927
21  com.apple.CoreFoundation      	0x00007fff8493abd8 CFRunLoopRunSpecific + 296
22  com.apple.HIToolbox           	0x00007fff8dd0a56f RunCurrentEventLoopInMode + 235
23  com.apple.HIToolbox           	0x00007fff8dd0a2ea ReceiveNextEventCommon + 431
24  com.apple.HIToolbox           	0x00007fff8dd0a12b _BlockUntilNextEventMatchingListInModeWithFilter + 71
25  com.apple.AppKit              	0x00007fff8b07d9bb _DPSNextEvent + 978
26  com.apple.AppKit              	0x00007fff8b07cf68 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 346
27  XUL                           	0x0000000102c2f696 -[GeckoNSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 86
28  com.apple.AppKit              	0x00007fff8b072bf3 -[NSApplication run] + 594
29  XUL                           	0x0000000102c30ae5 nsAppShell::Run() + 421
30  XUL                           	0x00000001037a4f94 XRE_RunAppShell + 260
31  XUL                           	0x00000001009e8e02 mozilla::ipc::MessagePumpForChildProcess::Run(base::MessagePump::Delegate*) + 66
32  XUL                           	0x00000001009b40cc MessageLoop::Run() + 60
33  XUL                           	0x00000001037a49b0 XRE_InitChildProcess + 1904
34  org.mozilla.plugincontainer   	0x00000001000011b0 content_process_main(int, char**) + 208 (plugin-container.cpp:236)
35  org.mozilla.plugincontainer   	0x0000000100000e14 start + 52

Comment 22

[Nick Fitzgerald [:fitzgen] [⏰PST; UTC-8]]

Comment on attachment 8616217 [details] [diff] [review]
1131661-style-invalidations.patch

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

Regarding the GC crashes: do a try push with a hazard analysis build to see if you aren't rooting something when you should be. Nothing is jumping out at me.

::: docshell/base/TimelineMarker.h
@@ +69,5 @@
>      return nullptr;
>    }
>  
> +  static void CaptureCurrentStack(
> +      JS::PersistentRooted<JSObject*>& aStackTrace)

You want to take a `MutableHandle<JSObject>`, not a `PersistentRooted<JSObject>`. Note that there is an implicit `MutableHandle` constructor given a `PersistentRooted*`.

`MutableHandle<T>` means that `T` is a GC thing and that it is rooted Somewhere by Someone. Because it is rooted Somewhere Else by Someone Else, that means *you* don't have to root it yourself, or talk about *how* it is rooted (eg if it is a persistent heap thing, or some stack-only thing, etc). There is also plain `Handle<T>` if you don't need to mutate the thing, which is not the case here. See this comment for more: https://dxr.mozilla.org/mozilla-central/source/js/public/RootingAPI.h?from=MutableHandle#23-102

So, when you make the change to take a `JS::MutableHandle<JSObject>` as a parameter, the call sites would look like this:

  TimelineMarker::CaptureCurrentStack(&mStackStace);

And inside this method, you would do `.set(stack.get())` instead of `.init(...)`.

::: layout/base/RestyleManager.cpp
@@ +1830,5 @@
>    // option here would be a dedicated boolean to track whether we need
>    // to do so (set here and unset in ProcessPendingRestyles).
>    presShell->GetDocument()->SetNeedStyleFlush();
> +
> +    // Gather stack information on style invalidation reasons

It seems this whole block (starting here) is indented 2 more spaces than it should be.

@@ +1834,5 @@
> +    // Gather stack information on style invalidation reasons
> +    // for ProfileTimelineMarkers and pass them to
> +    // mPendingRestyles to attach to the next "Styles" marker.
> +    nsDocShell* docShell = static_cast<nsDocShell*>(mPresContext->GetDocShell());
> +    if (docShell && docShell->GetRecordProfileTimelineMarkers()) {

This code should probably guard on if `nsDocShell::gProfileTimelineRecordingsCount > 0` before even getting the docshell.

@@ +1835,5 @@
> +    // for ProfileTimelineMarkers and pass them to
> +    // mPendingRestyles to attach to the next "Styles" marker.
> +    nsDocShell* docShell = static_cast<nsDocShell*>(mPresContext->GetDocShell());
> +    if (docShell && docShell->GetRecordProfileTimelineMarkers()) {
> +      JS::PersistentRooted<JSObject*> stack;

This should be a plain old `JS::Rooted<JSObject>` that lives on the stack.

@@ +1837,5 @@
> +    nsDocShell* docShell = static_cast<nsDocShell*>(mPresContext->GetDocShell());
> +    if (docShell && docShell->GetRecordProfileTimelineMarkers()) {
> +      JS::PersistentRooted<JSObject*> stack;
> +      TimelineMarker::CaptureCurrentStack(stack);
> +      if (stack.initialized()) {

And then this should just check for if stack is truthy.

@@ +1838,5 @@
> +    if (docShell && docShell->GetRecordProfileTimelineMarkers()) {
> +      JS::PersistentRooted<JSObject*> stack;
> +      TimelineMarker::CaptureCurrentStack(stack);
> +      if (stack.initialized()) {
> +        mPendingRestyles.AddStyleInvalidation(stack);

And then this method should take a `Handle<JSObject>` parameter.

When you append the element, you can use the move construction version of AppendElement to construct the PersistentRooted that gets put in the Sequence in place: https://dxr.mozilla.org/mozilla-central/source/xpcom/glue/nsTArray.h#1452

void
AppendInvalidation(JS::Handle<JSObject> stack)
{
  invalidations.AppendElement(JS::PersistentRooted<JSObject*>(whateverCtx, stack.get()));
}

Comment 23

[Victor Porof [:vporof][:vp]]

Triaging. Filter on ADRENOCORTICOTROPIC (yes).

Comment 24

[Jordan Santell [:jsantell] [@jsantell]]

Unassigning myself from bugs I won't be able to get to due to other commitments.

Comment 25

[Jan Honza Odvarko [:Honza] (always need-info? me)]

The old DevTools Profiler available in the Performance panel has been removed and the panel points to the new Firefox profiler available at profiler.firefox.com

Closing this bug