images: UMA number of frames dropped for animated images.

If the renderer can not run an image animation at the requested frame
rate, frames in the animation are skipped when trying to catch up to
the desired frame. Add an UMA to measure this to assess the smoothness
of these animations.

Bug: 735741
Cq-Include-Trybots: master.tryserver.blink:linux_trusty_blink_rel
Change-Id: I4d00dbeb6455f8e5badebbdec3403677ec2db462
Reviewed-on: https://chromium-review.googlesource.com/668016
Commit-Queue: Khushal <khushalsagar@chromium.org>
Reviewed-by: Mark Pearson <mpearson@chromium.org>
Reviewed-by: Chris Harrelson <chrishtr@chromium.org>
Cr-Commit-Position: refs/heads/master@{#505898}

cc/trees/image_animation_controller.cc

@@ -5,6 +5,7 @@
 #include "cc/trees/image_animation_controller.h"
 
 #include "base/bind.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/trace_event/trace_event.h"
 #include "cc/paint/image_animation_count.h"
 
@@ -156,6 +157,13 @@ ImageAnimationController::GetDriversForTesting(
   return it->second.drivers_for_testing();
 }
 
+size_t ImageAnimationController::GetLastNumOfFramesSkippedForTesting(
+    PaintImage::Id paint_image_id) const {
+  const auto& it = animation_state_map_.find(paint_image_id);
+  DCHECK(it != animation_state_map_.end());
+  return it->second.last_num_frames_skipped_for_testing();
+}
+
 ImageAnimationController::AnimationState::AnimationState() = default;
 
 ImageAnimationController::AnimationState::AnimationState(
@@ -246,7 +254,9 @@ bool ImageAnimationController::AnimationState::AdvanceFrame(
   // TODO(khushalsagar): Avoid unnecessary iterations for skipping whole loops
   // in the animations.
   size_t last_frame_index = frames_.size() - 1;
+  size_t num_of_frames_advanced = 0u;
   while (next_desired_frame_time_ <= now && ShouldAnimate()) {
+    num_of_frames_advanced++;
     size_t next_frame_index = NextFrameIndex();
     base::TimeTicks next_desired_frame_time =
         next_desired_frame_time_ + frames_[next_frame_index].duration;
@@ -279,6 +289,13 @@ bool ImageAnimationController::AnimationState::AdvanceFrame(
       repetitions_completed_++;
   }
 
+  // We should have advanced a single frame, anything more than that are frames
+  // skipped trying to catch up.
+  DCHECK_GT(num_of_frames_advanced, 0u);
+  last_num_frames_skipped_ = num_of_frames_advanced - 1u;
+  UMA_HISTOGRAM_COUNTS_100000("AnimatedImage.NumOfFramesSkipped.Compositor",
+                              last_num_frames_skipped_);
+
   return pending_index_ != active_index_;
 }
 

cc/trees/image_animation_controller.h

@@ -98,6 +98,8 @@ class CC_EXPORT ImageAnimationController {
 
   const base::flat_set<AnimationDriver*>& GetDriversForTesting(
       PaintImage::Id paint_image_id) const;
+  size_t GetLastNumOfFramesSkippedForTesting(
+      PaintImage::Id paint_image_id) const;
 
  private:
   class AnimationState {
@@ -124,6 +126,9 @@ class CC_EXPORT ImageAnimationController {
     const base::flat_set<AnimationDriver*>& drivers_for_testing() const {
       return drivers_;
     }
+    size_t last_num_frames_skipped_for_testing() const {
+      return last_num_frames_skipped_;
+    }
 
    private:
     void ResetAnimation();
@@ -177,6 +182,10 @@ class CC_EXPORT ImageAnimationController {
     PaintImage::CompletionState completion_state_ =
         PaintImage::CompletionState::PARTIALLY_DONE;
 
+    // The number of frames skipped during catch-up the last time this animation
+    // was advanced.
+    size_t last_num_frames_skipped_ = 0u;
+
     DISALLOW_COPY_AND_ASSIGN(AnimationState);
   };
 

cc/trees/image_animation_controller_unittest.cc

@@ -100,6 +100,12 @@ class ImageAnimationControllerTest : public testing::Test {
 
       // Animate the image on the sync tree.
       auto animated_images = controller_->AnimateForSyncTree(now_);
+
+      // No frames should have been skipped since we add no delay in advancing
+      // the animation.
+      EXPECT_EQ(
+          controller_->GetLastNumOfFramesSkippedForTesting(paint_image_id), 0u);
+
       EXPECT_EQ(controller_->GetFrameIndexForImage(paint_image_id,
                                                    WhichTree::PENDING_TREE),
                 i);
@@ -154,7 +160,8 @@ TEST_F(ImageAnimationControllerTest, AnimationWithDelays) {
   std::vector<FrameMetadata> frames = {
       FrameMetadata(true, base::TimeDelta::FromMilliseconds(5)),
       FrameMetadata(true, base::TimeDelta::FromMilliseconds(3)),
-      FrameMetadata(true, base::TimeDelta::FromMilliseconds(4))};
+      FrameMetadata(true, base::TimeDelta::FromMilliseconds(4)),
+      FrameMetadata(true, base::TimeDelta::FromMilliseconds(3))};
 
   DiscardableImageMap::AnimatedImageMetadata data(
       PaintImage::GetNextId(), PaintImage::CompletionState::DONE, frames,
@@ -175,15 +182,18 @@ TEST_F(ImageAnimationControllerTest, AnimationWithDelays) {
   auto animated_images = controller_->AnimateForSyncTree(now_);
   EXPECT_EQ(animated_images.size(), 1u);
   EXPECT_EQ(animated_images.count(data.paint_image_id), 1u);
+  EXPECT_EQ(
+      controller_->GetLastNumOfFramesSkippedForTesting(data.paint_image_id),
+      1u);
 
   // The pending tree displays the second frame while the active tree has the
-  // third frame.
+  // last frame.
   EXPECT_EQ(controller_->GetFrameIndexForImage(data.paint_image_id,
                                                WhichTree::PENDING_TREE),
             1u);
   EXPECT_EQ(controller_->GetFrameIndexForImage(data.paint_image_id,
                                                WhichTree::ACTIVE_TREE),
-            2u);
+            3u);
 
   // Invalidation delay is based on the duration of the second frame and the
   // delay in creating this sync tree.
@@ -192,15 +202,19 @@ TEST_F(ImageAnimationControllerTest, AnimationWithDelays) {
   base::RunLoop().RunUntilIdle();
   EXPECT_EQ(invalidation_count_, 1);
 
-  // Activate and animate with a delay that causes us to skip another frame.
+  // Activate and animate with a delay that causes us to skip another 2 frames.
   controller_->DidActivate();
   EXPECT_EQ(controller_->GetFrameIndexForImage(data.paint_image_id,
                                                WhichTree::ACTIVE_TREE),
             1u);
-  AdvanceNow(data.frames[1].duration + data.frames[2].duration);
+  AdvanceNow(data.frames[1].duration + data.frames[2].duration +
+             data.frames[3].duration);
   animated_images = controller_->AnimateForSyncTree(now_);
   EXPECT_EQ(animated_images.size(), 1u);
   EXPECT_EQ(animated_images.count(data.paint_image_id), 1u);
+  EXPECT_EQ(
+      controller_->GetLastNumOfFramesSkippedForTesting(data.paint_image_id),
+      2u);
 
   // The pending tree displays the first frame, while the active tree has the
   // second frame.

third_party/WebKit/Source/platform/graphics/BitmapImage.cpp

@@ -26,6 +26,7 @@
 
 #include "platform/graphics/BitmapImage.h"
 
+#include "base/metrics/histogram_macros.h"
 #include "platform/Timer.h"
 #include "platform/geometry/FloatRect.h"
 #include "platform/graphics/BitmapImageMetrics.h"
@@ -490,15 +491,21 @@ bool BitmapImage::ShouldAnimate() {
 }
 
 void BitmapImage::StartAnimation() {
-  StartAnimationInternal(MonotonicallyIncreasingTime());
+  last_num_frames_skipped_ =
+      StartAnimationInternal(MonotonicallyIncreasingTime());
+  if (!last_num_frames_skipped_.has_value())
+    return;
+
+  UMA_HISTOGRAM_COUNTS_100000("AnimatedImage.NumOfFramesSkipped.Main",
+                              last_num_frames_skipped_.value());
 }
 
-void BitmapImage::StartAnimationInternal(const double time) {
+Optional<size_t> BitmapImage::StartAnimationInternal(const double time) {
   // If the |frame_timer_| is set, it indicates that a task is already pending
   // to advance the current frame of the animation. We don't need to schedule
   // a task to advance the animation in that case.
   if (frame_timer_ || !ShouldAnimate() || FrameCount() <= 1)
-    return;
+    return WTF::nullopt;
 
   // If we aren't already animating, set now as the animation start time.
   if (!desired_frame_start_time_)
@@ -507,7 +514,7 @@ void BitmapImage::StartAnimationInternal(const double time) {
   // Don't advance the animation to an incomplete frame.
   size_t next_frame = (current_frame_index_ + 1) % FrameCount();
   if (!all_data_received_ && !FrameIsReceivedAtIndex(next_frame))
-    return;
+    return WTF::nullopt;
 
   // Don't advance past the last frame if we haven't decoded the whole image
   // yet and our repetition count is potentially unset.  The repetition count
@@ -517,7 +524,7 @@ void BitmapImage::StartAnimationInternal(const double time) {
       (RepetitionCount() == kAnimationLoopOnce ||
        animation_policy_ == kImageAnimationPolicyAnimateOnce) &&
       current_frame_index_ >= (FrameCount() - 1))
-    return;
+    return WTF::nullopt;
 
   // Determine time for next frame to start.  By ignoring paint and timer lag
   // in this calculation, we make the animation appear to run at its desired
@@ -550,67 +557,88 @@ void BitmapImage::StartAnimationInternal(const double time) {
     desired_frame_start_time_ = time;
 
   if (time < desired_frame_start_time_) {
-    // Haven't yet reached time for next frame to start; delay until then.
+    // Haven't yet reached time for next frame to start; delay until then
     frame_timer_ = WTF::WrapUnique(new TaskRunnerTimer<BitmapImage>(
         task_runner_, this, &BitmapImage::AdvanceAnimation));
     frame_timer_->StartOneShot(std::max(desired_frame_start_time_ - time, 0.),
                                BLINK_FROM_HERE);
-  } else {
-    // We've already reached or passed the time for the next frame to start.
-    // See if we've also passed the time for frames after that to start, in
-    // case we need to skip some frames entirely.  Remember not to advance
-    // to an incomplete frame.
+
+    // No frames needed to be skipped to advance to the next frame.
+    return Optional<size_t>(0u);
+  }
+
+  // We've already reached or passed the time for the next frame to start.
+  // See if we've also passed the time for frames after that to start, in
+  // case we need to skip some frames entirely.  Remember not to advance
+  // to an incomplete frame.
+  // Note that |desired_frame_start_time_| is always set to the time at which
+  // |next_frame| should be displayed.
+  size_t frames_advanced = 0u;
+  for (; FrameIsReceivedAtIndex(next_frame);
+       next_frame = (current_frame_index_ + 1) % FrameCount()) {
+    // Should we skip the next frame?
+    // TODO(vmpstr): This function can probably deal in TimeTicks/TimeDelta
+    // instead.
+    if (time < desired_frame_start_time_)
+      break;
 
     // Skip the next frame by advancing the animation forward one frame.
     if (!InternalAdvanceAnimation(kSkipFramesToCatchUp)) {
       DCHECK(animation_finished_);
-      return;
-    }
 
-    // We have already realized that we need to skip the |next_frame| since
-    // |desired_frame_start_time_| is when |next_frame| should have been
-    // displayed, which is in the past. The rest of the loop determines if more
-    // frames need to be skipped to catch up.
-    last_num_frames_skipped_ = 1u;
-    for (size_t frame_after_next = (next_frame + 1) % FrameCount();
-         FrameIsReceivedAtIndex(frame_after_next);
-         frame_after_next = (next_frame + 1) % FrameCount()) {
-      // Should we skip the next frame?
-      // TODO(vmpstr): This function can probably deal in TimeTicks/TimeDelta
-      // instead.
-      double frame_after_next_start_time =
-          desired_frame_start_time_ +
-          FrameDurationAtIndex(next_frame).InSecondsF();
-      if (time < frame_after_next_start_time)
-        break;
-
-      // Skip the next frame by advancing the animation forward one frame.
-      if (!InternalAdvanceAnimation(kSkipFramesToCatchUp)) {
-        DCHECK(animation_finished_);
-        return;
-      }
-      last_num_frames_skipped_++;
-      desired_frame_start_time_ = frame_after_next_start_time;
-      next_frame = frame_after_next;
+      // No frames skipped, we simply marked the animation as finished on the
+      // first attempt to advance it.
+      if (frames_advanced == 0u)
+        return WTF::nullopt;
+
+      // Don't include the |current_frame_index_|, the last frame we will be
+      // painting when finishing this animation, in the number of frames
+      // skipped.
+      return Optional<size_t>(frames_advanced - 1);
     }
 
-    // Since we just advanced a bunch of frames during catch up, post a
-    // notification to the observers. Note this has to be async because
-    // animation can happen during painting and this invalidation is required
-    // after the current paint.
-    task_runner_->PostTask(
-        BLINK_FROM_HERE,
-        WTF::Bind(&BitmapImage::NotifyObserversOfAnimationAdvance,
-                  weak_factory_.CreateWeakPtr(), nullptr));
-
-    // Set up the timer for the next frame if required. Note that we have
-    // already advanced to the current_frame_index_ after catching up. And in
-    // the loop above, we either could not advance the animation further or we
-    // advanced it up till the desired time for the current frame. This ensures
-    // that calling StartAnimationInternal here with the same |time| will not
-    // need to perform any catch up skipping.
-    StartAnimationInternal(time);
+    DCHECK_EQ(current_frame_index_, next_frame);
+    frames_advanced++;
+    desired_frame_start_time_ +=
+        FrameDurationAtIndex(current_frame_index_).InSecondsF();
   }
+
+  DCHECK_GT(frames_advanced, 0u);
+
+  // Since we just advanced a bunch of frames during catch up, post a
+  // notification to the observers. Note this has to be async because the
+  // animation can happen during painting and this invalidation is required
+  // after the current paint.
+  task_runner_->PostTask(
+      BLINK_FROM_HERE,
+      WTF::Bind(&BitmapImage::NotifyObserversOfAnimationAdvance,
+                weak_factory_.CreateWeakPtr(), nullptr));
+
+  // Reset the |desired_frame_start_time_| to the time for starting the
+  // |current_frame_index_|. Whenever StartAnimationInternal decides to schedule
+  // the task for the next frame (which may not happen in the call below), it
+  // always updates the |desired_frame_start_time_| based on the current frame
+  // duration.
+  desired_frame_start_time_ -=
+      FrameDurationAtIndex(current_frame_index_).InSecondsF();
+
+  // Set up the timer for the next frame if required. Note that we have
+  // already advanced to the current_frame_index_ after catching up. And in
+  // the loop above, we either could not advance the animation further or we
+  // advanced it up till the desired time for the current frame. This ensures
+  // that calling StartAnimationInternal here with the same |time| will not
+  // need to perform any catch up skipping.
+  StartAnimationInternal(time);
+
+  // At this point, we've advanced to the |current_frame_index_|, and requested
+  // an invalidation from the observers, and potentially scheduled a task for
+  // further advancing the animation. If the task runs before the next draw,
+  // current_frame_index_ will be skipped, if not, we will draw with it. For the
+  // purpose of keeping the UMA tracking simple, we always exclude the
+  // |current_frame_index_|, since if we do end up drawing before the task runs,
+  // we won't emit an UMA entry for advancing to the next frame with no
+  // skipping.
+  return Optional<size_t>(frames_advanced - 1);
 }
 
 void BitmapImage::StopAnimation() {

third_party/WebKit/Source/platform/graphics/BitmapImage.h

@@ -39,6 +39,7 @@
 #include "platform/graphics/ImageOrientation.h"
 #include "platform/image-decoders/ImageAnimation.h"
 #include "platform/wtf/Forward.h"
+#include "platform/wtf/Optional.h"
 #include "platform/wtf/Time.h"
 #include "third_party/skia/include/core/SkRefCnt.h"
 
@@ -103,7 +104,7 @@ class PLATFORM_EXPORT BitmapImage final : public Image {
     task_runner_ = task_runner;
   }
 
-  size_t last_num_frames_skipped_for_testing() const {
+  Optional<size_t> last_num_frames_skipped_for_testing() const {
     return last_num_frames_skipped_;
   }
 
@@ -162,7 +163,10 @@ class PLATFORM_EXPORT BitmapImage final : public Image {
 
   bool ShouldAnimate();
   void StartAnimation() override;
-  void StartAnimationInternal(const double time);
+  // Starts the animation by scheduling a task to advance to the next desired
+  // frame, if possible, and catching up any frames if the time to display them
+  // is in the past.
+  Optional<size_t> StartAnimationInternal(const double time);
   void StopAnimation();
   void AdvanceAnimation(TimerBase*);
 
@@ -214,14 +218,16 @@ class PLATFORM_EXPORT BitmapImage final : public Image {
   double desired_frame_start_time_;  // The system time at which we hope to see
                                      // the next call to startAnimation().
 
-  size_t last_num_frames_skipped_ = 0u;
-
   size_t frame_count_;
 
   PaintImage::AnimationSequenceId reset_animation_sequence_id_ = 0;
 
   RefPtr<WebTaskRunner> task_runner_;
 
+  // Value used in UMA tracking for the number of animation frames skipped
+  // during catch-up.
+  Optional<size_t> last_num_frames_skipped_ = 0u;
+
   WTF::WeakPtrFactory<BitmapImage> weak_factory_;
 };
 

third_party/WebKit/Source/platform/graphics/BitmapImageTest.cpp

@@ -457,12 +457,15 @@ TEST_F(BitmapImageTestWithMockDecoder, AnimationPolicyOverride) {
 TEST_F(BitmapImageTestWithMockDecoder, FrameSkipTracking) {
   RuntimeEnabledFeatures::SetCompositorImageAnimationsEnabled(false);
 
-  repetition_count_ = kAnimationLoopInfinite;
-  frame_count_ = 5u;
-  last_frame_complete_ = true;
+  repetition_count_ = kAnimationLoopOnce;
+  frame_count_ = 7u;
+  last_frame_complete_ = false;
   duration_ = TimeDelta::FromSeconds(10);
   now_ = 10;
-  image_->SetData(SharedBuffer::Create("data", sizeof("data")), true);
+
+  // Start with an image that is incomplete, and the last frame is not fully
+  // received.
+  image_->SetData(SharedBuffer::Create("data", sizeof("data")), false);
 
   RefPtr<scheduler::FakeWebTaskRunner> task_runner =
       WTF::AdoptRef(new scheduler::FakeWebTaskRunner);
@@ -475,7 +478,7 @@ TEST_F(BitmapImageTestWithMockDecoder, FrameSkipTracking) {
   EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 0u);
 
   // No frames skipped since we just started the animation.
-  EXPECT_EQ(image_->last_num_frames_skipped_for_testing(), 0u);
+  EXPECT_EQ(image_->last_num_frames_skipped_for_testing().value(), 0u);
 
   // Advance the time to 15s. The frame is still at 0u because the posted task
   // should run at 20s.
@@ -486,6 +489,7 @@ TEST_F(BitmapImageTestWithMockDecoder, FrameSkipTracking) {
   // to 1u.
   task_runner->AdvanceTimeAndRun(5);
   EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 1u);
+  EXPECT_EQ(image_->last_num_frames_skipped_for_testing().value(), 0u);
 
   // Set now_ to 41 seconds. Since the animation started at 10s, and each frame
   // has a duration of 10s, we should see the fourth frame at 41 seconds.
@@ -493,17 +497,42 @@ TEST_F(BitmapImageTestWithMockDecoder, FrameSkipTracking) {
   task_runner->SetTime(41);
   StartAnimation();
   EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 3u);
-  EXPECT_EQ(image_->last_num_frames_skipped_for_testing(), 2u);
+  EXPECT_EQ(image_->last_num_frames_skipped_for_testing().value(), 1u);
 
-  // We should have scheduled a task to move to the last frame in
+  // We should have scheduled a task to move to the fifth frame in
   // StartAnimation above, at 50s.
   // Advance by 5s, not time for the next frame yet.
   task_runner->AdvanceTimeAndRun(5);
   EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 3u);
 
+  // Advance to the fifth frame.
   task_runner->SetTime(50);
   task_runner->AdvanceTimeAndRun(0);
   EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 4u);
+
+  // At 70s, we would want to display the last frame and would skip 1 frame.
+  // But because its incomplete, we advanced to the sixth frame and did not need
+  // to skip anything.
+  now_ = 71;
+  task_runner->SetTime(71);
+  StartAnimation();
+  EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 5u);
+  EXPECT_EQ(image_->last_num_frames_skipped_for_testing().value(), 0u);
+
+  // Run any pending tasks and try to animate again. Can't advance the animation
+  // because the last frame is not complete.
+  task_runner->AdvanceTimeAndRun(0);
+  StartAnimation();
+  EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 5u);
+  EXPECT_FALSE(image_->last_num_frames_skipped_for_testing().has_value());
+
+  // Finish the load and kick the animation again. It finishes during catch up.
+  // But no frame skipped because we just advanced to the last frame.
+  last_frame_complete_ = true;
+  image_->SetData(SharedBuffer::Create("data", sizeof("data")), true);
+  StartAnimation();
+  EXPECT_EQ(image_->PaintImageForCurrentFrame().frame_index(), 6u);
+  EXPECT_EQ(image_->last_num_frames_skipped_for_testing().value(), 0u);
 }
 
 TEST_F(BitmapImageTestWithMockDecoder, ResetAnimation) {

tools/metrics/histograms/histograms.xml

@@ -1410,6 +1410,21 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="AnimatedImage.NumOfFramesSkipped" units="count">
+  <owner>khushalsagar@chromium.org</owner>
+  <summary>
+    If the frame rate for the image animation can not be reached, frames in the
+    animation are skipped to catch up to the desired frame. This metric tracks
+    the number of frames skipped during catch up, and can be used to assess the
+    smoothness of these animations. It records the number of frames skipped each
+    time the animation is ticked forward to draw the next frame. In the ideal
+    case, where the animation can be drawn at the desired rate, 0 frames should
+    be skipped. Note that skipping of frames can also be triggered if the
+    animation was intentionally paused (on becoming off-screen, or the tab being
+    hidden).
+  </summary>
+</histogram>
+
 <histogram name="AppBanners.BeforeInstallEvent"
     enum="AppBannersBeforeInstallEvent">
   <owner>dominickn@chromium.org</owner>
@@ -102525,6 +102540,13 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   <affected-histogram name="RendererScheduler.TaskDurationPerQueueType2"/>
 </histogram_suffixes>
 
+<histogram_suffixes name="RendererThreadType" separator=".">
+  <suffix name="Main" label="Measurement taken on the main/render thread."/>
+  <suffix name="Compositor"
+      label="Measurement taken on the compositor thread."/>
+  <affected-histogram name="AnimatedImage.NumOfFramesSkipped"/>
+</histogram_suffixes>
+
 <histogram_suffixes name="RequestMediaKeySystemAccessKeySystems" separator=".">
   <suffix name="ClearKey" label="Requests for the Clear Key key system."/>
   <suffix name="Unknown"