Bug 1338347 - Record frame throughput ratios for compositor animations r=botond

This augments the AnimationMetricsTracker to also track compositor animations
triggered by chrome and content layers separately. During the animation, the
tracker keeps a count of frames composited, and once the animation ends, it
uses the wall-clock time and vsync interval to compute the expected number of
composited frames. It then submits a ratio of actual/expected to telemetry.
A score of 1000 (because the ratio is scaled up to an integer between 0 and 1000)
indicates a perfect score with no frames dropped. Lower values are worse, and
values significantly above 1000 indicate abnormal behaviour. Values may be slightly
above 1000 due to rounding error or vsync jitter.

MozReview-Commit-ID: 30Vw0j3dm9G

--HG--
extra : rebase_source : a35c764549c3441f89521629acfa11be82c004ae

gfx/layers/composite/AnimationMetricsTracker.cpp

@@ -6,8 +6,8 @@
 #include "mozilla/layers/AnimationMetricsTracker.h"
 
 #include <algorithm>
+#include <cmath>
 #include <inttypes.h>
-#include "mozilla/Telemetry.h"
 
 #define AMT_LOG(...)
 // #define AMT_LOG(...) printf_stderr("AMT: " __VA_ARGS__)
@@ -16,6 +16,9 @@ namespace mozilla {
 namespace layers {
 
 AnimationMetricsTracker::AnimationMetricsTracker()
+  : mMaxLayerAreaAnimated(0)
+  , mChromeAnimationFrameCount(0)
+  , mContentAnimationFrameCount(0)
 {
 }
 
@@ -24,15 +27,17 @@ AnimationMetricsTracker::~AnimationMetricsTracker()
 }
 
 void
-AnimationMetricsTracker::UpdateAnimationInProgress(bool aInProgress,
-                                                   uint64_t aLayerArea)
+AnimationMetricsTracker::UpdateAnimationInProgress(AnimationProcessTypes aActive,
+                                                   uint64_t aLayerArea,
+                                                   TimeDuration aVsyncInterval)
 {
-  MOZ_ASSERT(aInProgress || aLayerArea == 0);
-  if (mCurrentAnimationStart && !aInProgress) {
+  bool inProgress = (aActive != AnimationProcessTypes::eNone);
+  MOZ_ASSERT(inProgress || aLayerArea == 0);
+  if (mCurrentAnimationStart && !inProgress) {
     AnimationEnded();
     mCurrentAnimationStart = TimeStamp();
     mMaxLayerAreaAnimated = 0;
-  } else if (aInProgress) {
+  } else if (inProgress) {
     if (!mCurrentAnimationStart) {
       mCurrentAnimationStart = TimeStamp::Now();
       mMaxLayerAreaAnimated = aLayerArea;
@@ -41,6 +46,19 @@ AnimationMetricsTracker::UpdateAnimationInProgress(bool aInProgress,
       mMaxLayerAreaAnimated = std::max(mMaxLayerAreaAnimated, aLayerArea);
     }
   }
+
+  UpdateAnimationThroughput("chrome",
+                            (aActive & AnimationProcessTypes::eChrome) != AnimationProcessTypes::eNone,
+                            mChromeAnimationStart,
+                            mChromeAnimationFrameCount,
+                            aVsyncInterval,
+                            Telemetry::COMPOSITOR_ANIMATION_THROUGHPUT_CHROME);
+  UpdateAnimationThroughput("content",
+                            (aActive & AnimationProcessTypes::eContent) != AnimationProcessTypes::eNone,
+                            mContentAnimationStart,
+                            mContentAnimationFrameCount,
+                            aVsyncInterval,
+                            Telemetry::COMPOSITOR_ANIMATION_THROUGHPUT_CONTENT);
 }
 
 void
@@ -52,6 +70,7 @@ void
 AnimationMetricsTracker::AnimationEnded()
 {
   MOZ_ASSERT(mCurrentAnimationStart);
+
   Telemetry::AccumulateTimeDelta(Telemetry::COMPOSITOR_ANIMATION_DURATION, mCurrentAnimationStart);
   Telemetry::Accumulate(Telemetry::COMPOSITOR_ANIMATION_MAX_LAYER_AREA, mMaxLayerAreaAnimated);
   AMT_LOG("Ended animation; duration: %f ms, area: %" PRIu64 "\n",
@@ -59,5 +78,62 @@ AnimationMetricsTracker::AnimationEnded()
     mMaxLayerAreaAnimated);
 }
 
+void
+AnimationMetricsTracker::UpdateAnimationThroughput(const char* aLabel,
+                                                   bool aInProgress,
+                                                   TimeStamp& aStartTime,
+                                                   uint32_t& aFrameCount,
+                                                   TimeDuration aVsyncInterval,
+                                                   Telemetry::HistogramID aHistogram)
+{
+  if (aInProgress && !aStartTime) {
+    // the animation just started
+    aStartTime = TimeStamp::Now();
+    aFrameCount = 1;
+    AMT_LOG("Compositor animation of type %s just started\n", aLabel);
+  } else if (aInProgress && aStartTime) {
+    // the animation continues
+    aFrameCount++;
+  } else if (!aInProgress && aStartTime) {
+    // the animation just ended
+
+    // Get the length and clear aStartTime before the early-returns below
+    TimeDuration animationLength = TimeStamp::Now() - aStartTime;
+    aStartTime = TimeStamp();
+
+    if (aVsyncInterval == TimeDuration::Forever()) {
+      AMT_LOG("Invalid vsync interval: forever\n");
+      return;
+    }
+    double vsyncIntervalMs = aVsyncInterval.ToMilliseconds();
+    if (vsyncIntervalMs < 1.0f) {
+      // Guard to avoid division by zero or other crazy results below
+      AMT_LOG("Invalid vsync interval: %fms\n", vsyncIntervalMs);
+      return;
+    }
+
+    // We round the expectedFrameCount because it's a count and should be an
+    // integer. The animationLength might not be an exact vsync multiple because
+    // it's taken during the composition process and the amount of work done
+    // between the vsync signal and the Timestamp::Now() call may vary slightly
+    // from one composite to another.
+    uint32_t expectedFrameCount = std::lround(animationLength.ToMilliseconds() / vsyncIntervalMs);
+    AMT_LOG("Type %s ran for %fms (interval: %fms), %u frames (expected: %u)\n",
+        aLabel, animationLength.ToMilliseconds(), vsyncIntervalMs, aFrameCount,
+        expectedFrameCount);
+    if (expectedFrameCount <= 0) {
+      // Graceful handling of probably impossible thing, unless the clock
+      // changes while running?
+      return;
+    }
+
+    // Scale up by 1000 because telemetry takes ints, truncate intentionally
+    // to avoid artificial inflation of the result.
+    uint32_t frameHitRatio = (uint32_t)(1000.0f * aFrameCount / expectedFrameCount);
+    Telemetry::Accumulate(aHistogram, frameHitRatio);
+    AMT_LOG("Reported frameHitRatio %u\n", frameHitRatio);
+  }
+}
+
 } // namespace layers
 } // namespace mozilla

gfx/layers/composite/AnimationMetricsTracker.h

@@ -6,6 +6,7 @@
 #ifndef mozilla_layers_AnimationMetricsTracker_h
 #define mozilla_layers_AnimationMetricsTracker_h
 
+#include "mozilla/Telemetry.h"
 #include "mozilla/TimeStamp.h"
 #include "mozilla/TypedEnumBits.h"
 
@@ -30,17 +31,39 @@ public:
 
   /**
    * This function should be called per composite, to inform the metrics
-   * tracker if any animation is in progress, and if so, what area is
-   * being animated. The aLayerArea is in Layer pixels squared.
+   * tracker which processes have active animations. If there is are animations
+   * in progress, the sum of their areas should also be provided, along with
+   * the vsync interval.
    */
-  void UpdateAnimationInProgress(bool aInProgress, uint64_t aLayerArea);
+  void UpdateAnimationInProgress(AnimationProcessTypes aActive, uint64_t aLayerArea,
+                                 TimeDuration aVsyncInterval);
 
 private:
   void AnimationStarted();
   void AnimationEnded();
+  void UpdateAnimationThroughput(const char* aLabel,
+                                 bool aInProgress,
+                                 TimeStamp& aStartTime,
+                                 uint32_t& aFrameCount,
+                                 TimeDuration aVsyncInterval,
+                                 Telemetry::HistogramID aHistogram);
 
+  // The start time of the current compositor animation. This just tracks
+  // whether the compositor is running an animation, without regard to which
+  // process the animation is coming from.
   TimeStamp mCurrentAnimationStart;
+  // The max area (in layer pixels) that the current compositor animation
+  // has touched on any given animation frame.
   uint64_t mMaxLayerAreaAnimated;
+
+  // The start time of the current chrome-process animation.
+  TimeStamp mChromeAnimationStart;
+  // The number of frames composited for the current chrome-process animation.
+  uint32_t mChromeAnimationFrameCount;
+  // The start time of the current content-process animation.
+  TimeStamp mContentAnimationStart;
+  // The number of frames composited for the current content-process animation.
+  uint32_t mContentAnimationFrameCount;
 };
 
 } // namespace layers

gfx/layers/composite/AsyncCompositionManager.cpp

@@ -1367,7 +1367,7 @@ AsyncCompositionManager::TransformShadowTree(TimeStamp aCurrentFrame,
   bool wantNextFrame = (animationProcess != AnimationProcessTypes::eNone);
 
   mAnimationMetricsTracker.UpdateAnimationInProgress(
-    wantNextFrame, layerAreaAnimated);
+    animationProcess, layerAreaAnimated, aVsyncRate);
 
   if (!wantNextFrame) {
     // Clean up the CompositorAnimationStorage because