[timeline] gather gecko operations markers under a docshell vector

RESOLVED FIXED in Firefox 35

Status

DevTools
Performance Tools (Profiler/Timeline)
RESOLVED FIXED
4 years ago
11 days ago

People

(Reporter: paul, Assigned: pbro)

Tracking

Trunk
Firefox 35
Dependency tree / graph
Bug Flags:
in-testsuite +
qe-verify -

Firefox Tracking Flags

(firefox35 fixed)

Details

Attachments

(2 attachments, 25 obsolete attachments)

24.29 KB, patch
pbro
: review+
mattwoodrow
: feedback+
Details | Diff | Splinter Review
6.80 KB, patch
pbro
: review+
Details | Diff | Splinter Review
Comment hidden (empty)
(Reporter)

Updated

4 years ago
Blocks: 1050372
(Reporter)

Comment 1

4 years ago
Created attachment 8469394 [details] [diff] [review]
v0.0001
(Reporter)

Comment 2

4 years ago
First, we want to track:
- restyle
- reflow
- paint
(Reporter)

Updated

4 years ago
Depends on: 1050335
(Reporter)

Updated

4 years ago
Duplicate of this bug: 1050335
(Assignee)

Updated

4 years ago
Assignee: nobody → pbrosset
(Assignee)

Updated

4 years ago
Blocks: 1050770
(Assignee)

Updated

4 years ago
No longer blocks: 1050770
(Assignee)

Comment 4

4 years ago
Created attachment 8470031 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell WIP.patch
Attachment #8469394 - Attachment is obsolete: true
(Assignee)

Comment 5

4 years ago
Created attachment 8470045 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell WIP.patch

This one compiles!
Attachment #8470031 - Attachment is obsolete: true
(Reporter)

Updated

4 years ago
Blocks: 1050791
(Assignee)

Comment 6

4 years ago
Created attachment 8470098 [details] [diff] [review]
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.
Attachment #8470045 - Attachment is obsolete: true
(Reporter)

Comment 7

4 years ago
Created attachment 8470789 [details] [diff] [review]
tests

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

Comment 8

4 years ago
Created attachment 8470798 [details] [diff] [review]
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.
Attachment #8470098 - Attachment is obsolete: true
Attachment #8470798 - Flags: feedback?(paul)
(Assignee)

Comment 9

4 years ago
Created attachment 8470800 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v1.1.patch

Forgot to remove an obsolete comment.
Attachment #8470798 - Attachment is obsolete: true
Attachment #8470798 - Flags: feedback?(paul)
Attachment #8470800 - Flags: feedback?(paul)
(Assignee)

Comment 10

4 years ago
Created attachment 8470805 [details] [diff] [review]
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.
Attachment #8470800 - Attachment is obsolete: true
Attachment #8470800 - Flags: feedback?(paul)
Attachment #8470805 - Flags: feedback?(paul)
(Reporter)

Comment 11

4 years ago
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.
Attachment #8470805 - Flags: feedback?(paul) → feedback+
(Assignee)

Comment 12

4 years ago
Created attachment 8471403 [details] [diff] [review]
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).
Attachment #8470805 - Attachment is obsolete: true
Attachment #8471403 - Flags: review?(ehsan)
Flags: needinfo?(ehsan)
(Assignee)

Comment 13

4 years ago
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 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.
Attachment #8471403 - Flags: review?(ehsan) → review?(bugs)
Flags: needinfo?(ehsan)
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...)
(Assignee)

Comment 16

