Bug 1050376 - Record restyle/reflow/paint devtools timeline markers at docshell level; r=smaug

docshell/base/moz.build

@@ -83,6 +83,7 @@ LOCAL_INCLUDES += [
     '/layout/generic',
     '/layout/xul',
     '/netwerk/protocol/viewsource',
+    '/tools/profiler',
 ]
 
 if CONFIG['MOZ_TOOLKIT_SEARCH']:

docshell/base/nsDocShell.cpp

@@ -15,6 +15,8 @@
 #include "mozilla/dom/ContentChild.h"
 #include "mozilla/dom/Element.h"
 #include "mozilla/dom/TabChild.h"
+#include "mozilla/dom/ProfileTimelineMarkerBinding.h"
+#include "mozilla/dom/ToJSValue.h"
 #include "mozilla/EventStateManager.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/Services.h"
@@ -88,6 +90,8 @@
 #include "nsDocShellEnumerator.h"
 #include "nsSHistory.h"
 #include "nsDocShellEditorData.h"
+#include "GeckoProfiler.h"
+#include "ProfilerMarkers.h"
 
 // Helper Classes
 #include "nsError.h"
@@ -2791,6 +2795,138 @@ nsDocShell::HistoryTransactionRemoved(int32_t aIndex)
     return NS_OK;
 }
 
