Bug 820167: Enable performance measurement of tab animation. r=jmuizelaar,dao
☠☠ backed out by cc6f68c9a929 ☠ ☠
authorAvi Halachmi <ahalachmi@mozilla.com>
Tue, 18 Dec 2012 09:31:01 -0500
changeset 125503 9864a836aa3565989a79b7af8990c0d13d830dd2
parent 125502 59f60da956f252d41c26fa8775d0b287ec98dc7a
child 125504 b6036a834a577e3a396b2c52260b1c9a5f1b396f
push id2151
push userlsblakk@mozilla.com
push dateTue, 19 Feb 2013 18:06:57 +0000
treeherdermozilla-beta@4952e88741ec [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersjmuizelaar, dao
bugs820167
milestone20.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 820167: Enable performance measurement of tab animation. r=jmuizelaar,dao
browser/base/content/tabbrowser.xml
dom/base/nsDOMWindowUtils.cpp
dom/interfaces/base/nsIDOMWindowUtils.idl
gfx/layers/Layers.cpp
gfx/layers/Layers.h
layout/base/nsRefreshDriver.cpp
--- a/browser/base/content/tabbrowser.xml
+++ b/browser/base/content/tabbrowser.xml
@@ -1270,16 +1270,22 @@
               setTimeout(function (tabContainer) {
                 tabContainer._handleNewTab(t);
               }, 0, this.tabContainer);
             } else {
               setTimeout(function (tabContainer) {
                 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");
 
                   // This call to adjustTabstrip is redundant but needed so that
                   // when opening a second tab, the first tab's close buttons
                   // appears immediately rather than when the transition ends.
                   if (tabContainer.childNodes.length == 2)
                     tabContainer.adjustTabstrip();
@@ -1570,16 +1576,22 @@
                 this._removingTabs.length > 3 /* don't want lots of concurrent animations */ ||
                 aTab.getAttribute("fadein") != "true" /* fade-in transition hasn't been triggered yet */ ||
                 window.getComputedStyle(aTab).maxWidth == "0.1px" /* fade-in transition hasn't moved yet */ ||
                 !Services.prefs.getBoolPref("browser.tabs.animate")) {
               this._endRemoveTab(aTab);
               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);
             aTab.style.maxWidth = ""; // ensure that fade-out transition happens
             aTab.removeAttribute("fadein");
 
             setTimeout(function (tab, tabbrowser) {
               if (tab.parentNode &&
@@ -2873,16 +2885,22 @@
           tab.setAttribute("crop", "end");
           tab.setAttribute("validate", "never");
           tab.setAttribute("onerror", "this.removeAttribute('image');");
           this.adjustTabstrip();
 
           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>
 
       <destructor>
         <![CDATA[
           Services.prefs.removeObserver("browser.tabs.", this._prefObserver);
         ]]>
       </destructor>
@@ -3505,16 +3523,28 @@
         var tab = event.target;
 
         if (tab._animStartTime) {
           Services.telemetry.getHistogramById(tab.closing ?
                                               "FX_TAB_ANIM_CLOSE_MS" :
                                               "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") {
           if (tab._fullyOpen)
             this.adjustTabstrip();
           else
             this._handleNewTab(tab);
         } else if (tab.closing) {
--- a/dom/base/nsDOMWindowUtils.cpp
+++ b/dom/base/nsDOMWindowUtils.cpp
@@ -2152,47 +2152,55 @@ nsDOMWindowUtils::StartFrameTimeRecordin
     return NS_ERROR_FAILURE;
 
   mgr->StartFrameTimeRecording();
 
   return NS_OK;
 }
 
 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)
     return NS_ERROR_FAILURE;
 
   LayerManager *mgr = widget->GetLayerManager();
   if (!mgr)
     return NS_ERROR_FAILURE;
 
-  nsTArray<float> frameTimes;
-  mgr->StopFrameTimeRecording(frameTimes);
-
-  *frames = nullptr;
-  *frameCount = frameTimes.Length();
+  nsTArray<float> tmpFrameIntervals;
+  nsTArray<float> tmpPaintTimes;
+  mgr->StopFrameTimeRecording(tmpFrameIntervals, tmpPaintTimes);
+
+  *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];
     }
   }
 
   return NS_OK;
 }
 
 NS_IMETHODIMP
 nsDOMWindowUtils::BeginTabSwitch()
--- a/dom/interfaces/base/nsIDOMWindowUtils.idl
+++ b/dom/interfaces/base/nsIDOMWindowUtils.idl
@@ -35,17 +35,17 @@ interface nsIQueryContentEventResult;
 interface nsIDOMWindow;
 interface nsIDOMBlob;
 interface nsIDOMFile;
 interface nsIFile;
 interface nsIDOMTouch;
 interface nsIDOMClientRect;
 interface nsIURI;
 
-[scriptable, uuid(C98B7275-93C4-4EAD-B7CF-573D872C1071)]
+[scriptable, uuid(c98249a5-d38a-4ec6-b6e0-6866ea87d6bb)]
 interface nsIDOMWindowUtils : nsISupports {
 
   /**
    * Image animation mode of the window. When this attribute's value
    * is changed, the implementation should set all images in the window
    * to the given value. That is, when set to kDontAnimMode, all images
    * will stop animating. The attribute's value must be one of the
    * animationMode values from imgIContainer.
@@ -1039,18 +1039,19 @@ interface nsIDOMWindowUtils : nsISupport
   /**
    * What type of layer manager the widget associated with this window is
    * using. "Basic" is unaccelerated; other types are accelerated. Throws an
    * error if there is no widget associated with this window.
    */
   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.
    */
   void beginTabSwitch();
 
   /**
    * The DPI of the display
--- a/gfx/layers/Layers.cpp
+++ b/gfx/layers/Layers.cpp
@@ -885,39 +885,51 @@ RefLayer::FillSpecificAttributes(Specifi
 {
   aAttrs = RefLayerAttributes(GetReferentId());
 }
 
 void
 LayerManager::StartFrameTimeRecording()
 {
   mLastFrameTime = TimeStamp::Now();
+  mPaintStartTime = mLastFrameTime;
+}
+
+void
+LayerManager::SetPaintStartTime(TimeStamp& aTime)
+{
+  if (!mLastFrameTime.IsNull()) {
+    mPaintStartTime = aTime;
+  }
 }
 
 void
 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()) {
     Telemetry::Accumulate(Telemetry::FX_TAB_SWITCH_TOTAL_MS,
                           uint32_t((TimeStamp::Now() - mTabSwitchStart).ToMilliseconds()));
     mTabSwitchStart = TimeStamp();
   }
 }
 
 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
 LayerManager::BeginTabSwitch()
 {
   mTabSwitchStart = TimeStamp::Now();
 }
 
--- a/gfx/layers/Layers.h
+++ b/gfx/layers/Layers.h
@@ -479,17 +479,18 @@ public:
   void Log(const char* aPrefix="");
   /**
    * Log information about just this layer manager itself to the NSPR
    * log (if enabled for "Layers").
    */
   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();
 
   void BeginTabSwitch();
 
   static bool IsLogEnabled();
   static PRLogModuleInfo* GetLog() { return sLog; }
 
@@ -511,17 +512,19 @@ protected:
   virtual nsACString& PrintInfo(nsACString& aTo, const char* aPrefix);
 
   static void InitLog();
   static PRLogModuleInfo* sLog;
   uint64_t mId;
   bool mInTransaction;
 private:
   TimeStamp mLastFrameTime;
-  nsTArray<float> mFrameTimes;
+  TimeStamp mPaintStartTime;
+  nsTArray<float> mFrameIntervals;
+  nsTArray<float> mPaintTimes;
   TimeStamp mTabSwitchStart;
 };
 
 class ThebesLayer;
 typedef InfallibleTArray<Animation> AnimationArray;
 
 struct AnimData {
   InfallibleTArray<nsStyleAnimation::Value> mStartValues;
--- a/layout/base/nsRefreshDriver.cpp
+++ b/layout/base/nsRefreshDriver.cpp
@@ -922,16 +922,21 @@ nsRefreshDriver::Tick(int64_t aNowEpoch,
     mPresShellsToInvalidateIfHidden[i]->InvalidatePresShellIfHidden();
   }
   mPresShellsToInvalidateIfHidden.Clear();
 
   if (mViewManagerFlushIsPending) {
 #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();
 #ifdef DEBUG_INVALIDATIONS
     printf("Ending ProcessPendingUpdates\n");
 #endif
   }
 }