4 years ago
(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.
(Assignee)

Updated

4 years ago
Status: NEW → ASSIGNED
Hardware: x86_64 → All
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?
(Assignee)

Comment 18

4 years ago
(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 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
Attachment #8471403 - Flags: review?(bugs) → review-
(Reporter)

Updated

4 years ago
Component: Developer Tools → Developer Tools: Timeline
(Assignee)

Comment 20

4 years ago
(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.
Flags: needinfo?(bgirard)
(Assignee)

Comment 21

4 years ago
Created attachment 8472945 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v3.patch

Here's a v2 that addresses review comments.
Please see my comments/questions in comment 20.
Attachment #8471403 - Attachment is obsolete: true
Attachment #8472945 - Flags: review?(bugs)
(Assignee)

Comment 22

4 years ago
Created attachment 8472948 [details] [diff] [review]
bug1050376-timeline-tests v1.patch
Attachment #8470789 - Attachment is obsolete: true
(Assignee)

Comment 23

4 years ago
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...
(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.
Flags: needinfo?(bgirard)
(Assignee)

Comment 25

4 years ago
(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.
(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 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?
Attachment #8472945 - Flags: review?(bugs) → review-
(Assignee)

Comment 28

4 years ago
Created attachment 8474587 [details] [diff] [review]
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.
Attachment #8472945 - Attachment is obsolete: true
Attachment #8474587 - Flags: review?(bugs)
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.
Attachment #8474587 - Flags: review?(bugs) → review-
(Assignee)

Comment 30

4 years ago
(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 :)
(Assignee)

Comment 31

4 years ago
Created attachment 8475123 [details] [diff] [review]
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.
Attachment #8474587 - Attachment is obsolete: true
Attachment #8475123 - Flags: review?(bugs)
(Assignee)

Comment 32

4 years ago
Created attachment 8475124 [details] [diff] [review]
bug1050376-timeline-tests v2.patch

Updated the test patch with the new names.
Attachment #8472948 - Attachment is obsolete: true
Attachment #8475124 - Flags: review?(bugs)
(Assignee)

Comment 33

4 years ago
Created attachment 8475127 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v5.1.patch

Fixing a typo in a comment
Attachment #8475123 - Attachment is obsolete: true
Attachment #8475123 - Flags: review?(bugs)
Attachment #8475127 - Flags: review?(bugs)
(Assignee)

Comment 34

4 years ago
Created attachment 8476608 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v5.2.patch

Forgot to decrement the record counter in the destructor.
Attachment #8475127 - Attachment is obsolete: true
Attachment #8475127 - Flags: review?(bugs)
Attachment #8476608 - Flags: review?(bugs)
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.
Attachment #8475124 - Flags: review?(bugs) → review-
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
Attachment #8476608 - Flags: review?(bugs) → review-
(Assignee)

Comment 37

4 years ago
(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.
Flags: needinfo?(bugs)
(Assignee)

Comment 38

4 years ago
Created attachment 8478969 [details] [diff] [review]
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
(Assignee)

Comment 39

4 years ago
Created attachment 8478980 [details] [diff] [review]
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.
Attachment #8475124 - Attachment is obsolete: true
Attachment #8478980 - Flags: review?(bugs)
(Assignee)

Comment 40

4 years ago
Created attachment 8479079 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v6.patch
Attachment #8476608 - Attachment is obsolete: true
(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.
Flags: needinfo?(bugs)
(Assignee)

Comment 42

4 years ago
Created attachment 8479713 [details] [diff] [review]
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!
Attachment #8478969 - Attachment is obsolete: true
Attachment #8479079 - Attachment is obsolete: true
Attachment #8479713 - Flags: review?(bugs)
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.
Attachment #8478980 - Flags: review?(bugs) → review+
(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 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.
Attachment #8479713 - Flags: review?(bugs) → review+
(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.
oh, right, we don't want payload to be nsAutoPtr<ProfilerMarkerTracing>, but 
ProfilerMarkerTracing should be fine
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 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.
Attachment #8479713 - Flags: review+ → review-
And thank BenWa!
(Assignee)

Comment 51

4 years ago
Created attachment 8480498 [details] [diff] [review]
bug1050376-timeline-tests v4.patch

Thanks for the review. Removed the extra generator * symbol next to waitForMarkers.
Attachment #8478980 - Attachment is obsolete: true
Attachment #8480498 - Flags: review+
(Assignee)

Comment 52

4 years ago
Created attachment 8480536 [details] [diff] [review]
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.
Attachment #8479713 - Attachment is obsolete: true
Attachment #8480536 - Flags: review?(bugs)
(Assignee)

Comment 54

4 years ago
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 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();
Attachment #8480536 - Flags: review?(bugs) → review-
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.
(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.
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.
(Assignee)

Comment 59

4 years ago
(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.
(Assignee)

Comment 60

4 years ago
Created attachment 8483320 [details] [diff] [review]
bug1050376-record-gecko-timeline-in-docshell v9.patch
Attachment #8480536 - Attachment is obsolete: true
Attachment #8483320 - Flags: review?(bugs)
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.
Attachment #8483320 - Flags: review?(bugs) → review+
(Assignee)

Comment 62

4 years ago
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.
Attachment #8483320 - Attachment is obsolete: true
Attachment #8484068 - Flags: review+
Attachment #8484068 - Flags: feedback?(matt.woodrow)
(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.
Flags: needinfo?(paul)
(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.
(Reporter)

Comment 66

4 years ago
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.
Flags: needinfo?(paul)
(Assignee)

Comment 67

4 years ago
Created attachment 8485755 [details] [diff] [review]
bug1050376-timeline-tests v5.patch

Rebased
Attachment #8480498 - Attachment is obsolete: true
Attachment #8485755 - Flags: review+
(Reporter)

Comment 68

4 years ago
Happy if we land this patch as it is?
Flags: needinfo?(matt.woodrow)
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!
Attachment #8484068 - Flags: feedback?(matt.woodrow) → feedback+
(Reporter)

Updated

4 years ago
Flags: needinfo?(matt.woodrow)
(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
(Assignee)

Comment 72

4 years ago
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.
(Assignee)

Comment 73

4 years ago
Created attachment 8486393 [details] [diff] [review]
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.
Attachment #8485755 - Attachment is obsolete: true
Attachment #8486393 - Flags: review+
(Assignee)

Comment 74

4 years ago
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).
(Reporter)

Updated

4 years ago
Blocks: 1050384
(Assignee)

Comment 75

4 years ago
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
(Assignee)

Comment 76

4 years ago
Created attachment 8486606 [details] [diff] [review]
bug1050376-timeline-tests v7.patch

I actually had to rebase the test patch before landing.
Attachment #8486393 - Attachment is obsolete: true
Attachment #8486606 - Flags: review+
https://hg.mozilla.org/mozilla-central/rev/72903248eeb9
https://hg.mozilla.org/mozilla-central/rev/58156616368d
Status: ASSIGNED → RESOLVED
Last Resolved: 4 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → Firefox 35

Updated

4 years ago
Depends on: 1065251
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.
status-firefox35: --- → fixed
Flags: qe-verify-
Sorry for the spam. Moving bugs to Firefox :: Developer Tools: Performance Tools (Profiler/Timeline).

dkl
Component: Developer Tools: Timeline → Developer Tools: Performance Tools (Profiler/Timeline)

Updated

11 days ago
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.