Bug 826383: cyclic array for frames recording to support concurrent users. r=jmuizelaar,khuey

browser/base/content/tabbrowser.xml

@@ -1275,9 +1275,9 @@
                   tabContainer._handleNewTab(t);
                 else {
                   if (tabContainer._tabAnimationLoggingEnabled) {
-                    window.QueryInterface(Ci.nsIInterfaceRequestor)
-                          .getInterface(Ci.nsIDOMWindowUtils)
-                          .startFrameTimeRecording();
+                    t._recordingHandle = window.QueryInterface(Ci.nsIInterfaceRequestor)
+                                               .getInterface(Ci.nsIDOMWindowUtils)
+                                               .startFrameTimeRecording();
                   }
                   t._animStartTime = Date.now();
                   t.setAttribute("fadein", "true");
@@ -1580,9 +1580,9 @@
             }
 
             if (this.tabContainer._tabAnimationLoggingEnabled) {
-              window.QueryInterface(Ci.nsIInterfaceRequestor)
-                    .getInterface(Ci.nsIDOMWindowUtils)
-                    .startFrameTimeRecording();
+              aTab._recordingHandle = window.QueryInterface(Ci.nsIInterfaceRequestor)
+                                            .getInterface(Ci.nsIDOMWindowUtils)
+                                            .startFrameTimeRecording();
             }
             aTab._animStartTime = Date.now();
 
@@ -3544,11 +3544,11 @@
                             .add(Date.now() - tab._animStartTime);
           tab._animStartTime = 0;
 