+unsigned long nsDocShell::gProfileTimelineRecordingsCount = 0;
+
+NS_IMETHODIMP
+nsDocShell::SetRecordProfileTimelineMarkers(bool aValue)
+{
+  bool currentValue;
+  GetRecordProfileTimelineMarkers(&currentValue);
+  if (currentValue != aValue) {
+    if (aValue) {
+      ++gProfileTimelineRecordingsCount;
+      mProfileTimelineStartTime = TimeStamp::Now();
+    } else {
+      --gProfileTimelineRecordingsCount;
+      mProfileTimelineStartTime = TimeStamp();
+      ClearProfileTimelineMarkers();
+    }
+  }
+
+  return NS_OK;
+}
+
+NS_IMETHODIMP
+nsDocShell::GetRecordProfileTimelineMarkers(bool* aValue)
+{
+  *aValue = !mProfileTimelineStartTime.IsNull();
+  return NS_OK;
+}
+
+nsresult
+nsDocShell::PopProfileTimelineMarkers(JSContext* aCx,
+                          JS::MutableHandle<JS::Value> aProfileTimelineMarkers)
+{
+  // 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 Layer marker type was recorded too.
+
+  nsTArray<mozilla::dom::ProfileTimelineMarker> profileTimelineMarkers;
+
+  for (uint32_t i = 0; i < mProfileTimelineMarkers.Length(); ++i) {
+    ProfilerMarkerTracing* startPayload = static_cast<ProfilerMarkerTracing*>(
+      mProfileTimelineMarkers[i]->mPayload);
+    const char* startMarkerName = mProfileTimelineMarkers[i]->mName;
+
+    bool hasSeenPaintedLayer = 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 < mProfileTimelineMarkers.Length(); ++j) {
+        ProfilerMarkerTracing* endPayload = static_cast<ProfilerMarkerTracing*>(
+          mProfileTimelineMarkers[j]->mPayload);
+        const char* endMarkerName = mProfileTimelineMarkers[j]->mName;
+
+        // Look for Layer markers to stream out paint markers
+        if (strcmp(endMarkerName, "Layer") == 0) {
+          hasSeenPaintedLayer = true;
+        }
+
+        bool isSameMarkerType = strcmp(startMarkerName, endMarkerName) == 0;
+        bool isValidType = strcmp(endMarkerName, "Paint") != 0 ||
+                           hasSeenPaintedLayer;
+
+        if (endPayload->GetMetaData() == TRACING_INTERVAL_END &&
+            isSameMarkerType && isValidType) {
+          mozilla::dom::ProfileTimelineMarker marker;
+          marker.mName = NS_ConvertUTF8toUTF16(startMarkerName);
+          marker.mStart = mProfileTimelineMarkers[i]->mTime;
+          marker.mEnd = mProfileTimelineMarkers[j]->mTime;
+          profileTimelineMarkers.AppendElement(marker);
+
+          break;
+        }
+      }
+    }
+  }
+
+  ToJSValue(aCx, profileTimelineMarkers, aProfileTimelineMarkers);
+
+  ClearProfileTimelineMarkers();
+
+  return NS_OK;
+}
+
+float
+nsDocShell::GetProfileTimelineDelta()
+{
+  return (TimeStamp::Now() - mProfileTimelineStartTime).ToMilliseconds();
+}
+
+void
+nsDocShell::AddProfileTimelineMarker(const char* aName,
+                                     TracingMetadata aMetaData)
+{
+  if (!mProfileTimelineStartTime.IsNull()) {
+    float delta = GetProfileTimelineDelta();
+    ProfilerMarkerTracing* payload = new ProfilerMarkerTracing("Timeline",
+                                                               aMetaData);
+    mProfileTimelineMarkers.AppendElement(
+      new InternalProfileTimelineMarker(aName, payload, delta));
+  }
+}
+
+void
+nsDocShell::AddProfileTimelineMarker(const char* aName,
+                                     ProfilerBacktrace* aCause,
+                                     TracingMetadata aMetaData)
+{
+  if (!mProfileTimelineStartTime.IsNull()) {
+    float delta = GetProfileTimelineDelta();
+    ProfilerMarkerTracing* payload = new ProfilerMarkerTracing("Timeline",
+                                                               aMetaData,
+                                                               aCause);
+    mProfileTimelineMarkers.AppendElement(
+      new InternalProfileTimelineMarker(aName, payload, delta));
+  }
+}
+
+void
+nsDocShell::ClearProfileTimelineMarkers()
+{
+  for (uint32_t i = 0; i < mProfileTimelineMarkers.Length(); ++i) {
+    delete mProfileTimelineMarkers[i]->mPayload;
+    mProfileTimelineMarkers[i]->mPayload = nullptr;
+  }
+  mProfileTimelineMarkers.Clear();
+}
+
 nsIDOMStorageManager*
 nsDocShell::TopSessionStorageManager()
 {
@@ -5360,6 +5496,9 @@ nsDocShell::Destroy()
     
     mIsBeingDestroyed = true;
 
+    // Make sure we don't record profile timeline markers anymore
+    SetRecordProfileTimelineMarkers(false);
+
     // Remove our pref observers
     if (mObserveErrorPages) {
         mObserveErrorPages = false;

docshell/base/nsDocShell.h

@@ -18,6 +18,8 @@
 #include "nsIDOMStorageManager.h"
 #include "nsDocLoader.h"
 #include "mozilla/WeakPtr.h"
+#include "mozilla/TimeStamp.h"
+#include "GeckoProfiler.h"
 
 // Helper Classes
 #include "nsCOMPtr.h"
@@ -79,6 +81,7 @@ class nsIURIFixup;
 class nsIURILoader;
 class nsIWebBrowserFind;
 class nsIWidget;
+class ProfilerMarkerTracing;
 
 /* load commands were moved to nsIDocShell.h */
 /* load types were moved to nsDocShellLoadTypes.h */
@@ -250,6 +253,19 @@ public:
     // Notify Scroll observers when an async panning/zooming transform
     // is no longer applied
     void NotifyAsyncPanZoomStopped();
+
+    // 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* aName,
+                                  TracingMetadata aMetaData);
+    void AddProfileTimelineMarker(const char* aName,
+                                  ProfilerBacktrace* aCause,
+                                  TracingMetadata aMetaData);
+
+    // Global counter for how many docShells are currently recording profile
+    // timeline markers
+    static unsigned long gProfileTimelineRecordingsCount;
 protected:
     // Object Management
     virtual ~nsDocShell();
@@ -925,6 +941,30 @@ private:
     nsWeakPtr mOpener;
     nsWeakPtr mOpenedRemote;
 
+    // Storing profile timeline markers and if/when recording started
+    mozilla::TimeStamp mProfileTimelineStartTime;
+    struct InternalProfileTimelineMarker
+    {
+      InternalProfileTimelineMarker(const char* aName,
+                                    ProfilerMarkerTracing* aPayload,
+                                    float aTime)
+        : mName(aName)
+        , mPayload(aPayload)
+        , mTime(aTime)
+      {}
+      const char* mName;
+      ProfilerMarkerTracing* mPayload;
+      float mTime;
+    };
+    nsTArray<nsAutoPtr<InternalProfileTimelineMarker>> mProfileTimelineMarkers;
+
+    // Get the elapsed time (in millis) since the profile timeline recording
+    // started
+    float GetProfileTimelineDelta();
+
+    // Get rid of all the timeline markers accumulated so far
+    void ClearProfileTimelineMarkers();
+
     // Separate function to do the actual name (i.e. not _top, _self etc.)
     // searching for FindItemWithName.
     nsresult DoFindItemWithName(const char16_t* aName,

docshell/base/nsIDocShell.idl

@@ -54,7 +54,7 @@ interface nsITabParent;
  
 typedef unsigned long nsLoadFlags;
 
-[scriptable, builtinclass, uuid(3646c915-df79-4500-8b57-c65ab9c3b39f)]
+[scriptable, builtinclass, uuid(2b8e4a50-7744-454d-a05b-debead8070fe)]
 interface nsIDocShell : nsIDocShellTreeItem
 {
   /**
@@ -667,6 +667,17 @@ interface nsIDocShell : nsIDocShellTreeItem
     out int32_t parentCharsetSource,
     out nsIPrincipal parentCharsetPrincipal);
 
+  /**
+   * Whether the docShell records profile timeline markers at the moment
+   */
+  [infallible] attribute boolean recordProfileTimelineMarkers;
+
+  /**
+   * Returns and flushes the profile timeline markers gathered by the docShell
+   */
+  [implicit_jscontext]
+  jsval popProfileTimelineMarkers();
+
   /**
    * Add an observer to the list of parties to be notified when this docshell's
    * private browsing status is changed. |obs| must support weak references.

dom/webidl/ProfileTimelineMarker.webidl

@@ -0,0 +1,11 @@
+/* -*- Mode: IDL; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this file,
+ * You can obtain one at http://mozilla.org/MPL/2.0/.
+ */
+
+dictionary ProfileTimelineMarker {
+  DOMString name = "";
+  DOMTimeStamp start = 0;
+  DOMTimeStamp end = 0;
+};

dom/webidl/moz.build

@@ -309,6 +309,7 @@ WEBIDL_FILES = [
     'Position.webidl',
     'PositionError.webidl',
     'ProcessingInstruction.webidl',
+    'ProfileTimelineMarker.webidl',
     'Promise.webidl',
     'PromiseDebugging.webidl',
     'PushManager.webidl',

layout/base/FrameLayerBuilder.cpp

@@ -24,6 +24,7 @@
 #include "ActiveLayerTracker.h"
 #include "gfx2DGlue.h"
 #include "mozilla/LookAndFeel.h"
+#include "nsDocShell.h"
 
 #include "GeckoProfiler.h"
 #include "mozilla/gfx/Tools.h"
@@ -4504,8 +4505,9 @@ FrameLayerBuilder::DrawThebesLayer(ThebesLayer* aLayer,
                              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) {
@@ -4517,6 +4519,11 @@ FrameLayerBuilder::DrawThebesLayer(ThebesLayer* aLayer,
     FlashPaint(aContext);
   }
 
+  if (presContext && presContext->GetDocShell() && isActiveLayerManager) {
+    nsDocShell* docShell = static_cast<nsDocShell*>(presContext->GetDocShell());
+    docShell->AddProfileTimelineMarker("Layer", TRACING_EVENT);
+  }
+
   if (!aRegionToInvalidate.IsEmpty()) {
     aLayer->AddInvalidRect(aRegionToInvalidate.GetBounds());
   }

layout/base/nsPresShell.cpp

@@ -8743,6 +8743,11 @@ PresShell::DoReflow(nsIFrame* target, bool aInterruptible)
   PROFILER_LABEL_PRINTF("PresShell", "DoReflow",
     js::ProfileEntry::Category::GRAPHICS, "(%s)", docURL.get());
 
+  nsDocShell* docShell = static_cast<nsDocShell*>(GetPresContext()->GetDocShell());
+  if (docShell) {
+    docShell->AddProfileTimelineMarker("Reflow", TRACING_INTERVAL_START);
+  }
+
   if (mReflowContinueTimer) {
     mReflowContinueTimer->Cancel();
     mReflowContinueTimer = nullptr;
@@ -8906,6 +8911,9 @@ PresShell::DoReflow(nsIFrame* target, bool aInterruptible)
   }
 #endif
 
+  if (docShell) {
+    docShell->AddProfileTimelineMarker("Reflow", TRACING_INTERVAL_END);
+  }
   return !interrupted;
 }
 

layout/base/nsRefreshDriver.cpp

@@ -48,6 +48,8 @@
 #include "imgIContainer.h"
 #include "nsIFrameRequestCallback.h"
 #include "mozilla/dom/ScriptSettings.h"
+#include "nsDocShell.h"
+#include "nsISimpleEnumerator.h"
 
 using namespace mozilla;
 using namespace mozilla::widget;
@@ -1045,6 +1047,52 @@ struct DocumentFrameCallbacks {
   nsIDocument::FrameRequestCallbackList mCallbacks;
 };
 
+static nsDocShell* GetDocShell(nsPresContext* aPresContext)
+{
+  return static_cast<nsDocShell*>(aPresContext->GetDocShell());
+}
+
+/**
+ * Return a list of all the child docShells in a given root docShell that are
+ * visible and are recording markers for the profilingTimeline
+ */
+static void GetProfileTimelineSubDocShells(nsDocShell* aRootDocShell,
+                                           nsTArray<nsDocShell*>& aShells)
+{
+  if (!aRootDocShell || nsDocShell::gProfileTimelineRecordingsCount == 0) {
+    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;
+    enumerator->GetNext(getter_AddRefs(curSupports));
+    curItem = do_QueryInterface(curSupports);
+
+    if (!curItem || !curItem->GetRecordProfileTimelineMarkers()) {
+      continue;
+    }
+
+    nsDocShell* shell = static_cast<nsDocShell*>(curItem.get());
+    bool isVisible = false;
+    shell->GetVisibility(&isVisible);
+    if (!isVisible) {
+      continue;
+    }
+
+    aShells.AppendElement(shell);
+  };
+}
+
 void
 nsRefreshDriver::Tick(int64_t aNowEpoch, TimeStamp aNowTime)
 {
@@ -1178,6 +1226,12 @@ nsRefreshDriver::Tick(int64_t aNowEpoch, TimeStamp aNowTime)
           if (!mStyleFlushObservers.Contains(shell))
             continue;
 
+          nsRefPtr<nsDocShell> docShell = GetDocShell(shell->GetPresContext());
+          if (docShell) {
+            docShell->AddProfileTimelineMarker("Styles", mStyleCause,
+                                               TRACING_INTERVAL_START);
+          }
+
           if (!tracingStyleFlush) {
             tracingStyleFlush = true;
             profiler_tracing("Paint", "Styles", mStyleCause, TRACING_INTERVAL_START);
@@ -1189,6 +1243,10 @@ nsRefreshDriver::Tick(int64_t aNowEpoch, TimeStamp aNowTime)
           shell->GetPresContext()->RestyleManager()->mObservingRefreshDriver = false;
           shell->FlushPendingNotifications(ChangesToFlush(Flush_Style, false));
           NS_RELEASE(shell);
+
+          if (docShell) {
+            docShell->AddProfileTimelineMarker("Styles", TRACING_INTERVAL_END);
+          }
         }
 
         if (tracingStyleFlush) {
@@ -1264,6 +1322,14 @@ nsRefreshDriver::Tick(int64_t aNowEpoch, TimeStamp aNowTime)
   mPresShellsToInvalidateIfHidden.Clear();
 
   if (mViewManagerFlushIsPending) {
+    nsTArray<nsDocShell*> profilingDocShells;
+    GetProfileTimelineSubDocShells(GetDocShell(mPresContext), profilingDocShells);
+    for (uint32_t i = 0; i < profilingDocShells.Length(); i ++) {
+      // For the sake of the profile timeline's simplicity, this is flagged as
+      // paint even if it includes creating display lists
+      profilingDocShells[i]->AddProfileTimelineMarker("Paint",
+                                                      TRACING_INTERVAL_START);
+    }
     profiler_tracing("Paint", "DisplayList", TRACING_INTERVAL_START);
 #ifdef MOZ_DUMP_PAINTING
     if (nsLayoutUtils::InvalidationDebuggingIsEnabled()) {
@@ -1279,6 +1345,10 @@ nsRefreshDriver::Tick(int64_t aNowEpoch, TimeStamp aNowTime)
       printf_stderr("Ending ProcessPendingUpdates\n");
     }
 #endif
+    for (uint32_t i = 0; i < profilingDocShells.Length(); i ++) {
+      profilingDocShells[i]->AddProfileTimelineMarker("Paint",
+                                                      TRACING_INTERVAL_END);
+    }
     profiler_tracing("Paint", "DisplayList", TRACING_INTERVAL_END);
   }
 

tools/profiler/moz.build

@@ -80,6 +80,7 @@ if CONFIG['MOZ_ENABLE_PROFILER_SPS']:
         ]
 
     LOCAL_INCLUDES += [
+        '/docshell/base',
         '/ipc/chromium/src',
         '/mozglue/linker',
         '/toolkit/crashreporter/google-breakpad/src',