Bug 820167: Enable performance measurement of tab animation. r=jmuizelaar

browser/base/content/tabbrowser.xml

@@ -1275,6 +1275,12 @@
                 if (t.pinned)
                   tabContainer._handleNewTab(t);
                 else {
+                  t._animationLoggingEnabled = tabContainer._cachedTabAnimationLoggingPref;
+                  if (t._animationLoggingEnabled) {
+                    window.QueryInterface(Components.interfaces.nsIInterfaceRequestor)
+                    .getInterface(Components.interfaces.nsIDOMWindowUtils)
+                    .startFrameTimeRecording();
+                  }
                   t._animStartTime = Date.now();
                   t.setAttribute("fadein", "true");
 
@@ -1575,6 +1581,12 @@
               return;
             }
 
+            aTab._animationLoggingEnabled = this.tabContainer._cachedTabAnimationLoggingPref;
+            if (aTab._animationLoggingEnabled) {
+              window.QueryInterface(Components.interfaces.nsIInterfaceRequestor)
+              .getInterface(Components.interfaces.nsIDOMWindowUtils)
+              .startFrameTimeRecording();
+            }
             aTab._animStartTime = Date.now();
 
             this._blurTab(aTab);
@@ -2878,6 +2890,12 @@
           Services.prefs.addObserver("browser.tabs.", this._prefObserver, false);
           window.addEventListener("resize", this, false);
           window.addEventListener("load", this, false);
+
+          try {
+            this._cachedTabAnimationLoggingPref = Services.prefs.getBoolPref("browser.tabs.animationLogging");
+          } catch (ex) {
+            this._cachedTabAnimationLoggingPref = false;
+          }
         ]]>
       </constructor>
 
@@ -3510,6 +3528,18 @@
                                               "FX_TAB_ANIM_OPEN_MS")
                             .add(Date.now() - tab._animStartTime);
           tab._animStartTime = 0;
+
+          if (tab._animationLoggingEnabled) {
+            let paints = {};
+            let intervals = window.QueryInterface(Components.interfaces.nsIInterfaceRequestor)
+                            .getInterface(Components.interfaces.nsIDOMWindowUtils)
+                            .stopFrameTimeRecording(paints);
+            let msg = "Tab " + (tab.closing ? "close" : "open") + " (Frame-interval / paint-processing):\n";
+            for (let i = 0; i < intervals.length; i++) {
+              msg += Math.round(intervals[i]) + " / " + Math.round(paints.value[i]) + "\n";
+            }
+            Services.console.logStringMessage(msg);
+          }
         }
 
         if (tab.getAttribute("fadein") == "true") {

dom/base/nsDOMWindowUtils.cpp

@@ -2157,14 +2157,15 @@ nsDOMWindowUtils::StartFrameTimeRecording()
 }
 
 NS_IMETHODIMP
