[cc/metrics] Fix detecting some 'dropped frames'.

If a frame is not produced, and the reason is anything other than
'no damage', (e.g. if draw is aborted because of checkerboarding
etc.), then mark that frame as a 'dropped frame'.

BUG=790761

Change-Id: I9783563fe2d8e87fa0fabad91895fc238b8050b5
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2147694
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: Behdad Bakhshinategh <behdadb@chromium.org>
Cr-Commit-Position: refs/heads/master@{#759917}

cc/metrics/compositor_frame_reporter.cc

@@ -289,8 +289,10 @@ void CompositorFrameReporter::OnAbortBeginMainFrame(base::TimeTicks timestamp) {
   // stage
 }
 
-void CompositorFrameReporter::OnDidNotProduceFrame() {
+void CompositorFrameReporter::OnDidNotProduceFrame(
+    FrameSkippedReason skip_reason) {
   did_not_produce_frame_time_ = base::TimeTicks::Now();
+  frame_skip_reason_ = skip_reason;
 }
 
 void CompositorFrameReporter::SetBlinkBreakdown(
@@ -354,6 +356,12 @@ void CompositorFrameReporter::TerminateReporter() {
       break;
     case FrameTerminationStatus::kDidNotProduceFrame:
       termination_status_str = "did_not_produce_frame";
+      if (!frame_skip_reason_.has_value() ||
+          frame_skip_reason() != FrameSkippedReason::kNoDamage) {
+        report_compositor_latency = true;
+        DroppedFrame();
+        termination_status_str = "dropped_frame";
+      }
       break;
     case FrameTerminationStatus::kUnknown:
       termination_status_str = "terminated_before_ending";

cc/metrics/compositor_frame_reporter.h

@@ -16,6 +16,7 @@
 #include "cc/metrics/begin_main_frame_metrics.h"
 #include "cc/metrics/event_metrics.h"
 #include "cc/metrics/frame_sequence_tracker.h"
+#include "cc/scheduler/scheduler.h"
 #include "components/viz/common/frame_sinks/begin_frame_args.h"
 #include "components/viz/common/frame_timing_details.h"
 
@@ -150,7 +151,7 @@ class CC_EXPORT CompositorFrameReporter {
 
   void OnFinishImplFrame(base::TimeTicks timestamp);
   void OnAbortBeginMainFrame(base::TimeTicks timestamp);
-  void OnDidNotProduceFrame();
+  void OnDidNotProduceFrame(FrameSkippedReason skip_reason);
   bool did_finish_impl_frame() const { return did_finish_impl_frame_; }
   base::TimeTicks impl_frame_finish_time() const {
     return impl_frame_finish_time_;
@@ -170,6 +171,8 @@ class CC_EXPORT CompositorFrameReporter {
     return *main_frame_abort_time_;
   }
 
+  FrameSkippedReason frame_skip_reason() const { return *frame_skip_reason_; }
+
  private:
   void DroppedFrame();
   void MissedDeadlineFrame();
@@ -250,6 +253,7 @@ class CC_EXPORT CompositorFrameReporter {
   // The timestamp of when the frame was marked as not having produced a frame
   // (through a call to DidNotProduceFrame()).
   base::Optional<base::TimeTicks> did_not_produce_frame_time_;
+  base::Optional<FrameSkippedReason> frame_skip_reason_;
   base::Optional<base::TimeTicks> main_frame_abort_time_;
 };
 }  // namespace cc

cc/metrics/compositor_frame_reporting_controller.cc

@@ -61,10 +61,11 @@ void CompositorFrameReportingController::WillBeginImplFrame(
     const viz::BeginFrameArgs& args) {
   base::TimeTicks begin_time = Now();
   if (reporters_[PipelineStage::kBeginImplFrame]) {
-    // If the the reporter is replaced in this stage, it means that Impl frame
-    // caused no damage.
-    reporters_[PipelineStage::kBeginImplFrame]->TerminateFrame(
-        FrameTerminationStatus::kDidNotProduceFrame, begin_time);
+    auto& reporter = reporters_[PipelineStage::kBeginImplFrame];
+    DCHECK(reporter->did_finish_impl_frame());
+    DCHECK(reporter->did_not_produce_frame());
+    reporter->TerminateFrame(FrameTerminationStatus::kDidNotProduceFrame,
+                             reporter->did_not_produce_frame_time());
   }
   std::unique_ptr<CompositorFrameReporter> reporter =
       std::make_unique<CompositorFrameReporter>(
@@ -251,7 +252,8 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame(
 }
 
 void CompositorFrameReportingController::DidNotProduceFrame(
-    const viz::BeginFrameId& id) {
+    const viz::BeginFrameId& id,
+    FrameSkippedReason skip_reason) {
   for (auto& stage_reporter : reporters_) {
     if (stage_reporter && stage_reporter->frame_id_ == id) {
       // The reporter will be flagged and terminated when replaced by another
@@ -261,7 +263,7 @@ void CompositorFrameReportingController::DidNotProduceFrame(
       // long, then DidNotProduceFrame() is called for the reporter in the
       // BeginMain stage, but the main-thread can make updates, which can be
       // submitted with the next frame.
-      stage_reporter->OnDidNotProduceFrame();
+      stage_reporter->OnDidNotProduceFrame(skip_reason);
       return;
     }
   }
@@ -303,6 +305,7 @@ void CompositorFrameReportingController::OnStoppedRequestingBeginFrames() {
   auto now = Now();
   for (int i = 0; i < PipelineStage::kNumPipelineStages; ++i) {
     if (reporters_[i]) {
+      reporters_[i]->OnDidNotProduceFrame(FrameSkippedReason::kNoDamage);
       reporters_[i]->TerminateFrame(FrameTerminationStatus::kDidNotProduceFrame,
                                     now);
     }

cc/metrics/compositor_frame_reporting_controller.h

@@ -60,7 +60,8 @@ class CC_EXPORT CompositorFrameReportingController {
       const viz::BeginFrameId& current_frame_id,
       const viz::BeginFrameId& last_activated_frame_id,
       EventMetricsSet events_metrics);
-  virtual void DidNotProduceFrame(const viz::BeginFrameId& id);
+  virtual void DidNotProduceFrame(const viz::BeginFrameId& id,
+                                  FrameSkippedReason skip_reason);
   virtual void OnFinishImplFrame(const viz::BeginFrameId& id);
   virtual void DidPresentCompositorFrame(
       uint32_t frame_token,

cc/metrics/compositor_frame_reporting_controller_unittest.cc

@@ -45,6 +45,12 @@ class TestCompositorFrameReportingController
     }
     return count;
   }
+
+  void ResetReporters() {
+    for (int i = 0; i < PipelineStage::kNumPipelineStages; ++i) {
+      reporters()[i] = nullptr;
+    }
+  }
 };
 
 class CompositorFrameReportingControllerTest : public testing::Test {
@@ -56,6 +62,7 @@ class CompositorFrameReportingControllerTest : public testing::Test {
   // The following functions simulate the actions that would
   // occur for each phase of the reporting controller.
   void SimulateBeginImplFrame() {
+    IncrementCurrentId();
     reporting_controller_.WillBeginImplFrame(args_);
   }
 
@@ -164,11 +171,17 @@ TEST_F(CompositorFrameReportingControllerTest, ActiveReporterCounts) {
   // BF
   reporting_controller_.WillBeginImplFrame(args_1);
   EXPECT_EQ(1, reporting_controller_.ActiveReporters());
+  reporting_controller_.OnFinishImplFrame(args_1.frame_id);
+  reporting_controller_.DidNotProduceFrame(args_1.frame_id,
+                                           FrameSkippedReason::kNoDamage);
 
   // BF -> BF
   // Should replace previous reporter.
   reporting_controller_.WillBeginImplFrame(args_2);
   EXPECT_EQ(1, reporting_controller_.ActiveReporters());
+  reporting_controller_.OnFinishImplFrame(args_2.frame_id);
+  reporting_controller_.DidNotProduceFrame(args_2.frame_id,
+                                           FrameSkippedReason::kNoDamage);
 
   // BF -> BMF -> BF
   // Should add new reporter.
@@ -205,21 +218,46 @@ TEST_F(CompositorFrameReportingControllerTest, ActiveReporterCounts) {
                                                  last_activated_id_, {});
   EXPECT_EQ(0, reporting_controller_.ActiveReporters());
 
-  // 4 simultaneous reporters active.
+  // Start a frame and take it all the way to the activate stage.
   SimulateActivate();
+  EXPECT_EQ(1, reporting_controller_.ActiveReporters());
 
+  // Start another frame and let it progress up to the commit stage.
   SimulateCommit(nullptr);
+  EXPECT_EQ(2, reporting_controller_.ActiveReporters());
 
+  // Start the next frame, and let it progress up to the main-frame.
   SimulateBeginMainFrame();
+  EXPECT_EQ(3, reporting_controller_.ActiveReporters());
 
+  // Start the next frame.
   SimulateBeginImplFrame();
   EXPECT_EQ(4, reporting_controller_.ActiveReporters());
 
+  reporting_controller_.OnFinishImplFrame(args_.frame_id);
+  reporting_controller_.DidNotProduceFrame(args_.frame_id,
+                                           FrameSkippedReason::kNoDamage);
+
   // Any additional BeginImplFrame's would be ignored.
   SimulateBeginImplFrame();
   EXPECT_EQ(4, reporting_controller_.ActiveReporters());
 }
 
+TEST_F(CompositorFrameReportingControllerTest,
+       StopRequestingFramesCancelsInFlightFrames) {
+  base::HistogramTester histogram_tester;
+
+  // 2 reporters active.
+  SimulateActivate();
+  SimulateCommit(nullptr);
+
+  reporting_controller_.OnStoppedRequestingBeginFrames();
+  reporting_controller_.ResetReporters();
+  histogram_tester.ExpectBucketCount(
+      "CompositorLatency.Type",
+      CompositorFrameReporter::FrameReportType::kDroppedFrame, 0);
+}
+
 TEST_F(CompositorFrameReportingControllerTest,
        SubmittedFrameHistogramReporting) {
   base::HistogramTester histogram_tester;
@@ -286,9 +324,25 @@ TEST_F(CompositorFrameReportingControllerTest, ImplFrameCausedNoDamage) {
   base::HistogramTester histogram_tester;
 
   SimulateBeginImplFrame();
+  reporting_controller_.OnFinishImplFrame(args_.frame_id);
+  reporting_controller_.DidNotProduceFrame(args_.frame_id,
+                                           FrameSkippedReason::kNoDamage);
   SimulateBeginImplFrame();
   histogram_tester.ExpectTotalCount(
       "CompositorLatency.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 0);
+  histogram_tester.ExpectBucketCount(
+      "CompositorLatency.Type",
+      CompositorFrameReporter::FrameReportType::kDroppedFrame, 0);
+
+  reporting_controller_.OnFinishImplFrame(args_.frame_id);
+  reporting_controller_.DidNotProduceFrame(args_.frame_id,
+                                           FrameSkippedReason::kWaitingOnMain);
+  SimulateBeginImplFrame();
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.DroppedFrame.BeginImplFrameToSendBeginMainFrame", 1);
+  histogram_tester.ExpectBucketCount(
+      "CompositorLatency.Type",
+      CompositorFrameReporter::FrameReportType::kDroppedFrame, 1);
 }
 
 TEST_F(CompositorFrameReportingControllerTest, MainFrameCausedNoDamage) {
@@ -306,13 +360,15 @@ TEST_F(CompositorFrameReportingControllerTest, MainFrameCausedNoDamage) {
   reporting_controller_.WillBeginMainFrame(args_1);
   reporting_controller_.BeginMainFrameAborted(current_id_1);
   reporting_controller_.OnFinishImplFrame(current_id_1);
-  reporting_controller_.DidNotProduceFrame(current_id_1);
+  reporting_controller_.DidNotProduceFrame(current_id_1,
+                                           FrameSkippedReason::kNoDamage);
 
   reporting_controller_.WillBeginImplFrame(args_2);
   reporting_controller_.WillBeginMainFrame(args_2);
   reporting_controller_.OnFinishImplFrame(current_id_2);
   reporting_controller_.BeginMainFrameAborted(current_id_2);
-  reporting_controller_.DidNotProduceFrame(current_id_2);
+  reporting_controller_.DidNotProduceFrame(current_id_2,
+                                           FrameSkippedReason::kNoDamage);
 
   reporting_controller_.WillBeginImplFrame(args_3);
   reporting_controller_.WillBeginMainFrame(args_3);
@@ -335,7 +391,8 @@ TEST_F(CompositorFrameReportingControllerTest, DidNotProduceFrame) {
   reporting_controller_.WillBeginImplFrame(args_1);
   reporting_controller_.WillBeginMainFrame(args_1);
   reporting_controller_.OnFinishImplFrame(current_id_1);
-  reporting_controller_.DidNotProduceFrame(current_id_1);
+  reporting_controller_.DidNotProduceFrame(current_id_1,
+                                           FrameSkippedReason::kNoDamage);
 
   reporting_controller_.WillBeginImplFrame(args_2);
   reporting_controller_.OnFinishImplFrame(current_id_2);
@@ -367,6 +424,60 @@ TEST_F(CompositorFrameReportingControllerTest, DidNotProduceFrame) {
       2);
 }
 
+TEST_F(CompositorFrameReportingControllerTest,
+       DidNotProduceFrameDueToWaitingOnMain) {
+  base::HistogramTester histogram_tester;
+
+  viz::BeginFrameId current_id_1(1, 1);
+  viz::BeginFrameArgs args_1 = SimulateBeginFrameArgs(current_id_1);
+
+  viz::BeginFrameId current_id_2(1, 2);
+  viz::BeginFrameArgs args_2 = SimulateBeginFrameArgs(current_id_2);
+  args_2.frame_time = args_1.frame_time + args_1.interval;
+
+  viz::BeginFrameId current_id_3(1, 3);
+  viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3);
+  args_3.frame_time = args_2.frame_time + args_2.interval;
+
+  reporting_controller_.WillBeginImplFrame(args_1);
+  reporting_controller_.WillBeginMainFrame(args_1);
+  reporting_controller_.OnFinishImplFrame(current_id_1);
+  reporting_controller_.DidNotProduceFrame(current_id_1,
+                                           FrameSkippedReason::kWaitingOnMain);
+
+  reporting_controller_.WillBeginImplFrame(args_2);
+  reporting_controller_.OnFinishImplFrame(current_id_2);
+  reporting_controller_.DidNotProduceFrame(current_id_2,
+                                           FrameSkippedReason::kWaitingOnMain);
+
+  reporting_controller_.WillBeginImplFrame(args_3);
+  reporting_controller_.WillCommit();
+  reporting_controller_.DidCommit();
+  reporting_controller_.WillActivate();
+  reporting_controller_.DidActivate();
+  reporting_controller_.OnFinishImplFrame(current_id_3);
+  reporting_controller_.DidSubmitCompositorFrame(1, current_id_3, current_id_1,
+                                                 {});
+  viz::FrameTimingDetails details;
+  details.presentation_feedback = {args_3.frame_time + args_3.interval,
+                                   args_3.interval, 0};
+  reporting_controller_.DidPresentCompositorFrame(1, details);
+
+  // Frame for |args_2| was dropped waiting on the main-thread.
+  histogram_tester.ExpectBucketCount(
+      "CompositorLatency.Type",
+      CompositorFrameReporter::FrameReportType::kDroppedFrame, 1);
+
+  // Frames for |args_1| and |args_3| were presented, although |args_1| missed
+  // its deadline.
+  histogram_tester.ExpectBucketCount(
+      "CompositorLatency.Type",
+      CompositorFrameReporter::FrameReportType::kNonDroppedFrame, 2);
+  histogram_tester.ExpectBucketCount(
+      "CompositorLatency.Type",
+      CompositorFrameReporter::FrameReportType::kMissedDeadlineFrame, 1);
+}
+
 TEST_F(CompositorFrameReportingControllerTest, MainFrameAborted) {
   base::HistogramTester histogram_tester;
 

cc/metrics/compositor_timing_history.cc

@@ -952,8 +952,10 @@ void CompositorTimingHistory::DidSubmitCompositorFrame(
   submit_start_time_ = Now();
 }
 
-void CompositorTimingHistory::DidNotProduceFrame(const viz::BeginFrameId& id) {
-  compositor_frame_reporting_controller_->DidNotProduceFrame(id);
+void CompositorTimingHistory::DidNotProduceFrame(
+    const viz::BeginFrameId& id,
+    FrameSkippedReason skip_reason) {
+  compositor_frame_reporting_controller_->DidNotProduceFrame(id, skip_reason);
 }
 
 void CompositorTimingHistory::DidReceiveCompositorFrameAck() {

cc/metrics/compositor_timing_history.h

@@ -11,6 +11,7 @@
 #include "cc/base/rolling_time_delta_history.h"
 #include "cc/cc_export.h"
 #include "cc/metrics/event_metrics.h"
+#include "cc/scheduler/scheduler.h"
 #include "cc/tiles/tile_priority.h"
 #include "components/viz/common/frame_sinks/begin_frame_args.h"
 
@@ -100,7 +101,8 @@ class CC_EXPORT CompositorTimingHistory {
       const viz::BeginFrameId& current_frame_id,
       const viz::BeginFrameId& last_activated_frame_id,
       EventMetricsSet events_metrics);
-  void DidNotProduceFrame(const viz::BeginFrameId& id);
+  void DidNotProduceFrame(const viz::BeginFrameId& id,
+                          FrameSkippedReason skip_reason);
   void DidReceiveCompositorFrameAck();
   void DidPresentCompositorFrame(uint32_t frame_token,
                                  const viz::FrameTimingDetails& details);

cc/scheduler/scheduler.cc

@@ -607,8 +607,7 @@ void Scheduler::SendDidNotProduceFrame(const viz::BeginFrameArgs& args,
     return;
   last_begin_frame_ack_ = viz::BeginFrameAck(args, false /* has_damage */);
   client_->DidNotProduceFrame(last_begin_frame_ack_, reason);
-  if (reason == FrameSkippedReason::kNoDamage)
-    compositor_timing_history_->DidNotProduceFrame(args.frame_id);
+  compositor_timing_history_->DidNotProduceFrame(args.frame_id, reason);
 }
 
 // BeginImplFrame starts a compositor frame that will wait up until a deadline