1050376 - [timeline] gather gecko operations markers under a docshell vector

Status: RESOLVED FIXED

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

Comment 1

[Paul Rouget [:paul]]

Attachment: v0.0001

Comment 2

[Paul Rouget [:paul]]

First, we want to track:
- restyle
- reflow
- paint

Comment 4

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell WIP.patch

Comment 5

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell WIP.patch

This one compiles!

Comment 6

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell WIP.patch

ProfilerMarkers are now handled via UniquePtr to avoid having to delete them when the mTimelineMarkers nsTArray is cleared.

Comment 7

[Paul Rouget [:paul]]

Attachment: tests

I had to use a browser mochitest because of bug 1050773 comment 2.

Comment 8

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v1.patch

v1 - Rebased and added markers for sync reflows.
Paul, some feedback before a first round of formal review would be great.

Comment 9

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v1.1.patch

Forgot to remove an obsolete comment.

Comment 10

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v1.2.patch

Removed trailing whitespaces. Sorry Paul if you already started reviewing this, but it's really the same patch anyway, just with trailing whitespaces removed.

Comment 11

[Paul Rouget [:paul]]

Comment on attachment 8470805 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v1.2.patch

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

I would do a try run with mTimelineStartTime initialized with TimeStamp::Now().
Basically, running all our test suite with the timeline activated. To see if there are crashes.

::: docshell/base/nsIDocShell.idl
@@ +675,5 @@
> +  /**
> +   * Get and flush the devtools timeline markers gathered by the docShell so far
> +   */
> +  [implicit_jscontext]
> +  jsval flushTimelineMarkers();

s/flush/pop ?