-nsDOMWindowUtils::StopFrameTimeRecording(uint32_t *frameCount, float **frames)
+nsDOMWindowUtils::StopFrameTimeRecording(float** paintTimes, uint32_t *frameCount, float **frameIntervals)
 {
   if (!nsContentUtils::IsCallerChrome()) {
     return NS_ERROR_DOM_SECURITY_ERR;
   }
 
   NS_ENSURE_ARG_POINTER(frameCount);
-  NS_ENSURE_ARG_POINTER(frames);
+  NS_ENSURE_ARG_POINTER(frameIntervals);
+  NS_ENSURE_ARG_POINTER(paintTimes);
 
   nsCOMPtr<nsIWidget> widget = GetWidget();
   if (!widget)
@@ -2174,20 +2175,27 @@ nsDOMWindowUtils::StopFrameTimeRecording(uint32_t *frameCount, float **frames)
   if (!mgr)
     return NS_ERROR_FAILURE;
 
-  nsTArray<float> frameTimes;
-  mgr->StopFrameTimeRecording(frameTimes);
+  nsTArray<float> tmpFrameIntervals;
+  nsTArray<float> tmpPaintTimes;
+  mgr->StopFrameTimeRecording(tmpFrameIntervals, tmpPaintTimes);
 
-  *frames = nullptr;
-  *frameCount = frameTimes.Length();
+  *frameIntervals = nullptr;
+  *paintTimes = nullptr;
+  *frameCount = tmpFrameIntervals.Length();
 
   if (*frameCount != 0) {
-    *frames = (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
-    if (!*frames)
+    *frameIntervals = (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
+    if (!*frameIntervals)
       return NS_ERROR_OUT_OF_MEMORY;
 
-    /* copy over the frame times into the array we just allocated */
+    *paintTimes = (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
+    if (!*paintTimes)
+      return NS_ERROR_OUT_OF_MEMORY;
+
+    /* copy over the frame intervals and paint times into the arrays we just allocated */
     for (uint32_t i = 0; i < *frameCount; i++) {
-      (*frames)[i] = frameTimes[i];
+      (*frameIntervals)[i] = tmpFrameIntervals[i];
+      (*paintTimes)[i] = tmpPaintTimes[i];
     }
   }
 

dom/interfaces/base/nsIDOMWindowUtils.idl

@@ -40,7 +40,7 @@ interface nsIDOMTouch;
 interface nsIDOMClientRect;
 interface nsIURI;
 
-[scriptable, uuid(C98B7275-93C4-4EAD-B7CF-573D872C1071)]
+[scriptable, uuid(c98249a5-d38a-4ec6-b6e0-6866ea87d6bb)]
 interface nsIDOMWindowUtils : nsISupports {
 
   /**
@@ -1044,8 +1044,9 @@ interface nsIDOMWindowUtils : nsISupports {
   readonly attribute AString layerManagerType;
 
   void startFrameTimeRecording();
-  void stopFrameTimeRecording([optional] out unsigned long frameCount,
-                              [retval, array, size_is(frameCount)] out float frameTime);
+  void stopFrameTimeRecording([optional, array, size_is(frameCount)] out float paintTimes,
+                              [optional] out unsigned long frameCount,
+                              [retval, array, size_is(frameCount)] out float frameIntervals);
   /**
    * Signals that we're begining to tab switch. This is used by painting code to
    * determine total tab switch time.

gfx/layers/Layers.cpp

@@ -890,6 +890,15 @@ void
 LayerManager::StartFrameTimeRecording()
 {
   mLastFrameTime = TimeStamp::Now();
+  mPaintStartTime = mLastFrameTime;
+}
+
+void
+LayerManager::SetPaintStartTime(TimeStamp& aTime)
+{
+  if (!mLastFrameTime.IsNull()) {
+    mPaintStartTime = aTime;
+  }
 }
 
 void
@@ -897,7 +906,8 @@ LayerManager::PostPresent()
 {
   if (!mLastFrameTime.IsNull()) {
     TimeStamp now = TimeStamp::Now();
-    mFrameTimes.AppendElement((now - mLastFrameTime).ToMilliseconds());
+    mFrameIntervals.AppendElement((now - mLastFrameTime).ToMilliseconds());
+    mPaintTimes.AppendElement((now - mPaintStartTime).ToMilliseconds());
     mLastFrameTime = now;
   }
   if (!mTabSwitchStart.IsNull()) {
@@ -908,11 +918,13 @@ LayerManager::PostPresent()
 }
 
 void
-LayerManager::StopFrameTimeRecording(nsTArray<float>& aTimes)
+LayerManager::StopFrameTimeRecording(nsTArray<float>& aFrameIntervals, nsTArray<float>& aPaintTimes)
 {
   mLastFrameTime = TimeStamp();
-  aTimes.SwapElements(mFrameTimes);
-  mFrameTimes.Clear();
+  aFrameIntervals.SwapElements(mFrameIntervals);
+  aPaintTimes.SwapElements(mPaintTimes);
+  mFrameIntervals.Clear();
+  mPaintTimes.Clear();
 }
 
 void

gfx/layers/Layers.h

@@ -484,7 +484,8 @@ public:
   void LogSelf(const char* aPrefix="");
 
   void StartFrameTimeRecording();
-  void StopFrameTimeRecording(nsTArray<float>& aTimes);
+  void SetPaintStartTime(TimeStamp& aTime);
+  void StopFrameTimeRecording(nsTArray<float>& aFrameTimes, nsTArray<float>& aProcessingTimes);
 
   void PostPresent();
 
@@ -516,7 +517,9 @@ protected:
   bool mInTransaction;
 private:
   TimeStamp mLastFrameTime;
-  nsTArray<float> mFrameTimes;
+  TimeStamp mPaintStartTime;
+  nsTArray<float> mFrameIntervals;
+  nsTArray<float> mPaintTimes;
   TimeStamp mTabSwitchStart;
 };
 

layout/base/nsRefreshDriver.cpp

@@ -927,6 +927,11 @@ nsRefreshDriver::Tick(int64_t aNowEpoch, TimeStamp aNowTime)
 #ifdef DEBUG_INVALIDATIONS
     printf("Starting ProcessPendingUpdates\n");
 #endif
+    layers::LayerManager *mgr = mPresContext->GetPresShell()->GetLayerManager();
+    if (mgr) {
+      mgr->SetPaintStartTime(mMostRecentRefresh);
+    }
+
     mViewManagerFlushIsPending = false;
     nsCOMPtr<nsIViewManager> vm = mPresContext->GetPresShell()->GetViewManager();
     vm->ProcessPendingUpdates();