-          if (this._tabAnimationLoggingEnabled) {
+          if (this._tabAnimationLoggingEnabled && tab.hasOwnProperty("_recordingHandle")) {
             let paints = {};
             let intervals = window.QueryInterface(Ci.nsIInterfaceRequestor)
                                   .getInterface(Ci.nsIDOMWindowUtils)
-                                  .stopFrameTimeRecording(paints);
+                                  .stopFrameTimeRecording(tab._recordingHandle, 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";

dom/base/nsDOMWindowUtils.cpp

@@ -2137,12 +2137,14 @@ nsDOMWindowUtils::GetLayerManagerType(nsAString& aType)
 }
 
 NS_IMETHODIMP
-nsDOMWindowUtils::StartFrameTimeRecording()
+nsDOMWindowUtils::StartFrameTimeRecording(uint32_t *startIndex)
 {
   if (!nsContentUtils::IsCallerChrome()) {
     return NS_ERROR_DOM_SECURITY_ERR;
   }
 
+  NS_ENSURE_ARG_POINTER(startIndex);
+
   nsCOMPtr<nsIWidget> widget = GetWidget();
   if (!widget)
     return NS_ERROR_FAILURE;
@@ -2151,13 +2153,16 @@ nsDOMWindowUtils::StartFrameTimeRecording()
   if (!mgr)
     return NS_ERROR_FAILURE;
 
-  mgr->StartFrameTimeRecording();
+  *startIndex = mgr->StartFrameTimeRecording();
 
   return NS_OK;
 }
 
 NS_IMETHODIMP
-nsDOMWindowUtils::StopFrameTimeRecording(float** paintTimes, uint32_t *frameCount, float **frameIntervals)
+nsDOMWindowUtils::StopFrameTimeRecording(uint32_t   startIndex,
+                                         float    **paintTimes,
+                                         uint32_t  *frameCount,
+                                         float    **frameIntervals)
 {
   if (!nsContentUtils::IsCallerChrome()) {
     return NS_ERROR_DOM_SECURITY_ERR;
@@ -2177,31 +2182,21 @@ nsDOMWindowUtils::StopFrameTimeRecording(float** paintTimes, uint32_t *frameCoun
 
   nsTArray<float> tmpFrameIntervals;
   nsTArray<float> tmpPaintTimes;
-  mgr->StopFrameTimeRecording(tmpFrameIntervals, tmpPaintTimes);
-
-  *frameIntervals = nullptr;
-  *paintTimes = nullptr;
+  mgr->StopFrameTimeRecording(startIndex, tmpFrameIntervals, tmpPaintTimes);
   *frameCount = tmpFrameIntervals.Length();
 
-  if (*frameCount != 0) {
-    *frameIntervals = (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
-    if (!*frameIntervals)
-      return NS_ERROR_OUT_OF_MEMORY;
+  *frameIntervals = (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
+  *paintTimes =     (float*)nsMemory::Alloc(*frameCount * sizeof(float*));
 
-    *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++) {
-      (*frameIntervals)[i] = tmpFrameIntervals[i];
+  /* copy over the frame intervals and paint times into the arrays we just allocated */
+  for (uint32_t i = 0; i < *frameCount; i++) {
+    (*frameIntervals)[i] = tmpFrameIntervals[i];
 #ifndef MOZ_WIDGET_GONK
-      (*paintTimes)[i] = tmpPaintTimes[i];
+    (*paintTimes)[i] = tmpPaintTimes[i];
 #else
-      // Waiting for bug 830475 to work on B2G.
-      (*paintTimes)[i] = 0;
+    // Waiting for bug 830475 to work on B2G.
+    (*paintTimes)[i] = 0;
 #endif
-    }
   }
 
   return NS_OK;

dom/interfaces/base/nsIDOMWindowUtils.idl

@@ -41,7 +41,7 @@ interface nsIDOMClientRect;
 interface nsIURI;
 interface nsIDOMEventTarget;
 
-[scriptable, uuid(7cd26372-d2e2-463a-bce3-3f02d4b23fa8)]
+[scriptable, uuid(458f5b08-4966-4a91-8617-258afb87070e)]
 interface nsIDOMWindowUtils : nsISupports {
 
   /**
@@ -1053,10 +1053,33 @@ interface nsIDOMWindowUtils : nsISupports {
    */
   readonly attribute AString layerManagerType;
 
-  void startFrameTimeRecording();
-  void stopFrameTimeRecording([optional, array, size_is(frameCount)] out float paintTimes,
+  /**
+   * Record (and return) frame-intervals and paint-times for frames which were presented
+   *   between calling StartFrameTimeRecording and StopFrameTimeRecording.
+   *
+   * - Uses a cyclic buffer and serves concurrent consumers, so if Stop is called too late
+   *     (elements were overwritten since Start), result is considered invalid and hence empty.
+   * - Buffer is capable of holding 10 seconds @ 60fps (or more if frames were less frequent).
+   *     Can be changed (up to 1 hour) via pref: toolkit.framesRecording.bufferSize.
+   * - Note: the first frame-interval may be longer than expected because last frame
+   *     might have been presented some time before calling StartFrameTimeRecording.
+   */
+
+  /**
+   * Returns a handle which represents current recording start position.
+   */
+   void startFrameTimeRecording([retval] out unsigned long startIndex);
+
+  /**
+   * Returns number of recorded frames since startIndex was issued,
+   *   and allocates+populates 2 arraye with the recorded data.
+   * - Allocation is infallible. Should be released even if size is 0.
+   */
+   void stopFrameTimeRecording(in unsigned long startIndex,
+                              [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

@@ -947,29 +947,94 @@ RefLayer::FillSpecificAttributes(SpecificLayerAttributes& aAttrs)
   aAttrs = RefLayerAttributes(GetReferentId());
 }
 
-void
+/** 
+ * StartFrameTimeRecording, together with StopFrameTimeRecording
+ * enable recording of frame intrvals and paint times.
+ * (Paint start time is set from the refresh driver right before starting
+ * flush/paint and ends at PostPresent. Intervals are measured at PostPresent).
+ *
+ * To allow concurrent consumers, 2 cyclic arrays are used (for intervals, paints)
+ * which serve all consumers, practically stateless with regard to consumers.
+ *
+ * To save resources, the buffers are allocated on first call to StartFrameTimeRecording
+ * and recording is paused if no consumer which called StartFrameTimeRecording is able
+ * to get valid results (because the cyclic buffers were overwritten since that call).
+ *
+ * To determine availability of the data upon StopFrameTimeRecording:
+ * - mRecording.mNextIndex increases on each PostPresent, and never resets.
+ * - Cyclic buffer position is realized as mNextIndex % bufferSize.
+ * - StartFrameTimeRecording returns mNextIndex. When StopFrameTimeRecording is called,
+ *   the required start index is passed as an arg, and we're able to calculate the required
+ *   length. If this length is bigger than bufferSize, it means data was overwritten.
+ *   otherwise, we can return the entire sequence.
+ * - To determine if we need to pause, mLatestStartIndex is updated to mNextIndex
+ *   on each call to StartFrameTimeRecording. If this index gets overwritten,
+ *   it means that all earlier start indices obtained via StartFrameTimeRecording
+ *   were also overwritten, hence, no point in recording, so pause.
+ * - mCurrentRunStartIndex indicates the oldest index of the recording after which
+ *   the recording was not paused. If StopFrameTimeRecording is invoked with a start index
+ *   older than this, it means that some frames were not recorded, so data is invalid.
+ */
+uint32_t
 LayerManager::StartFrameTimeRecording()
 {
-  mLastFrameTime = TimeStamp::Now();
-  mPaintStartTime = mLastFrameTime;
+  if (mRecording.mIsPaused) {
+    mRecording.mIsPaused = false;
+
+    if (!mRecording.mIntervals.Length()) { // Initialize recording buffers
+      const uint32_t kRecordingMinSize = 60 * 10; // 10 seconds @60 fps.
+      const uint32_t kRecordingMaxSize = 60 * 60 * 60; // One hour
+      uint32_t bufferSize = Preferences::GetUint("toolkit.framesRecording.bufferSize",
+                                                 kRecordingMinSize);
+      bufferSize = std::min(bufferSize, kRecordingMaxSize);
+      bufferSize = std::max(bufferSize, kRecordingMinSize);
+
+      if (!mRecording.mIntervals.SetLength(bufferSize) || !mRecording.mPaints.SetLength(bufferSize)) {
+        mRecording.mIsPaused = true; // OOM
+        mRecording.mIntervals.Clear();
+        mRecording.mPaints.Clear();
+      }
+    }
+
+    // After being paused, recent values got invalid. Update them to now.
+    mRecording.mLastFrameTime = TimeStamp::Now();
+    mRecording.mPaintStartTime = mRecording.mLastFrameTime;
+
+    // Any recording which started before this is invalid, since we were paused.
+    mRecording.mCurrentRunStartIndex = mRecording.mNextIndex;
+  }
+
+  // If we'll overwrite this index, there are no more consumers with aStartIndex
+  // for which we're able to provide the full recording, so no point in keep recording.
+  mRecording.mLatestStartIndex = mRecording.mNextIndex;
+  return mRecording.mNextIndex;
 }
 
 void
 LayerManager::SetPaintStartTime(TimeStamp& aTime)
 {
-  if (!mLastFrameTime.IsNull()) {
-    mPaintStartTime = aTime;
+  if (!mRecording.mIsPaused) {
+    mRecording.mPaintStartTime = aTime;
   }
 }
 
 void
 LayerManager::PostPresent()
 {
-  if (!mLastFrameTime.IsNull()) {
+  if (!mRecording.mIsPaused) {
     TimeStamp now = TimeStamp::Now();
-    mFrameIntervals.AppendElement((now - mLastFrameTime).ToMilliseconds());
-    mPaintTimes.AppendElement((now - mPaintStartTime).ToMilliseconds());
-    mLastFrameTime = now;
+    uint32_t i = mRecording.mNextIndex % mRecording.mIntervals.Length();
+    mRecording.mIntervals[i] = static_cast<float>((now - mRecording.mLastFrameTime)
+                                                  .ToMilliseconds());
+    mRecording.mPaints[i]    = static_cast<float>((now - mRecording.mPaintStartTime)
+                                                  .ToMilliseconds());
+    mRecording.mNextIndex++;
+    mRecording.mLastFrameTime = now;
+
+    if (mRecording.mNextIndex > (mRecording.mLatestStartIndex + mRecording.mIntervals.Length())) {
+      // We've just overwritten the most recent recording start -> pause.
+      mRecording.mIsPaused = true;
+    }
   }
   if (!mTabSwitchStart.IsNull()) {
     Telemetry::Accumulate(Telemetry::FX_TAB_SWITCH_TOTAL_MS,
@@ -979,13 +1044,33 @@ LayerManager::PostPresent()
 }
 
 void
-LayerManager::StopFrameTimeRecording(nsTArray<float>& aFrameIntervals, nsTArray<float>& aPaintTimes)
+LayerManager::StopFrameTimeRecording(uint32_t         aStartIndex,
+                                     nsTArray<float>& aFrameIntervals,
+                                     nsTArray<float>& aPaintTimes)
 {
-  mLastFrameTime = TimeStamp();
-  aFrameIntervals.SwapElements(mFrameIntervals);
-  aPaintTimes.SwapElements(mPaintTimes);
-  mFrameIntervals.Clear();
-  mPaintTimes.Clear();
+  uint32_t bufferSize = mRecording.mIntervals.Length();
+  uint32_t length = mRecording.mNextIndex - aStartIndex;
+  if (mRecording.mIsPaused || length > bufferSize || aStartIndex < mRecording.mCurrentRunStartIndex) {
+    // aStartIndex is too old. Also if aStartIndex was issued before mRecordingNextIndex overflowed (uint32_t)
+    //   and stopped after the overflow (would happen once every 828 days of constant 60fps).
+    length = 0;
+  }
+
+  // Set length in advance to avoid possibly repeated reallocations (and OOM checks).
+  if (!length || !aFrameIntervals.SetLength(length) || !aPaintTimes.SetLength(length)) {
+    aFrameIntervals.Clear();
+    aPaintTimes.Clear();
+    return; // empty recording or OOM, return empty arrays.
+  }
+
+  uint32_t cyclicPos = aStartIndex % bufferSize;
+  for (uint32_t i = 0; i < length; i++, cyclicPos++) {
+    if (cyclicPos == bufferSize) {
+      cyclicPos = 0;
+    }
+    aFrameIntervals[i] = mRecording.mIntervals[cyclicPos];
+    aPaintTimes[i]     = mRecording.mPaints[cyclicPos];
+  }
 }
 
 void

gfx/layers/Layers.h

@@ -489,9 +489,32 @@ public:
    */
   void LogSelf(const char* aPrefix="");
 
-  void StartFrameTimeRecording();
+  /**
+   * Record (and return) frame-intervals and paint-times for frames which were presented
+   *   between calling StartFrameTimeRecording and StopFrameTimeRecording.
+   *
+   * - Uses a cyclic buffer and serves concurrent consumers, so if Stop is called too late
+   *     (elements were overwritten since Start), result is considered invalid and hence empty.
+   * - Buffer is capable of holding 10 seconds @ 60fps (or more if frames were less frequent).
+   *     Can be changed (up to 1 hour) via pref: toolkit.framesRecording.bufferSize.
+   * - Note: the first frame-interval may be longer than expected because last frame
+   *     might have been presented some time before calling StartFrameTimeRecording.
+   */
+
+  /**
+   * Returns a handle which represents current recording start position.
+   */
+  uint32_t StartFrameTimeRecording();
+
+  /**
+   *  Clears, then populates 2 arraye with the recorded frames timing data.
+   *  The arrays will be empty if data was overwritten since aStartIndex was obtained.
+   */
+  void StopFrameTimeRecording(uint32_t         aStartIndex,
+                              nsTArray<float>& aFrameIntervals,
+                              nsTArray<float>& aPaintTimes);
+
   void SetPaintStartTime(TimeStamp& aTime);
-  void StopFrameTimeRecording(nsTArray<float>& aFrameTimes, nsTArray<float>& aProcessingTimes);
 
   void PostPresent();
 
@@ -526,10 +549,25 @@ protected:
   uint64_t mId;
   bool mInTransaction;
 private:
-  TimeStamp mLastFrameTime;
-  TimeStamp mPaintStartTime;
-  nsTArray<float> mFrameIntervals;
-  nsTArray<float> mPaintTimes;
+  struct FramesTimingRecording
+  {
+    // Stores state and data for frame intervals and paint times recording.
+    // see LayerManager::StartFrameTimeRecording() at Layers.cpp for more details.
+    FramesTimingRecording()
+      : mIsPaused(true)
+      , mNextIndex(0)
+    {}
+    bool mIsPaused;
+    uint32_t mNextIndex;
+    TimeStamp mLastFrameTime;
+    TimeStamp mPaintStartTime;
+    nsTArray<float> mIntervals;
+    nsTArray<float> mPaints;
+    uint32_t mLatestStartIndex;
+    uint32_t mCurrentRunStartIndex;
+  };
+  FramesTimingRecording mRecording;
+
   TimeStamp mTabSwitchStart;
 };