::: layout/base/nsRefreshDriver.cpp
@@ +1065,5 @@
> +static void profiler_tracing_recursedocshell(nsDocShell* aRootDocShell,
> +                                             const char* aCategory,
> +                                             const char* aInfo,
> +                                             TracingMetadata aMetaData)
> +{

I would make sure that aRootDocShell is not null here.

::: tools/profiler/GeckoProfilerImpl.cpp
@@ +9,5 @@
> +
> +void profiler_tracing(const char* aCategory, const char* aInfo,
> +                                     nsDocShell* aDocShell,
> +                                     TracingMetadata aMetaData)
> +{

Test nsDocShell.

@@ +18,5 @@
> +void profiler_tracing(const char* aCategory, const char* aInfo,
> +                                     ProfilerBacktrace* aCause,
> +                                     nsDocShell* aDocShell,
> +                                     TracingMetadata aMetaData)
> +{

Test nsDocShell.

Comment 12

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v2.patch

Hi Ehsan, a first round of review on this patch would be great.
Here's a quick summary of what this patch does:

- Exposes a new attribute in nsIDocShell to toggle on/off the recording of timeline events at docShell level.
- Exposes a new function in nsIDocShell to flush the recorded timeline events in the docShell.

- It is built on top of the existing profiler markers recording system by just adding a new profiler_tracing implementation that accepts a docShell parameter.
- Any place where profiler_tracing is called that is interesting for the devtools timeline and where we actually can get a docShell, we now call the new profiler_tracing implementation (so far, this patch tracks async and sync reflows, restyles and paints).

Comment 13

[Patrick Brosset <:pbro>]

Forgot to mention: I ran this patch through various try pushes:
- build on all platforms, no tests: https://tbpl.mozilla.org/?tree=Try&rev=ae97e6d8bfeb
- build on linux only, all tests: https://tbpl.mozilla.org/?tree=Try&rev=b5b288e92f1d
- also, here's a try push with all tests running with the recordTimelineMarkers set to true by default, just to see if turning it on breaks any test: https://tbpl.mozilla.org/?tree=Try&rev=430a4d71ef72

Comment 14

[(no longer active)]

Comment on attachment 8471403 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v2.patch

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

I think smaug is a better reviewer for this patch.

Comment 15

[Olli Pettay [:smaug][[e-mail]]]

Why would we record restyle/reflow/paint at docshell level?
Feels rather odd.

And 
+    // Storing timeline markers to be consumed by the devtools timeline panel
+    mozilla::TimeStamp mTimelineStartTime;
+    nsTArray<mozilla::UniquePtr<ProfilerMarker>> mTimelineMarkers;
doesn't really tell at all what kind of TimelineMarkers we're storing in docshell.

In other words, I need some background information why we are doing this all.

(I can see adding a flag to docshell to tell that all the documents which are created for it will
do some recording, but why docshell itself would record anything...)

Comment 16

[Patrick Brosset <:pbro>]

(In reply to Olli Pettay [:smaug] from comment #15)
> Why would we record restyle/reflow/paint at docshell level?
> Feels rather odd.
> 
> And 
> +    // Storing timeline markers to be consumed by the devtools timeline
> panel
> +    mozilla::TimeStamp mTimelineStartTime;
> +    nsTArray<mozilla::UniquePtr<ProfilerMarker>> mTimelineMarkers;
> doesn't really tell at all what kind of TimelineMarkers we're storing in
> docshell.
> 
> In other words, I need some background information why we are doing this all.
> 
> (I can see adding a flag to docshell to tell that all the documents which
> are created for it will
> do some recording, but why docshell itself would record anything...)

You're right, some background information is needed here.
We are building a timeline tool in the devtools. The goal of this new tool is to pretty much provide the same types of functionality as the chrome devtools timeline: https://developer.chrome.com/devtools/docs/timeline?csw=1

So, we want to expose to the user the reflow/restyle/paint information (and eventually compositing, dom events, memory, ..., but that's for later) in order to help users investigate css-related performance problems.

When you open the devtools toolbox, it has one very specific context: the current tab. Everything in the toolbox let you inspect or modify things in that tab only, so any information we show in the timeline is going to have to be for this tab only.

Now, gecko already has a profiler mechanism whereby markers are stored at global level when you record a profile. This means it's a great tool for mozilla engineers to debug various problems, but not so much for web developers who are only interested in debugging problems related to their website only.

So our approach was to build on top of the profiler mechanism but store markers at docShell level (which corresponds to the tab being inspected by the devtools).
What the patch does is just provide a new implementation of profiler_tracing that accepts a docShell. So profiler_tracing does exactly as before except that when there's a docShell, and if timeline recording has been activated on the docShell, then we also store the markers at this level.

Hope this helps, feel free to ping me.
BenWa, paul, feel free to add to this if I missed anything.

Comment 17

[Olli Pettay [:smaug][[e-mail]]]

Ok, so we want to record stuff during several page loads? In that case docshell approach sounds ok.
How do we deal with iframes? Those have separate docshells.
Or do we just want to map all the stuff under one top level docshell to the same
timeline?

Comment 18

[Patrick Brosset <:pbro>]

(In reply to Olli Pettay [:smaug] from comment #17)
> Ok, so we want to record stuff during several page loads? In that case
> docshell approach sounds ok.
Yes, we want the timeline to survive page loads.
> How do we deal with iframes? Those have separate docshells.
> Or do we just want to map all the stuff under one top level docshell to the
> same
> timeline?
Yes, at least in our v1, that's what we're aiming at, just aggregating all data under the top level docshell.

Comment 19

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8471403 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v2.patch

>+nsDocShell::PopTimelineMarkers(JSContext* aCx,
>+                               JS::MutableHandle<JS::Value> aMarkers)
>+{
>+  JS::Rooted<JSObject*> array(aCx, JS_NewArrayObject(aCx, 0));
>+
>+  // Looping over all markers gathered so far at the docShell level, whenever a
>+  // START marker is found, look for the corresponding END marker and build a
>+  // {name,start,end} JS object.
>+  // Paint markers are different because paint is handled at root docShell level
>+  // in the information that a paint was done is then stored at each sub docShell
>+  // level but we can only be sure that a paint did happen in a docShell if an
>+  // Invalidate marker type was recorded too.
>+
>+  uint32_t eventIndex = 0;
>+  for (uint32_t i = 0; i < mTimelineMarkers.Length(); i++) {
>+    // Get the current marker
>+    ProfilerMarker* startMarker = mTimelineMarkers[i].get();
>+    ProfilerMarkerTracing* startPayload = static_cast<ProfilerMarkerTracing*>(
>+      startMarker->GetPayload());
>+    const char* startMarkerName = startMarker->GetMarkerName();
>+
>+    bool hasSeenPaintInvalidation = false;
>+
>+    if (startPayload->GetMetaData() == TRACING_INTERVAL_START) {
>+      // The assumption is that the devtools timeline flushes markers frequently
>+      // enough for the amount of markers to always be small enough that the
>+      // nested for loop isn't going to be a performance problem.
>+      for (uint32_t j = i + 1; j < mTimelineMarkers.Length(); j ++) {
>+        ProfilerMarker* endMarker = mTimelineMarkers[j].get();
>+        ProfilerMarkerTracing* endPayload = static_cast<ProfilerMarkerTracing*>(
>+          endMarker->GetPayload());
>+        const char* endMarkerName = endMarker->GetMarkerName();
>+
>+        // Look for paint invalidation markers to stream out paint markers
>+        if (strcmp(endMarker->GetMarkerName(), "Invalidate") == 0) {
>+          hasSeenPaintInvalidation = true;
>+        }
>+
>+        bool isSameMarkerType = strcmp(startMarkerName, endMarkerName) == 0;
>+        bool isValidType = strcmp(endMarkerName, "DisplayList") != 0 ||
>+                           hasSeenPaintInvalidation;
>+
>+        if (endPayload->GetMetaData() == TRACING_INTERVAL_END &&
>+            isSameMarkerType && isValidType) {
>+
>+          JS::Rooted<JSObject*> timelineEvent(aCx,
>+            JS_NewObject(aCx, nullptr, JS::NullPtr(), JS::NullPtr()));
>+
>+          JS::RootedString name(aCx,
>+            JS_NewStringCopyZ(aCx, startMarker->GetMarkerName()));
>+          JS_DefineProperty(aCx, timelineEvent, "name", name, JSPROP_ENUMERATE);
>+
>+          JS_DefineProperty(aCx, timelineEvent, "start", startMarker->GetTime(),
>+            JSPROP_ENUMERATE);
>+          JS_DefineProperty(aCx, timelineEvent, "end", endMarker->GetTime(),
>+            JSPROP_ENUMERATE);
>+
>+          JS_SetElement(aCx, array, eventIndex, timelineEvent);
>+          eventIndex ++;
>+
>+          break;
>+        }
>+      }
>+    }
>+  }
>+
>+  aMarkers.setObject(*array);
>+
>+  mTimelineMarkers.Clear();
>+
>+  return NS_OK;
>+}
Looks painful. Could you please at least use less JSAPI by
defining a webidl dictionary for "TimelineEvent" and assign
values to it in C++, and the just call ToJSValue.



>+nsDocShell::AddTimelineMarker(const char* aCategory,
>+                              const char* aInfo,
>+                              ProfilerBacktrace* aCause,
>+                              TracingMetadata aMetaData)
>+{
>+  if (!mTimelineStartTime.IsNull()) {
>+    this->AddTimelineMarker(aInfo,
drop 'this->'

>   /**
>+   * Controls whether the docShell records timeline markers at the moment
>+   */
>+  [infallible] attribute boolean recordTimelineMarkers;
>+
>+  /**
>+   * Returns and flushes the timeline markers gathered by the docShell so far
>+   */
>+  [implicit_jscontext]
>+  jsval popTimelineMarkers();
We really need better names here. What "timeline"?


> 
>@@ -4353,29 +4354,36 @@ FrameLayerBuilder::DrawThebesLayer(Thebe
>     aContext->Scale(userData->mXScale, userData->mYScale);
> 
>     layerBuilder->PaintItems(entry->mItems, aRegionToDraw.GetBounds(), aContext, rc,
>                              builder, presContext,
>                              offset, userData->mXScale, userData->mYScale,
>                              entry->mCommonClipCount);
>   }
> 
>-  if (presContext->GetPaintFlashing() &&
>-      !aLayer->Manager()->IsInactiveLayerManager()) {
>+  bool isActiveLAyerManager = !aLayer->Manager()->IsInactiveLayerManager();
>+
>+  if (presContext->GetPaintFlashing() && isActiveLAyerManager) {
>     gfxContextAutoSaveRestore save(aContext);
>     if (shouldDrawRectsSeparately) {
>       if (aClip == DrawRegionClip::DRAW_SNAPPED) {
>         gfxUtils::ClipToRegionSnapped(aContext, aRegionToDraw);
>       } else if (aClip == DrawRegionClip::DRAW) {
>         gfxUtils::ClipToRegion(aContext, aRegionToDraw);
>       }
>     }
>     FlashPaint(aContext);
>   }
> 
>+  if (presContext && presContext->GetDocShell() && isActiveLAyerManager) {
>+    profiler_tracing("Paint", "Invalidate",
>+                     static_cast<nsDocShell*>(presContext->GetDocShell()),
>+                     TRACING_EVENT);
>+  }
This needs a review from a graphics dev, since this sounds like a hot method, where
profiler_tracing might show up in the profiles, but I don't really know.


>+/**
>+ * Emit profiler_tracing calls for all docshells included in aRootDocShell's
>+ * hierarchy. That is because painting is a done at root level, but we need to
>+ * record timeline events per docshell.
>+ */
>+static void profiler_tracing_recursedocshell(nsDocShell* aRootDocShell,
>+                                             const char* aCategory,
>+                                             const char* aInfo,
>+                                             TracingMetadata aMetaData)
>+{
>+  if (!aRootDocShell) {
>+    return;
>+  }
>+
>+  nsCOMPtr<nsISimpleEnumerator> docShellEnumerator;
>+  nsresult rv = aRootDocShell->GetDocShellEnumerator(nsIDocShellTreeItem::typeAll,
>+    nsIDocShell::ENUMERATE_BACKWARDS, getter_AddRefs(docShellEnumerator));
>+  if (NS_FAILED(rv)) return;
>+
>+  nsCOMPtr<nsIDocShell> curItem;
>+
>+  // XXX We should avoid searching in frameset documents here.
Why?

>+  // We also need to honour mSearchSubFrames and mSearchParentFrames.
>+  bool hasMore = false;
>+  while (NS_SUCCEEDED(docShellEnumerator->HasMoreElements(&hasMore)) && hasMore) {
>+    nsCOMPtr<nsISupports> curSupports;
>+    rv = docShellEnumerator->GetNext(getter_AddRefs(curSupports));
>+    if (NS_FAILED(rv)) break;
>+    curItem = do_QueryInterface(curSupports, &rv);
>+    if (NS_FAILED(rv)) break;
>+
>+    profiler_tracing(aCategory, aInfo, static_cast<nsDocShell*>(curItem.get()),
>+                     aMetaData);
>+  };
>+}
I don't really understand this setup. Why would we want to look for all the hidden docshells too which aren't painted?
(this method is used right before and after painting) Like background tabs and such.


>       if (mPresContext && mPresContext->GetPresShell()) {
>         bool tracingStyleFlush = false;
>         nsAutoTArray<nsIPresShell*, 16> observers;
>         observers.AppendElements(mStyleFlushObservers);
>+        nsDocShell* docShell = GetDocShell(mPresContext);
>+
>         for (uint32_t j = observers.Length();
>              j && mPresContext && mPresContext->GetPresShell(); --j) {
>           // Make sure to not process observers which might have been removed
>           // during previous iterations.
>           nsIPresShell* shell = observers[j - 1];
>           if (!mStyleFlushObservers.Contains(shell))
>             continue;
> 
>           if (!tracingStyleFlush) {
>             tracingStyleFlush = true;
>-            profiler_tracing("Paint", "Styles", mStyleCause, TRACING_INTERVAL_START);
>+            profiler_tracing("Paint", "Styles", mStyleCause, docShell,
>+                             TRACING_INTERVAL_START);
So we are flushing shell, and its docshell is shell->PresContext()->GetDocShell(), but
we pass mPresContext->GetDocShell to profiler_tracing. Why?
Same also elsewhere.


>+  ProfilerMarkerPayload* GetPayload() const {
{ goes to the next line

Comment 20

[Patrick Brosset <:pbro>]

(In reply to Olli Pettay [:smaug] from comment #19)
> Comment on attachment 8471403 [details] [diff] [review]
> bug1050376-record-gecko-timeline-in-docshell v2.patch

Thanks for the review. I'm going through your feedback and will provide a new patch soon.
I have added some remarks/questions/answers below:

> >+nsDocShell::PopTimelineMarkers(JSContext* aCx,
> >+                               JS::MutableHandle<JS::Value> aMarkers)
> Looks painful. Could you please at least use less JSAPI by
> defining a webidl dictionary for "TimelineEvent" and assign
> values to it in C++, and the just call ToJSValue.
Yes, definitely. I just learned what was a webidl dictionary, seems simple enough for me to try and experiment on my own.
The only thing I'm unsure about is that all webidl files are currently in dom/webidl. Should I create one in docshell intead and add the necessary entry to moz.build?

> >+  jsval popTimelineMarkers();
> We really need better names here. What "timeline"?
Did you mean "What *is* "timeline""? or "What *about* "timeline""?
I guess the former, in which case we need a more self-explanatory name. What about replacing all occurences of timeline with devtoolsTimeline? But that, in the other hand, is bad in the sense that this API makes no assumption that the consumer is going to be the devtools.
To be honest, I can't think of better names right now.

> >+  if (presContext && presContext->GetDocShell() && isActiveLAyerManager) {
> >+    profiler_tracing("Paint", "Invalidate",
> >+                     static_cast<nsDocShell*>(presContext->GetDocShell()),
> >+                     TRACING_EVENT);
> >+  }
> This needs a review from a graphics dev, since this sounds like a hot
> method, where
> profiler_tracing might show up in the profiles, but I don't really know.
Benoit Girard was the one working on this with me last week, so I'll probably let him answer that question.

> >+  // XXX We should avoid searching in frameset documents here.
> Why?
Leftover comment from a copy/paste.

> >+  // We also need to honour mSearchSubFrames and mSearchParentFrames.
> >+  bool hasMore = false;
> >+  while (NS_SUCCEEDED(docShellEnumerator->HasMoreElements(&hasMore)) && hasMore) {
> >+    nsCOMPtr<nsISupports> curSupports;
> >+    rv = docShellEnumerator->GetNext(getter_AddRefs(curSupports));
> >+    if (NS_FAILED(rv)) break;
> >+    curItem = do_QueryInterface(curSupports, &rv);
> >+    if (NS_FAILED(rv)) break;
> >+
> >+    profiler_tracing(aCategory, aInfo, static_cast<nsDocShell*>(curItem.get()),
> >+                     aMetaData);
> >+  };
> >+}
> I don't really understand this setup. Why would we want to look for all the
> hidden docshells too which aren't painted?
> (this method is used right before and after painting) Like background tabs
> and such.
So, my understanding is that, unlike restyles and reflows, paints are always executed at root docShell level. So if the docshell we are currently inspecting with the devtools needs to paint, we are not going to be notified of this paint in the refreshDriver.
The profiler_tracing("Paint", "DisplayList", start/end) are only going to be executed by one of the parents of our docShell.
So we know when paints are done at global level, but at that level, we have no way of knowing which sub docShell is actually going to really be painted.
So our solution to that was that, anytime a paint was done in the refreshDriver, we would store a corresponding timeline marker in *all* child docshells.
Now, we also know in FrameLayerBuilder when a given docshell has layers being painted, so what we do is we store another timeline marker when this happens (profiler_tracing("Paint", "Invalidate", ...)

With this information, when popTimelineMarkers is called on the docShell, we just have to make sure that there is a "Paint"/"Invalidate" marker in between 2 "Paint","DisplayList" start and stop. If there isn't, then it means that given paint wasn't for our docshell after all.

> >+        nsDocShell* docShell = GetDocShell(mPresContext);
> >+
> >         for (uint32_t j = observers.Length();
> >              j && mPresContext && mPresContext->GetPresShell(); --j) {
> >           // Make sure to not process observers which might have been removed
> >           // during previous iterations.
> >           nsIPresShell* shell = observers[j - 1];
> >           if (!mStyleFlushObservers.Contains(shell))
> >             continue;
> > 
> >           if (!tracingStyleFlush) {
> >             tracingStyleFlush = true;
> >-            profiler_tracing("Paint", "Styles", mStyleCause, TRACING_INTERVAL_START);
> >+            profiler_tracing("Paint", "Styles", mStyleCause, docShell,
> >+                             TRACING_INTERVAL_START);
> So we are flushing shell, and its docshell is
> shell->PresContext()->GetDocShell(), but
> we pass mPresContext->GetDocShell to profiler_tracing. Why?
> Same also elsewhere.
That's correct. We did this because that's the way the profiler_tracing calls recorded markers. The way this works is there's a START profiler_tracing call that's made only if there's at least one observer being looped on, and the END profiler_tracing call is made after the for loop. The goal being to record the complete time it took to flush restyles and reflows.
Since I only just started development on the platform side, I'm unsure what observer shells are here.
I think it makes sense to record the time it took the parent shell to flush restyles and reflows because that's the shell we are currently interested in, in that tick of the refreshDriver.

Comment 21

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v3.patch

Here's a v2 that addresses review comments.
Please see my comments/questions in comment 20.

Comment 22

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v1.patch

Comment 23

[Patrick Brosset <:pbro>]

Maybe instead of the word timeline, which is too generic and may be confused with the w3c performance timeline API, we could use "GeckoPerformance" or something similar. In the end, that's what it is, a series of markers that gives information about how fast or slow Gecko handles things to be displayed in the current docShell.

recordTimelineMarkers would become recordGeckoPerformanceMarkers
popTimelineMarkers would become popGeckoPerformanceMarkers
and so on...

Comment 24

[Benoit Girard (:BenWa)]

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #20)
> > >+  if (presContext && presContext->GetDocShell() && isActiveLAyerManager) {
> > >+    profiler_tracing("Paint", "Invalidate",
> > >+                     static_cast<nsDocShell*>(presContext->GetDocShell()),
> > >+                     TRACING_EVENT);
> > >+  }
> > This needs a review from a graphics dev, since this sounds like a hot
> > method, where
> > profiler_tracing might show up in the profiles, but I don't really know.
> Benoit Girard was the one working on this with me last week, so I'll
> probably let him answer that question.
> 

This part of the code isn't really that 'hot'. Its typically called 2-10 times per frame. But we should make sure that profiler_tracing checks that nothing is listening and early returns before it does any 'new' allocation.

Comment 25

[Patrick Brosset <:pbro>]

(In reply to Benoit Girard (:BenWa) from comment #24)
> This part of the code isn't really that 'hot'. Its typically called 2-10
> times per frame. But we should make sure that profiler_tracing checks that
> nothing is listening and early returns before it does any 'new' allocation.
That is the case in the patch. profiler_tracing calls nsDocShell::AddTimelineMarker which first checks if we are recording, it returns otherwise.

Comment 26

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #20)

> So, my understanding is that, unlike restyles and reflows, paints are always
> executed at root docShell level. So if the docshell we are currently
> inspecting with the devtools needs to paint, we are not going to be notified
> of this paint in the refreshDriver.
> The profiler_tracing("Paint", "DisplayList", start/end) are only going to be
> executed by one of the parents of our docShell.
> So we know when paints are done at global level, but at that level, we have
> no way of knowing which sub docShell is actually going to really be painted.
> So our solution to that was that, anytime a paint was done in the
> refreshDriver, we would store a corresponding timeline marker in *all* child
> docshells.
> Now, we also know in FrameLayerBuilder when a given docshell has layers
> being painted, so what we do is we store another timeline marker when this
> happens (profiler_tracing("Paint", "Invalidate", ...)
> 
> With this information, when popTimelineMarkers is called on the docShell, we
> just have to make sure that there is a "Paint"/"Invalidate" marker in
> between 2 "Paint","DisplayList" start and stop. If there isn't, then it
> means that given paint wasn't for our docshell after all.
Sounds complicated when you could just bypass those docshells which are hidden.
And we certainly don't want to iterate through all the docshells if we aren't actually doing any profiling.
There can be up to thousands of docshells in a top level XULWindow, and we do this enumeration twice, so that
would certainly show up in the performance profiles.

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #23)
> Maybe instead of the word timeline, which is too generic and may be confused
> with the w3c performance timeline API, we could use "GeckoPerformance" or
> something similar. In the end, that's what it is, a series of markers that
> gives information about how fast or slow Gecko handles things to be
> displayed in the current docShell.
> 
> recordTimelineMarkers would become recordGeckoPerformanceMarkers
> popTimelineMarkers would become popGeckoPerformanceMarkers
> and so on...
Perhaps profilingTimeline?

Comment 27

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8472945 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v3.patch

>+++ b/layout/base/nsPresShell.cpp
>@@ -8767,16 +8767,21 @@ PresShell::DoReflow(nsIFrame* target, bo
>   nsAutoCString docURL("N/A");
>   nsIURI *uri = mDocument->GetDocumentURI();
>   if (uri)
>     uri->GetSpec(docURL);
> 
>   PROFILER_LABEL_PRINTF("PresShell", "DoReflow",
>     js::ProfileEntry::Category::GRAPHICS, "(%s)", docURL.get());
> 
>+  nsDocShell* docShell = static_cast<nsDocShell*>(GetPresContext()->GetDocShell());
>+  if (!aInterruptible && docShell) {
>+    profiler_tracing("Paint", "Reflow", docShell, TRACING_INTERVAL_START);
>+  }
Why you don't trace interruptible reflows?

>+static void profiler_tracing_recursedocshell(nsDocShell* aRootDocShell,
>+                                             const char* aCategory,
>+                                             const char* aInfo,
>+                                             TracingMetadata aMetaData)
>+{
>+  if (!aRootDocShell) {
>+    return;
>+  }
>+
>+  nsCOMPtr<nsISimpleEnumerator> docShellEnumerator;
>+  nsresult rv = aRootDocShell->GetDocShellEnumerator(nsIDocShellTreeItem::typeAll,
>+    nsIDocShell::ENUMERATE_BACKWARDS, getter_AddRefs(docShellEnumerator));
>+  if (NS_FAILED(rv)) return;
>+
>+  nsCOMPtr<nsIDocShell> curItem;
>+  bool hasMore = false;
>+  while (NS_SUCCEEDED(docShellEnumerator->HasMoreElements(&hasMore)) && hasMore) {
>+    nsCOMPtr<nsISupports> curSupports;
>+    rv = docShellEnumerator->GetNext(getter_AddRefs(curSupports));
>+    if (NS_FAILED(rv)) break;
>+    curItem = do_QueryInterface(curSupports, &rv);
>+    if (NS_FAILED(rv)) break;
>+
>+    profiler_tracing(aCategory, aInfo, static_cast<nsDocShell*>(curItem.get()),
>+                     aMetaData);
>+  };
>+}
So we really can't do this twice every time we're about to paint something.

>       if (mPresContext && mPresContext->GetPresShell()) {
>         bool tracingStyleFlush = false;
>         nsAutoTArray<nsIPresShell*, 16> observers;
>         observers.AppendElements(mStyleFlushObservers);
>+        nsDocShell* docShell = GetDocShell(mPresContext);
>+
>         for (uint32_t j = observers.Length();
>              j && mPresContext && mPresContext->GetPresShell(); --j) {
>           // Make sure to not process observers which might have been removed
>           // during previous iterations.
>           nsIPresShell* shell = observers[j - 1];
>           if (!mStyleFlushObservers.Contains(shell))
>             continue;
> 
>           if (!tracingStyleFlush) {
>             tracingStyleFlush = true;
>-            profiler_tracing("Paint", "Styles", mStyleCause, TRACING_INTERVAL_START);
>+            profiler_tracing("Paint", "Styles", mStyleCause, docShell,
>+                             TRACING_INTERVAL_START);
>             mStyleCause = nullptr;
>           }
> 
>           NS_ADDREF(shell);
>           mStyleFlushObservers.RemoveElement(shell);
>           shell->GetPresContext()->RestyleManager()->mObservingRefreshDriver = false;
>           shell->FlushPendingNotifications(ChangesToFlush(Flush_Style, false));
So I still don't quite understand. We're flushing style of shell, but we record the timeline in mPresContext->GetDocshell()
Why we don't want to record the style flushing in the right docshell?
Similar also with other flushes.
Or we if want to record the time on mPresContext->GetDocshell(), just move profiler_tracing calls to be outside the loops?

Comment 28

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v4.patch

(In reply to Olli Pettay [:smaug] from comment #26)
> Sounds complicated when you could just bypass those docshells which are
> hidden.
> And we certainly don't want to iterate through all the docshells if we
> aren't actually doing any profiling.
> There can be up to thousands of docshells in a top level XULWindow, and we
> do this enumeration twice, so that
> would certainly show up in the performance profiles.
I've changed a bit the logic here, now we only enumerate the docshells once and filter out all of those that are either not visible or not recording timeline markers. This should make it better.
I don't know of a way to avoid this entirely though. I've spent time looking at that part of the code and logging stuff out and I think my original understanding was correct: the part of nsRefreshDriver::tick that deals with painting and that we want to trace is never called with presContext->GetDocShell() being the one we actually are inspecting in the devtools. That's because painting is handled by one of the parent docShells (I guess this will change with e10s) and we only know if our inspected docShell has been painted at a lower level in the code.

> Perhaps profilingTimeline?
Sounds good. I've decided using the prefix ProfileTimeline for all my members and methods (GetRecordProfileTimelineMarkers, PopProfileTimelineMarkers, etc.)

(In reply to Olli Pettay [:smaug] from comment #27)
> >+  nsDocShell* docShell = static_cast<nsDocShell*>(GetPresContext()->GetDocShell());
> >+  if (!aInterruptible && docShell) {
> >+    profiler_tracing("Paint", "Reflow", docShell, TRACING_INTERVAL_START);
> >+  }
> Why you don't trace interruptible reflows?
That was because async reflows were already being traced in nsRefreshDriver. But I've changed that now and all reflows are now traced here.

> So I still don't quite understand. We're flushing style of shell, but we
> record the timeline in mPresContext->GetDocshell()
> Why we don't want to record the style flushing in the right docshell?
> Similar also with other flushes.
> Or we if want to record the time on mPresContext->GetDocshell(), just move
> profiler_tracing calls to be outside the loops?
Ok, I've changed this part to now record styles and reflows at the right docShell.
I started the patch with reusing as much of the profiler code as possible, and in particular, I tried keeping the same 'profiler_tracing' calls, but it turns out is just too hard to maintain that parallel. Our docShell-centric timeline is different from the global level profiler because we want information about specific docShells, so I've ended up removing my implementation of profiler_tracing (the one that accepted an extra docShell argument) and now call docShell->AddProfileTimelineMarker() directly, which gives me more flexibility.

Comment 29

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8474587 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v4.patch

>+        const char* endMarkerName = endMarker->GetMarkerName();
>+
>+        // Look for paint invalidation markers to stream out paint markers
>+        if (strcmp(endMarker->GetMarkerName(), "Invalidate") == 0) {
Why you don't use endMarkerName here?

>+static void GetProfileTimelineSubDocShells(nsDocShell* aRootDocShell,
>+                                           nsTArray<nsDocShell*>& aShells)
>+{
>+  if (!aRootDocShell) {
>+    return;
>+  }
>+
>+  nsCOMPtr<nsISimpleEnumerator> enumerator;
>+  nsresult rv = aRootDocShell->GetDocShellEnumerator(nsIDocShellTreeItem::typeAll,
>+    nsIDocShell::ENUMERATE_BACKWARDS, getter_AddRefs(enumerator));
>+
>+  if (NS_FAILED(rv)) {
>+    return;
>+  }
>+
>+  nsCOMPtr<nsIDocShell> curItem;
>+  bool hasMore = false;
>+  while (NS_SUCCEEDED(enumerator->HasMoreElements(&hasMore)) && hasMore) {
>+    nsCOMPtr<nsISupports> curSupports;
>+    rv = enumerator->GetNext(getter_AddRefs(curSupports));
>+    if (NS_FAILED(rv)) break;
>+    curItem = do_QueryInterface(curSupports, &rv);
>+    if (NS_FAILED(rv)) break;
>+
>+    nsDocShell* shell = static_cast<nsDocShell*>(curItem.get());
>+    
>+    if (shell) {
>+      bool isVisible = false;
>+      shell->GetVisibility(&isVisible);
>+      bool isRecording = false;
>+      shell->GetRecordProfileTimelineMarkers(&isRecording);
>+      
>+      if (isVisible && isRecording) {
>+        aShells.AppendElement(shell);
>+      }
>+    }
>+  };
So we're still unconditionally calling this method, and the method isn't exactly
fast one in case there are lots of docshells.
We need to not do any of this work in case we're not doing any profiling for any docshell.

Almost there, but would like to see yet another patch.

Comment 30

[Patrick Brosset <:pbro>]

(In reply to Olli Pettay [:smaug] from comment #29)
> Comment on attachment 8474587 [details] [diff] [review]
> bug1050376-record-gecko-timeline-in-docshell v4.patch
> 
> >+        const char* endMarkerName = endMarker->GetMarkerName();
> >+
> >+        // Look for paint invalidation markers to stream out paint markers
> >+        if (strcmp(endMarker->GetMarkerName(), "Invalidate") == 0) {
> Why you don't use endMarkerName here?
Changed.
> >+static void GetProfileTimelineSubDocShells(nsDocShell* aRootDocShell,
> >+                                           nsTArray<nsDocShell*>& aShells)
> >+{
> >+  if (!aRootDocShell) {
> >+    return;
> >+  }
> >+
> >+  nsCOMPtr<nsISimpleEnumerator> enumerator;
> >+  nsresult rv = aRootDocShell->GetDocShellEnumerator(nsIDocShellTreeItem::typeAll,
> >+    nsIDocShell::ENUMERATE_BACKWARDS, getter_AddRefs(enumerator));
> >+
> >+  if (NS_FAILED(rv)) {
> >+    return;
> >+  }
> >+
> >+  nsCOMPtr<nsIDocShell> curItem;
> >+  bool hasMore = false;
> >+  while (NS_SUCCEEDED(enumerator->HasMoreElements(&hasMore)) && hasMore) {
> >+    nsCOMPtr<nsISupports> curSupports;
> >+    rv = enumerator->GetNext(getter_AddRefs(curSupports));
> >+    if (NS_FAILED(rv)) break;
> >+    curItem = do_QueryInterface(curSupports, &rv);
> >+    if (NS_FAILED(rv)) break;
> >+
> >+    nsDocShell* shell = static_cast<nsDocShell*>(curItem.get());
> >+    
> >+    if (shell) {
> >+      bool isVisible = false;
> >+      shell->GetVisibility(&isVisible);
> >+      bool isRecording = false;
> >+      shell->GetRecordProfileTimelineMarkers(&isRecording);
> >+      
> >+      if (isVisible && isRecording) {
> >+        aShells.AppendElement(shell);
> >+      }
> >+    }
> >+  };
> So we're still unconditionally calling this method, and the method isn't
> exactly
> fast one in case there are lots of docshells.
> We need to not do any of this work in case we're not doing any profiling for
> any docshell.
Ok, sounds good. I just need to find a why to know whether there is at least one docShell that is being profiled at the moment. Right now I need to iterate over the children to know if at least 1 is recording. I need a global check. I'm not familiar with ways to do that yet, but I'll start by looking/asking around.
> Almost there, but would like to see yet another patch.
Sure, no problem. This is my first c++ patch and I don't know much about the mozilla platform yet, so any R- is a chance to learn some more :)

Comment 31

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v5.patch

Introduced a static profile timeline recording counter in nsDocShell. It is incremented whenever a docShell starts recording and decremented when a docShell stops recording.
nsRefreshDriver::GetProfileTimelineSubDocShells now checks this first and early return if 0.

Comment 32

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v2.patch

Updated the test patch with the new names.

Comment 33

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v5.1.patch

Fixing a typo in a comment

Comment 34

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v5.2.patch

Forgot to decrement the record counter in the destructor.

Comment 35

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8475124 [details] [diff] [review]
bug1050376-timeline-tests v2.patch

>+let test = Task.async(function*() {
>+  waitForExplicitFinish();
>+
>+  yield openUrl("data:text/html;charset=utf-8,Test page");

(personally I truly hate yield and the spaghetti code it tends to create. It reminds goto too much. 
 But that is just me, so this is fine.)

>+function* openUrl(url) {
>+  let def = Promise.defer();
Promise doesn't have defer().
Could you please use the native Promise implementation which follows the spec better than whatever
libraries we have.


>+  check: function(markers) {
>+    ok(markers.length > 0, "markers were returned");
>+    ok(markers.some(m => m.name == "Reflow"), "markers includes Reflow");
/me cries the recent JS syntax :(
function() is so much clearer for reader than =>
(and we don't need here the automatic binding => does)


r- because of use of some old Promise API.

Comment 36

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8476608 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v5.2.patch


>+
>+    // Add new profile timeline markers to this docShell. This will only add
>+    // markers if the docShell is currently recording profile timeline markers.
>+    // See nsIDocShell::recordProfileTimelineMarkers
>+    void AddProfileTimelineMarker(const char* aCategory,
>+                           const char* aInfo,
>+                           TracingMetadata aMetaData);
>+    void AddProfileTimelineMarker(const char* aCategory,
>+                           const char* aInfo,
>+                           ProfilerBacktrace* aCause,
>+                           TracingMetadata aMetaData);
align parameters


>+    // Storing profile timeline markers and if/when recording started
>+    mozilla::TimeStamp mProfileTimelineStartTime;
>+    nsTArray<mozilla::UniquePtr<ProfilerMarker>> mProfileTimelineMarkers;
Why you need UniquePtr here?
Doesn't nsTArray<ProfilerMarker> work?
Then when appending to the array do something like
ProfilerMarker* newMarker = mProfileTimelineMarkers.AppendElement();




>+  nsDocShell* docShell = static_cast<nsDocShell*>(GetPresContext()->GetDocShell());
>+  if (docShell) {
>+    docShell->AddProfileTimelineMarker("Paint", "Reflow", TRACING_INTERVAL_START);
>+  }
Don't understand why "Paint" + "Reflow" since those don't have much to do with each others, but
if "Paint" is some generic category for all layout+gfx stuff, fine.



>+static nsDocShell* GetDocShell(nsPresContext* presContext) {
{ goes to the next line, and s/presContext/aPresContext

>+  nsCOMPtr<nsIDocShell> curItem;
>+  bool hasMore = false;
>+  while (NS_SUCCEEDED(enumerator->HasMoreElements(&hasMore)) && hasMore) {
>+    nsCOMPtr<nsISupports> curSupports;
>+    rv = enumerator->GetNext(getter_AddRefs(curSupports));
>+    if (NS_FAILED(rv)) break;
Use {} always with 'if'.
But you could just not have this 'if' at all


>+    curItem = do_QueryInterface(curSupports, &rv);
... since do_QueryInterface is null safe.
Use the variant without &rv

>+    if (NS_FAILED(rv)) break;
drop this...


>+
>+    nsDocShell* shell = static_cast<nsDocShell*>(curItem.get());
>+    
>+    if (shell) {
since you anyway do a null check here.


>+      bool isVisible = false;
>+      shell->GetVisibility(&isVisible);
>+      bool isRecording = false;
>+      shell->GetRecordProfileTimelineMarkers(&isRecording);
>+      
>+      if (isVisible && isRecording) {
You could just do
if (isVisible && shell->RecordProfileTimelineMarkers())
...but actually, better to first check RecordProfileTimelineMarkers() and
only if it is true, check the visibility, since visibility check isn't super fast.






>+          nsDocShell* docShell = GetDocShell(shell->GetPresContext());
>+          if (docShell) {
>+            docShell->AddProfileTimelineMarker("Paint", "Styles", mStyleCause,
>+                                               TRACING_INTERVAL_START);
>+          }
>+
>           if (!tracingStyleFlush) {
>             tracingStyleFlush = true;
>             profiler_tracing("Paint", "Styles", mStyleCause, TRACING_INTERVAL_START);
>             mStyleCause = nullptr;
>           }
> 
>           NS_ADDREF(shell);
>           mStyleFlushObservers.RemoveElement(shell);
>           shell->GetPresContext()->RestyleManager()->mObservingRefreshDriver = false;
>           shell->FlushPendingNotifications(ChangesToFlush(Flush_Style, false));
>           NS_RELEASE(shell);
>+
>+          if (docShell) {
>+            docShell->AddProfileTimelineMarker("Paint", "Styles",
>+                                               TRACING_INTERVAL_END);
docshell is possibly a dead object here.
You really must make docShell a strong reference, so use nsRefPtr.

I don't understand "Paint", "Styles".
How is flushing styles really about painting.
Styles are possibly flushed many times before doing any painting.
But I guess that is fine since we have the old 
profiler_tracing("Paint", "Styles", TRACING_INTERVAL_END); too

Comment 37

[Patrick Brosset <:pbro>]

(In reply to Olli Pettay [:smaug] from comment #36)
> Comment on attachment 8476608 [details] [diff] [review]
> bug1050376-record-gecko-timeline-in-docshell v5.2.patch
> >+    // Storing profile timeline markers and if/when recording started
> >+    mozilla::TimeStamp mProfileTimelineStartTime;
> >+    nsTArray<mozilla::UniquePtr<ProfilerMarker>> mProfileTimelineMarkers;
> Why you need UniquePtr here?
> Doesn't nsTArray<ProfilerMarker> work?
> Then when appending to the array do something like
> ProfilerMarker* newMarker = mProfileTimelineMarkers.AppendElement();
This comes from when BenWa and I originally worked on the patch. The goal was to make sure ProfilerMarker objects would be freed when calling mProfileTimelineMarkers.Clear();
I'm happy to just use nsTArray<ProfilerMarker> since that sounds simpler to me.
I'm puzzled about this line though:
ProfilerMarker* newMarker = mProfileTimelineMarkers.AppendElement();
(this is my first patch with c++ and I'm still largely a beginner with the language). Can you elaborate about this?

> >+  nsDocShell* docShell = static_cast<nsDocShell*>(GetPresContext()->GetDocShell());
> >+  if (docShell) {
> >+    docShell->AddProfileTimelineMarker("Paint", "Reflow", TRACING_INTERVAL_START);
> >+  }
> Don't understand why "Paint" + "Reflow" since those don't have much to do
> with each others, but
> if "Paint" is some generic category for all layout+gfx stuff, fine.
Yeah, we just reused the same categories that the profiler was already using.
But since we don't rely as much as we thought we would on the profiler backend anyway, I might as well choose better names.

> >+      bool isVisible = false;
> >+      shell->GetVisibility(&isVisible);
> >+      bool isRecording = false;
> >+      shell->GetRecordProfileTimelineMarkers(&isRecording);
> >+      
> >+      if (isVisible && isRecording) {
> You could just do
> if (isVisible && shell->RecordProfileTimelineMarkers())
> ...but actually, better to first check RecordProfileTimelineMarkers() and
> only if it is true, check the visibility, since visibility check isn't super
> fast.
Not sure I understand, RecordProfileTimelineMarkers isn't a member of nsDocShell. There's a recordProfileTimelineMarkers attribute on nsIDocShell and 2 corresponding Get/Set methods on nsDocShell.
I understand the point about testing first the flag before the visibility for performance reasons though.

> >+          nsDocShell* docShell = GetDocShell(shell->GetPresContext());
> >+          if (docShell) {
> >+            docShell->AddProfileTimelineMarker("Paint", "Styles", mStyleCause,
> >+                                               TRACING_INTERVAL_START);
> >+          }
> >+
> >           if (!tracingStyleFlush) {
> >             tracingStyleFlush = true;
> >             profiler_tracing("Paint", "Styles", mStyleCause, TRACING_INTERVAL_START);
> >             mStyleCause = nullptr;
> >           }
> > 
> >           NS_ADDREF(shell);
> >           mStyleFlushObservers.RemoveElement(shell);
> >           shell->GetPresContext()->RestyleManager()->mObservingRefreshDriver = false;
> >           shell->FlushPendingNotifications(ChangesToFlush(Flush_Style, false));
> >           NS_RELEASE(shell);
> >+
> >+          if (docShell) {
> >+            docShell->AddProfileTimelineMarker("Paint", "Styles",
> >+                                               TRACING_INTERVAL_END);
> docshell is possibly a dead object here.
> You really must make docShell a strong reference, so use nsRefPtr.
I think I need a little mentoring on this too. How can doShell be a dead object here? Is it because of NS_RELEASE(shell) just above? Also, is the point of turning nsDocShell* into nsRefPtr<nsDocShell> to make sure that a count ref is added to the docShell and so it won't be destroyed? Does this mean I then need to release that reference? How?

> I don't understand "Paint", "Styles".
> How is flushing styles really about painting.
> Styles are possibly flushed many times before doing any painting.
> But I guess that is fine since we have the old 
> profiler_tracing("Paint", "Styles", TRACING_INTERVAL_END); too
Yes, again, we were just reusing the same categories/names than the profiler. As I said earlier, I can change them though.

Comment 38

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell-2.patch

As my last comment suggests, there's a few review comments I'm not sure how to act upon, so I've captured my latest changes in a separate patch.

You'll see I've remove the need for ProfilerMarker objects, and am now instead just using a struct ProfileTimelineMarker. With this, I removed the nsTArray<mozilla::UniquePtr<ProfilerMarker>> mProfileTimelineMarkers part and replaced it, as suggested, with a simple nsTArray<ProfileTimelineMarker>.

I'm also now using nsRefPtr<nsDocShell> docShell = GetDocShell(shell->GetPresContext()) in nsRefreshDriver.cpp

Comment 39

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v3.patch

(In reply to Olli Pettay [:smaug] from comment #35)
> Comment on attachment 8475124 [details] [diff] [review]
> bug1050376-timeline-tests v2.patch
> 
> >+let test = Task.async(function*() {
> >+  waitForExplicitFinish();
> >+
> >+  yield openUrl("data:text/html;charset=utf-8,Test page");
> 
> (personally I truly hate yield and the spaghetti code it tends to create. It
> reminds goto too much. 
>  But that is just me, so this is fine.)
Really? For me yield + tasks work really great because they give you back control flow in async code, basically making it look sync, instead of dealing with endlessly nested callbacks and chains of .then().then().then().

> >+function* openUrl(url) {
> >+  let def = Promise.defer();
> Promise doesn't have defer().
> Could you please use the native Promise implementation which follows the
> spec better than whatever
> libraries we have.
Done. Thanks for the suggestion, I wasn't entirely sure we could start using native promises already.

> >+  check: function(markers) {
> >+    ok(markers.length > 0, "markers were returned");
> >+    ok(markers.some(m => m.name == "Reflow"), "markers includes Reflow");
> /me cries the recent JS syntax :(
> function() is so much clearer for reader than =>
> (and we don't need here the automatic binding => does)
I guess it depends on the reader then :)
I would tend to agree for, more complex, multi-line functions. But when it comes to simple one-liner callbacks like this, I really like this new syntax, it makes it a lot more compact.

Comment 40

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v6.patch

Comment 41

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #37)
> I'm puzzled about this line though:
> ProfilerMarker* newMarker = mProfileTimelineMarkers.AppendElement();
> (this is my first patch with c++ and I'm still largely a beginner with the
> language). Can you elaborate about this?
See nsTArray.h
AppendElement() appends a new element to the array and gives pointer to it so that you can initialize the values.


> > >+      if (isVisible && isRecording) {
> > You could just do
> > if (isVisible && shell->RecordProfileTimelineMarkers())
> > ...but actually, better to first check RecordProfileTimelineMarkers() and
> > only if it is true, check the visibility, since visibility check isn't super
> > fast.
> Not sure I understand, RecordProfileTimelineMarkers isn't a member of
> nsDocShell. There's a recordProfileTimelineMarkers attribute on nsIDocShell
> and 2 corresponding Get/Set methods on nsDocShell.
RecordProfileTimelineMarkers is marked infallible.
So one doesn't need to use outparam.
But indeed, even the infallible version has Get* prefix.
So, shell->GetRecordProfileTimelineMarkers()



> > >+          if (docShell) {
> > >+            docShell->AddProfileTimelineMarker("Paint", "Styles",
> > >+                                               TRACING_INTERVAL_END);
> > docshell is possibly a dead object here.
> > You really must make docShell a strong reference, so use nsRefPtr.
> I think I need a little mentoring on this too. How can doShell be a dead
> object here? Is it because of NS_RELEASE(shell) just above?
flushing layout may run scripts, which means a window is possibly closed or whatever.

> Also, is the
> point of turning nsDocShell* into nsRefPtr<nsDocShell> to make sure that a
> count ref is added to the docShell and so it won't be destroyed?
Right.

 Does this
> mean I then need to release that reference? How?
nsRefPtr AddRefs when you assign value to it, and it automatically releases when the variable goes out of scope.

Comment 42

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v7.patch

- Simplified mProfileTimelineMarkers nsTArray by introducing a struct to store markers.
- Simplified AddProfileTimelineMarker's signature. Now strings "Paint", "Styles" and "Reflow" are passed instead of the misleading couple of strings: "Paint","Styles".
- Reworked nsRefreshDriver::GetProfileTimelineSubDocShells to simplify it and avoid checking the visibility if the docShell isn't recording.
- ... and more minor fixes ...

Thanks for your help so far Olli!

Comment 43

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8478980 [details] [diff] [review]
bug1050376-timeline-tests v3.patch

mostly rs+


>+let test = Task.async(function*() {
...
>+    info("Running the test setup function");
>+    let onMarkers = waitForMarkers(docShell);
>+    setup(div);
>+
>+    info("Waiting for new markers on the docShell");
>+    let markers = yield onMarkers;
Took quite some time, and chatting on #devtools, to understand this code.
The key issue was that I've never used Task.js so had no idea what yield onMarkers; does.
In general I'd prefer to not rely on some random script libraries in tests.
(like, I wouldn't rely on jQuery, but just use the plain normal DOM APIs)

>+function* waitForMarkers(docshell) {
No need for * here, as far I see, and if just makes this generator heavy code harder to read.

Comment 44

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Olli Pettay [:smaug] from comment #43)

> >+function* waitForMarkers(docshell) {
> No need for * here, as far I see, 
far as...

>and if just makes this generator heavy
> code harder to read.
s/if/it/

Comment 45

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8479713 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v7.patch

>+  for (uint32_t i = 0; i < mProfileTimelineMarkers.Length(); i++) {
++i

>+      for (uint32_t j = i + 1; j < mProfileTimelineMarkers.Length(); j ++) {
++j
>+    // Storing profile timeline markers and if/when recording started
>+    struct ProfileTimelineMarker
The name of the webidl dictionary really should be something else than the name of the struct.
Maybe the struct could be InternalProfileTimelineMarker

>+    {
>+      const char* name;
mName

>+      ProfilerMarkerTracing* payload;
mPayload

>+      float time;
mTime

>+    };
You end up leaking all the payloads.
Maybe nsAutoPtr<ProfilerMarkerTracing> mPayload, or just
ProfilerMarkerTracing mPayload
I think the latter should work just fine, and then no need to explicitly allocate ProfilerMarkerTracing objects.

Comment 46

[Benoit Girard (:BenWa)]

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #38)
> You'll see I've remove the need for ProfilerMarker objects, and am now
> instead just using a struct ProfileTimelineMarker. With this, I removed the
> nsTArray<mozilla::UniquePtr<ProfilerMarker>> mProfileTimelineMarkers part
> and replaced it, as suggested, with a simple nsTArray<ProfileTimelineMarker>.

This relies on the copy constructor which should of been disallowed. Sadly c++ gives a default copy constructor but complex classes like ProfilerMarker are used to not be copy-able if they don't have a copy constructor defined.

Comment 47

[Olli Pettay [:smaug][[e-mail]]]

oh, right, we don't want payload to be nsAutoPtr<ProfilerMarkerTracing>, but 
ProfilerMarkerTracing should be fine

Comment 48

[Olli Pettay [:smaug][[e-mail]]]

Also, when I suggested dropping UniquePtr, I thought the array was for the mozilla::dom::ProfileTimelineMarker, and not for the other struct.
(so names really must be different.)

Comment 49

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8479713 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v7.patch

Given that, let's use nsTArray<nsAutoPtr<InternalProfileTimelineMarker>>
or nsTArray<mozilla::UniquePtr<InternalProfileTimelineMarker>>.
I could take another look.

Comment 50

[Olli Pettay [:smaug][[e-mail]]]

And thank BenWa!

Comment 51

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v4.patch

Thanks for the review. Removed the extra generator * symbol next to waitForMarkers.

Comment 52

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v8.patch

Here's my attempt at fixing what smaug and BenWa discussed in the previous comment. This seems to work.
Let me know if this is correct.

Comment 53

[Patrick Brosset <:pbro>]

Interdiff: https://bugzilla.mozilla.org/attachment.cgi?oldid=8479713&action=interdiff&newid=8480536&headers=1

Comment 54

[Patrick Brosset <:pbro>]

Try builds with the latest patch:
- all builds, no tests: https://tbpl.mozilla.org/?tree=Try&rev=cde730023bbf
- linux build, all tests: https://tbpl.mozilla.org/?tree=Try&rev=4a7127069321

Comment 55

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8480536 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v8.patch

So you're still leaking all the payloads.
Perhaps add a helper method which first goes through the array and deletes all the payloads and then calls mProfileTimelineMarkers.Clear();
and call that when you now just call mProfileTimelineMarkers.Clear();

Comment 56

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8480536 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v8.patch

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

::: layout/base/nsRefreshDriver.cpp
@@ +1329,5 @@
> +    nsTArray<nsDocShell*> profilingDocShells;
> +    GetProfileTimelineSubDocShells(GetDocShell(mPresContext), profilingDocShells);
> +    for (uint32_t i = 0; i < profilingDocShells.Length(); i ++) {
> +      profilingDocShells[i]->AddProfileTimelineMarker("Paint",
> +                                                      TRACING_INTERVAL_START);

You should use nsLayoutUtils::PaintFrame to measure painting.

We have a shortcut in nsPresShell::Paint (called from within ProcessPendingUpdates) that skips painting and just does a composite - the EndEmptyTransaction() path near the top.

Comment 57

[Matt Woodrow (:mattwoodrow)]

(In reply to Matt Woodrow (:mattwoodrow) from comment #56)
> You should use nsLayoutUtils::PaintFrame to measure painting.
> 
> We have a shortcut in nsPresShell::Paint (called from within
> ProcessPendingUpdates) that skips painting and just does a composite - the
> EndEmptyTransaction() path near the top.

You might even just want the FrameLayerBuilder::PaintItems functions (currently marked as "Layer") to be Paint, depending on what you want Paint to mean.

Changing a transform on an element (assuming we don't have async animations) will go through nsLayoutUtils::PaintFrame since we have to go through this path in order to update the transform matrix on the affected layers. We won't hit PaintItems() though since no actual content needs repainting.

Comment 58

[Benoit Girard (:BenWa)]

Right now the code is designed so that we include display list code under painting. We don't want to charge it against layout and I don't think we want a separate category for it for simplicity. I think it's reasonable to charge it to Painting since we're figuring out what to paint.

Comment 59

[Patrick Brosset <:pbro>]

(In reply to Benoit Girard (:BenWa) from comment #58)
> Right now the code is designed so that we include display list code under
> painting. We don't want to charge it against layout and I don't think we
> want a separate category for it for simplicity. I think it's reasonable to
> charge it to Painting since we're figuring out what to paint.
Am I understanding this correctly: leaving our START/END markers in nsRefreshDriver.cpp (around ProcessPendingUpdates) is somewhat wrong because this includes creating displaylists, but for the sake of simplicity of the devtools timeline tool, it makes sense?
If yes, then I completely agree. The timeline tool we aim at developing for the devtools should be really simple and have as few categories as possible. It is aimed at web developers and, as such, is very different from the gecko profiler which aims at showing as many categories and data as possible.

Comment 60

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v9.patch

Comment 61

[Olli Pettay [:smaug][[e-mail]]]

Comment on attachment 8483320 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v9.patch

>+nsDocShell::ClearProfileTimelineMarkers()
>+{
>+  for (uint32_t i = 0; i < mProfileTimelineMarkers.Length(); ++i) {
>+    delete mProfileTimelineMarkers[i]->mPayload;
And set mPayload to nullptr

>-  if (presContext->GetPaintFlashing() &&
>-      !aLayer->Manager()->IsInactiveLayerManager()) {
>+  bool isActiveLAyerManager = !aLayer->Manager()->IsInactiveLayerManager();
s/LA/La/


You may want to ask review from Matt, or feedback.

Comment 62

[Patrick Brosset <:pbro>]

Attachment: bug1050376-record-gecko-timeline-in-docshell v10.patch

Thanks for the final review Olli.
I've addressed the last review comments.

Matt: as advised by Olli, your feedback would be valuable on this patch.

Comment 63

[Patrick Brosset <:pbro>]

Try builds with the latest patch:
https://tbpl.mozilla.org/?tree=Try&rev=5a7b9e830c96
https://tbpl.mozilla.org/?tree=Try&rev=5b1b2284d9ac

Comment 64

[Matt Woodrow (:mattwoodrow)]

(In reply to Benoit Girard (:BenWa) from comment #58)
> Right now the code is designed so that we include display list code under
> painting. We don't want to charge it against layout and I don't think we
> want a separate category for it for simplicity. I think it's reasonable to
> charge it to Painting since we're figuring out what to paint.

I believe Paul Rouget is using these labels to compute the results for his css triggers web page. For that use-case, we'd want a transform change to *not* show up as painting otherwise our results won't be comparable to WebKit's.

It sounds like we have multiple, conflicting use-cases here, so we might need more than one way to get this data out. Adding ni?paul to clarify what exactly his requirements are here.

Comment 65

[Matt Woodrow (:mattwoodrow)]

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #62)
> Created attachment 8484068 [details] [diff] [review]
> bug1050376-record-gecko-timeline-in-docshell v10.patch
> 
> Thanks for the final review Olli.
> I've addressed the last review comments.
> 
> Matt: as advised by Olli, your feedback would be valuable on this patch.

Patch looks good code-wise, but leaving f? until we know if it's solving the problems we want it to.

Comment 66

[Paul Rouget [:paul]]

I really don't want to block this bug on the CSS-trigger thing.

But it would be nice to be able to have some granularity, to be able to do things like CSS-trigger. We can always simplify the results on the frontend side (merge paint and displayList in the UI).

I recommend that we land this now, and we file bugs to refine the markers, to eventually be able to have comparable results as webkit.

Comment 67

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v5.patch

Rebased

Comment 68

[Paul Rouget [:paul]]

Happy if we land this patch as it is?

Comment 69

[Matt Woodrow (:mattwoodrow)]

Comment on attachment 8484068 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v10.patch

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

Yep, if it does what you need, then it's fine with me!

Comment 70

[Patrick Brosset <:pbro>]

Landed on fx-team:
remote:   https://hg.mozilla.org/integration/fx-team/rev/48816257a7b0
remote:   https://hg.mozilla.org/integration/fx-team/rev/f3643ddd721f

Comment 71

[Carsten Book [:Tomcat]]

(In reply to Patrick Brosset [:pbrosset] [:patrick] from comment #70)
> Landed on fx-team:
> remote:   https://hg.mozilla.org/integration/fx-team/rev/48816257a7b0
> remote:   https://hg.mozilla.org/integration/fx-team/rev/f3643ddd721f

had to backout for bc2 test failures like https://tbpl.mozilla.org/php/getParsedLog.php?id=47664309&tree=Fx-Team

Comment 72

[Patrick Brosset <:pbro>]

These are e10s failures that aren't related to the meat of the patches, but rather to how the tests are run, which isn't e10s compatible apparently.

Comment 73

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v6.patch

Fixed minor test issues in the way that the new test tab was opened which failed in e10s.
Also disabled one of the 2 tests for e10s and filed bug 1064848 for it.

Comment 74

[Patrick Brosset <:pbro>]

Here's a new try build with all tests on linux: https://tbpl.mozilla.org/?tree=Try&rev=ea99049999aa (which is what failed in the previous fx-team push).

Comment 75

[Patrick Brosset <:pbro>]

The last try is all green, so the e10s test failures are gone.
The last change was only a minor test change, the platform patch hasn't changed, so no need for a full try build again.
Pushing this to fx-team again:
remote:   https://hg.mozilla.org/integration/fx-team/rev/72903248eeb9
remote:   https://hg.mozilla.org/integration/fx-team/rev/58156616368d

Comment 76

[Patrick Brosset <:pbro>]

Attachment: bug1050376-timeline-tests v7.patch

I actually had to rebase the test patch before landing.

Comment 77

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/72903248eeb9
https://hg.mozilla.org/mozilla-central/rev/58156616368d

Comment 78

[Andrei Vaida [:avaida]]

Setting qe-verify- since this patch is covered by automated testing. If there's something manual QA can look at here, please flip the flag.

Comment 79

[David Lawrence [:dkl]]

Sorry for the spam. Moving bugs to Firefox :: Developer Tools: Performance Tools (Profiler/Timeline).

dkl