[debug] Dcheck impl throughput

This CL adds a dcheck to ensure that the impl throughput did not
mis-calculate impl frames.

Bug: 1021963
Change-Id: Id582bf9f8fafc701b1de2d4e2a76f592a6e31171
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1991973
Commit-Queue: Xida Chen <xidachen@chromium.org>
Reviewed-by: Sadrul Chowdhury <sadrul@chromium.org>
Cr-Commit-Position: refs/heads/master@{#732367}

cc/metrics/frame_sequence_tracker.cc

@@ -163,7 +163,7 @@ bool FrameSequenceMetrics::HasDataLeftForReporting() const {
          main_throughput_.frames_expected > 0;
 }
 
-void FrameSequenceMetrics::ReportMetrics() {
+void FrameSequenceMetrics::ReportMetrics(const std::string& debug_trace) {
   DCHECK_LE(impl_throughput_.frames_produced, impl_throughput_.frames_expected);
   DCHECK_LE(main_throughput_.frames_produced, main_throughput_.frames_expected);
   TRACE_EVENT_ASYNC_END2(
@@ -176,6 +176,14 @@ void FrameSequenceMetrics::ReportMetrics() {
       type_, ThreadType::kCompositor,
       GetIndexForMetric(FrameSequenceMetrics::ThreadType::kCompositor, type_),
       impl_throughput_);
+#if DCHECK_IS_ON()
+  if (impl_throughput_percent.has_value()) {
+    DCHECK_EQ(impl_throughput_.frames_received,
+              impl_throughput_.frames_processed)
+        << debug_trace << " " << type_;
+  }
+#endif
+
   base::Optional<int> main_throughput_percent = ThroughputData::ReportHistogram(
       type_, ThreadType::kMain,
       GetIndexForMetric(FrameSequenceMetrics::ThreadType::kMain, type_),
@@ -358,8 +366,13 @@ void FrameSequenceTrackerCollection::NotifyFramePresented(
         metrics->Merge(std::move(accumulated_metrics_[tracker->type()]));
         accumulated_metrics_.erase(tracker->type());
       }
-      if (metrics->HasEnoughDataForReporting())
+      if (metrics->HasEnoughDataForReporting()) {
+#if DCHECK_IS_ON()
+        metrics->ReportMetrics(tracker->frame_sequence_trace_.str());
+#else
         metrics->ReportMetrics();
+#endif
+      }
       if (metrics->HasDataLeftForReporting())
         accumulated_metrics_[tracker->type()] = std::move(metrics);
     }
@@ -429,6 +442,9 @@ void FrameSequenceTracker::ScheduleTerminate() {
   if (last_processed_impl_sequence_ < last_started_impl_sequence_) {
     impl_throughput().frames_expected -=
         begin_impl_frame_data_.previous_sequence_delta;
+#if DCHECK_IS_ON()
+    --impl_throughput().frames_received;
+#endif
   }
 }
 
@@ -471,6 +487,9 @@ void FrameSequenceTracker::ReportBeginImplFrame(
                          args.frame_id.sequence_number);
   impl_throughput().frames_expected +=
       begin_impl_frame_data_.previous_sequence_delta;
+#if DCHECK_IS_ON()
+  ++impl_throughput().frames_received;
+#endif
 
   if (first_frame_timestamp_.is_null())
     first_frame_timestamp_ = args.frame_time;
@@ -546,6 +565,10 @@ void FrameSequenceTracker::ReportSubmitFrame(
 
 #if DCHECK_IS_ON()
   DCHECK(is_inside_frame_) << TRACKER_DCHECK_MSG;
+  DCHECK_LT(impl_throughput().frames_processed,
+            impl_throughput().frames_received)
+      << TRACKER_DCHECK_MSG;
+  ++impl_throughput().frames_processed;
 #endif
 
   last_processed_impl_sequence_ = ack.frame_id.sequence_number;
@@ -616,6 +639,12 @@ void FrameSequenceTracker::ReportFrameEnd(const viz::BeginFrameArgs& args) {
               impl_throughput().frames_produced)
         << TRACKER_DCHECK_MSG;
     --impl_throughput().frames_expected;
+#if DCHECK_IS_ON()
+    DCHECK_LT(impl_throughput().frames_processed,
+              impl_throughput().frames_received)
+        << TRACKER_DCHECK_MSG;
+    ++impl_throughput().frames_processed;
+#endif
     begin_impl_frame_data_.previous_sequence = 0;
   }
   frame_had_no_compositor_damage_ = false;

cc/metrics/frame_sequence_tracker.h

@@ -82,6 +82,10 @@ class CC_EXPORT FrameSequenceMetrics {
     void Merge(const ThroughputData& data) {
       frames_expected += data.frames_expected;
       frames_produced += data.frames_produced;
+#if DCHECK_IS_ON()
+      frames_processed += data.frames_processed;
+      frames_received += data.frames_received;
+#endif
     }
 
     // Tracks the number of frames that were expected to be shown during this
@@ -91,13 +95,22 @@ class CC_EXPORT FrameSequenceMetrics {
     // Tracks the number of frames that were actually presented to the user
     // during this frame-sequence.
     uint32_t frames_produced = 0;
+
+#if DCHECK_IS_ON()
+    // Tracks the number of frames that is either submitted or reported as no
+    // damage.
+    uint32_t frames_processed = 0;
+
+    // Tracks the number of begin-frames that are received.
+    uint32_t frames_received = 0;
+#endif
   };
 
   void Merge(std::unique_ptr<FrameSequenceMetrics> metrics);
   bool HasEnoughDataForReporting() const;
   bool HasDataLeftForReporting() const;
   // Report related metrics: throughput, checkboarding...
-  void ReportMetrics();
+  void ReportMetrics(const std::string& debug_trace = std::string());
 
   ThroughputData& impl_throughput() { return impl_throughput_; }
   ThroughputData& main_throughput() { return main_throughput_; }

cc/metrics/frame_sequence_tracker_unittest.cc

@@ -487,15 +487,20 @@ TEST_F(FrameSequenceTrackerTest, ReportMetricsAtFixedInterval) {
   // args.frame_time is less than 5s of the tracker creation time, so won't
   // schedule this tracker to report its throughput.
   collection_.NotifyBeginImplFrame(args);
+  collection_.NotifyImplFrameCausedNoDamage(viz::BeginFrameAck(args, false));
+  collection_.NotifyFrameEnd(args);
+
   EXPECT_EQ(NumberOfTrackers(), 1u);
   EXPECT_EQ(NumberOfRemovalTrackers(), 0u);
 
-  ImplThroughput().frames_expected += 100;
+  ImplThroughput().frames_expected += 101;
   // Now args.frame_time is 5s since the tracker creation time, so this tracker
   // should be scheduled to report its throughput.
   args = CreateBeginFrameArgs(source, ++sequence,
                               args.frame_time + TimeDeltaToReort());
   collection_.NotifyBeginImplFrame(args);
+  collection_.NotifyImplFrameCausedNoDamage(viz::BeginFrameAck(args, false));
+  collection_.NotifyFrameEnd(args);
   EXPECT_EQ(NumberOfTrackers(), 1u);
   EXPECT_EQ(NumberOfRemovalTrackers(), 1u);
 }