From 2f848d25a9b24859b0e4e1080aca7a414f531f85 Mon Sep 17 00:00:00 2001
From: Sadrul Habib Chowdhury <sadrul@chromium.org>
Date: Mon, 23 Dec 2019 16:34:09 +0000
Subject: [PATCH] [cc/metrics] Some more debug checks.

. Validate that main frame starts for the same compositor/impl frame.
. A 'no damage' response from the main-thread can only happen from the
  most recently started main-frame.
. Move the stream-logging before some early exits.

BUG=none

Change-Id: I4037070d9b87b3aa424ad14ad5ceb57969113d1a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1980311
Commit-Queue: Sadrul Chowdhury <sadrul@chromium.org>
Auto-Submit: Sadrul Chowdhury <sadrul@chromium.org>
Reviewed-by: Xida Chen <xidachen@chromium.org>
Cr-Commit-Position: refs/heads/master@{#727168}
---
 cc/metrics/frame_sequence_tracker.cc | 25 ++++++++++++++++++++-----
 cc/metrics/frame_sequence_tracker.h  |  2 ++
 2 files changed, 22 insertions(+), 5 deletions(-)

diff --git a/cc/metrics/frame_sequence_tracker.cc b/cc/metrics/frame_sequence_tracker.cc
index e9ebfc58210bca..9010d82d4eb18c 100644
--- a/cc/metrics/frame_sequence_tracker.cc
+++ b/cc/metrics/frame_sequence_tracker.cc
@@ -429,9 +429,14 @@ void FrameSequenceTracker::ReportBeginImplFrame(
   if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
     return;
 
+  TRACKER_TRACE_STREAM << "b(" << args.frame_id.sequence_number << ")";
+
 #if DCHECK_IS_ON()
   DCHECK(!is_inside_frame_) << TRACKER_DCHECK_MSG;
   is_inside_frame_ = true;
+
+  DCHECK_EQ(last_started_impl_sequence_, 0u) << TRACKER_DCHECK_MSG;
+  DCHECK_EQ(last_processed_impl_sequence_, 0u) << TRACKER_DCHECK_MSG;
   last_started_impl_sequence_ = args.frame_id.sequence_number;
 
   if (args.type == viz::BeginFrameArgs::NORMAL)
@@ -444,7 +449,6 @@ void FrameSequenceTracker::ReportBeginImplFrame(
     reset_all_state_ = false;
   }
 
-  TRACKER_TRACE_STREAM << "b(" << args.frame_id.sequence_number << ")";
   DCHECK(!frame_had_no_compositor_damage_) << TRACKER_DCHECK_MSG;
   DCHECK(!compositor_frame_submitted_) << TRACKER_DCHECK_MSG;
 
@@ -475,6 +479,9 @@ void FrameSequenceTracker::ReportBeginMainFrame(
   if (args.type == viz::BeginFrameArgs::NORMAL) {
     DCHECK(impl_frames_.contains(args.frame_id));
   }
+  last_started_main_sequence_ = args.frame_id.sequence_number;
+  DCHECK_EQ(last_started_impl_sequence_, last_started_main_sequence_)
+      << TRACKER_DCHECK_MSG;
 #endif
 
   UpdateTrackedFrameData(&begin_main_frame_data_, args.frame_id.source_id,
@@ -580,6 +587,7 @@ void FrameSequenceTracker::ReportFrameEnd(const viz::BeginFrameArgs& args) {
   DCHECK_EQ(last_started_impl_sequence_, last_processed_impl_sequence_)
       << TRACKER_DCHECK_MSG;
   is_inside_frame_ = false;
+  last_started_impl_sequence_ = last_processed_impl_sequence_ = 0;
 #endif
 }
 
@@ -605,11 +613,11 @@ void FrameSequenceTracker::ReportFramePresented(
     return;
   }
 
+  TRACKER_TRACE_STREAM << "P(" << frame_token << ")";
+
   if (ignored_frame_tokens_.contains(frame_token))
     return;
 
-  TRACKER_TRACE_STREAM << "P(" << frame_token << ")";
-
   TRACE_EVENT_ASYNC_STEP_INTO_WITH_TIMESTAMP0(
       "cc,benchmark", "FrameSequenceTracker", metrics_.get(), "FramePresented",
       feedback.timestamp);
@@ -706,11 +714,12 @@ void FrameSequenceTracker::ReportMainFrameCausedNoDamage(
   if (ShouldIgnoreBeginFrameSource(args.frame_id.source_id))
     return;
 
+  TRACKER_TRACE_STREAM << "N(" << begin_main_frame_data_.previous_sequence
+                       << "," << args.frame_id.sequence_number << ")";
+
   if (ShouldIgnoreSequence(args.frame_id.sequence_number))
     return;
 
-  TRACKER_TRACE_STREAM << "N(" << begin_main_frame_data_.previous_sequence
-                       << "," << args.frame_id.sequence_number << ")";
   if (last_no_main_damage_sequence_ == args.frame_id.sequence_number)
     return;
 
@@ -725,6 +734,12 @@ void FrameSequenceTracker::ReportMainFrameCausedNoDamage(
 
   if (begin_main_frame_data_.previous_sequence == args.frame_id.sequence_number)
     begin_main_frame_data_.previous_sequence = 0;
+
+#if DCHECK_IS_ON()
+  DCHECK_EQ(last_started_main_sequence_, args.frame_id.sequence_number)
+      << TRACKER_DCHECK_MSG;
+  last_started_main_sequence_ = 0;
+#endif
 }
 
 void FrameSequenceTracker::PauseFrameProduction() {
diff --git a/cc/metrics/frame_sequence_tracker.h b/cc/metrics/frame_sequence_tracker.h
index 1c77b56c1ac434..1d8354db9c111c 100644
--- a/cc/metrics/frame_sequence_tracker.h
+++ b/cc/metrics/frame_sequence_tracker.h
@@ -409,6 +409,8 @@ class CC_EXPORT FrameSequenceTracker {
   uint64_t last_started_impl_sequence_ = 0;
   uint64_t last_processed_impl_sequence_ = 0;
 
+  uint64_t last_started_main_sequence_ = 0;
+
   // If ReportBeginImplFrame is never called on a arg, then ReportBeginMainFrame
   // should ignore that arg.
   base::flat_set<viz::BeginFrameId> impl_frames_;