Long main thread work is not blocking Impl work being reported

During submit, if the frame is not activated yet, a copy of reporter at
Begin_Impl stage will be created and reported. This reporter is the
Begin_Impl portion of the existing reporter which is in Begin_main or
Commit stage.

So in the case of:
BI_1 BM_1 S_1 P_1 BI_2 C_1 A_1 S_2 P_2

In addition to:
BI_1 -> BM_1 -> C_1 A_1 S_2 P_2

This set will also be reported:
BI_1 -> S_1 -> P_1

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

cc/metrics/compositor_frame_reporter.cc

@@ -210,6 +210,24 @@ CompositorFrameReporter::CompositorFrameReporter(
       latency_ukm_reporter_(latency_ukm_reporter),
       frame_deadline_(frame_deadline) {}
 
+std::unique_ptr<CompositorFrameReporter>
+CompositorFrameReporter::CopyReporterAtBeginImplStage() const {
+  if (stage_history_.empty() ||
+      stage_history_.front().stage_type !=
+          StageType::kBeginImplFrameToSendBeginMainFrame ||
+      !did_finish_impl_frame())
+    return nullptr;
+  auto new_reporter = std::make_unique<CompositorFrameReporter>(
+      active_trackers_, frame_id_, frame_deadline_, latency_ukm_reporter_,
+      is_single_threaded_);
+  new_reporter->did_finish_impl_frame_ = did_finish_impl_frame_;
+  new_reporter->impl_frame_finish_time_ = impl_frame_finish_time_;
+  new_reporter->current_stage_.stage_type =
+      StageType::kBeginImplFrameToSendBeginMainFrame;
+  new_reporter->current_stage_.start_time = stage_history_.front().start_time;
+  return new_reporter;
+}
+
 CompositorFrameReporter::~CompositorFrameReporter() {
   TerminateReporter();
 }

cc/metrics/compositor_frame_reporter.h

@@ -131,6 +131,8 @@ class CC_EXPORT CompositorFrameReporter {
   CompositorFrameReporter& operator=(const CompositorFrameReporter& reporter) =
       delete;
 
+  std::unique_ptr<CompositorFrameReporter> CopyReporterAtBeginImplStage() const;
+
   const viz::BeginFrameId frame_id_;
 
   // Note that the started stage may be reported to UMA. If the histogram is

cc/metrics/compositor_frame_reporting_controller.cc

@@ -14,6 +14,7 @@
 namespace cc {
 namespace {
 using StageType = CompositorFrameReporter::StageType;
+using FrameTerminationStatus = CompositorFrameReporter::FrameTerminationStatus;
 }  // namespace
 
 CompositorFrameReportingController::CompositorFrameReportingController(
@@ -25,15 +26,13 @@ CompositorFrameReportingController::~CompositorFrameReportingController() {
   base::TimeTicks now = Now();
   for (int i = 0; i < PipelineStage::kNumPipelineStages; ++i) {
     if (reporters_[i]) {
-      reporters_[i]->TerminateFrame(
-          CompositorFrameReporter::FrameTerminationStatus::kDidNotProduceFrame,
-          now);
+      reporters_[i]->TerminateFrame(FrameTerminationStatus::kDidNotProduceFrame,
+                                    now);
     }
   }
   for (auto& pair : submitted_compositor_frames_) {
-    pair.reporter->TerminateFrame(
-        CompositorFrameReporter::FrameTerminationStatus::kDidNotPresentFrame,
-        Now());
+    pair.reporter->TerminateFrame(FrameTerminationStatus::kDidNotPresentFrame,
+                                  Now());
   }
 }
 
@@ -60,8 +59,7 @@ void CompositorFrameReportingController::WillBeginImplFrame(
     // If the the reporter is replaced in this stage, it means that Impl frame
     // caused no damage.
     reporters_[PipelineStage::kBeginImplFrame]->TerminateFrame(
-        CompositorFrameReporter::FrameTerminationStatus::kDidNotProduceFrame,
-        begin_time);
+        FrameTerminationStatus::kDidNotProduceFrame, begin_time);
   }
   std::unique_ptr<CompositorFrameReporter> reporter =
       std::make_unique<CompositorFrameReporter>(
@@ -102,10 +100,10 @@ void CompositorFrameReportingController::WillBeginMainFrame(
 
 void CompositorFrameReportingController::BeginMainFrameAborted(
     const viz::BeginFrameId& id) {
-  DCHECK(reporters_[PipelineStage::kBeginMainFrame]);
-  DCHECK_EQ(reporters_[PipelineStage::kBeginMainFrame]->frame_id_, id);
-  auto& begin_main_reporter = reporters_[PipelineStage::kBeginMainFrame];
-  begin_main_reporter->OnAbortBeginMainFrame(Now());
+  auto& reporter = reporters_[PipelineStage::kBeginMainFrame];
+  DCHECK(reporter);
+  DCHECK_EQ(reporter->frame_id_, id);
+  reporter->OnAbortBeginMainFrame(Now());
 }
 
 void CompositorFrameReportingController::WillCommit() {
@@ -162,7 +160,9 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame(
   } else {
     // There is no Main damage, which is possible if (1) there was no beginMain
     // so the reporter in beginImpl will be submitted or (2) the beginMain is
-    // sent and aborted, so the reporter in beginMain will be submitted.
+    // sent and aborted, so the reporter in beginMain will be submitted or (3)
+    // the main thread work is not done yet and the impl portion should be
+    // reported.
     if (CanSubmitImplFrame(current_frame_id)) {
       auto& reporter = reporters_[PipelineStage::kBeginImplFrame];
       reporter->StartStage(StageType::kEndActivateToSubmitCompositorFrame,
@@ -176,7 +176,16 @@ void CompositorFrameReportingController::DidSubmitCompositorFrame(
       AdvanceReporterStage(PipelineStage::kBeginMainFrame,
                            PipelineStage::kActivate);
     } else {
-      return;
+      // The submitted frame might have unfinished main thread work, which in
+      // that case the BeginImpl portion can be reported.
+      auto reporter = RestoreReporterAtBeginImpl(current_frame_id);
+      // The method will return nullptr if Impl reporter has been submitted
+      // prior to BeginMainFrame.
+      if (!reporter)
+        return;
+      reporter->StartStage(StageType::kEndActivateToSubmitCompositorFrame,
+                           reporter->impl_frame_finish_time());
+      reporters_[PipelineStage::kActivate] = std::move(reporter);
     }
   }
 
@@ -195,8 +204,7 @@ void CompositorFrameReportingController::DidNotProduceFrame(
   for (auto& stage_reporter : reporters_) {
     if (stage_reporter && stage_reporter->frame_id_ == id) {
       stage_reporter->TerminateFrame(
-          CompositorFrameReporter::FrameTerminationStatus::kDidNotProduceFrame,
-          Now());
+          FrameTerminationStatus::kDidNotProduceFrame, Now());
       return;
     }
   }
@@ -209,8 +217,7 @@ void CompositorFrameReportingController::OnFinishImplFrame(
     reporters_[PipelineStage::kBeginImplFrame]->OnFinishImplFrame(Now());
   } else if (reporters_[PipelineStage::kBeginMainFrame]) {
     DCHECK_EQ(reporters_[PipelineStage::kBeginMainFrame]->frame_id_, id);
-    auto& begin_main_reporter = reporters_[PipelineStage::kBeginMainFrame];
-    begin_main_reporter->OnFinishImplFrame(Now());
+    reporters_[PipelineStage::kBeginMainFrame]->OnFinishImplFrame(Now());
   }
 }
 
@@ -222,11 +229,9 @@ void CompositorFrameReportingController::DidPresentCompositorFrame(
     if (viz::FrameTokenGT(submitted_frame->frame_token, frame_token))
       break;
 
-    auto termination_status =
-        CompositorFrameReporter::FrameTerminationStatus::kPresentedFrame;
+    auto termination_status = FrameTerminationStatus::kPresentedFrame;
     if (submitted_frame->frame_token != frame_token)
-      termination_status =
-          CompositorFrameReporter::FrameTerminationStatus::kDidNotPresentFrame;
+      termination_status = FrameTerminationStatus::kDidNotPresentFrame;
 
     submitted_frame->reporter->SetVizBreakdown(details);
     submitted_frame->reporter->TerminateFrame(
@@ -258,8 +263,7 @@ void CompositorFrameReportingController::AdvanceReporterStage(
     PipelineStage target) {
   if (reporters_[target]) {
     reporters_[target]->TerminateFrame(
-        CompositorFrameReporter::FrameTerminationStatus::kReplacedByNewReporter,
-        Now());
+        FrameTerminationStatus::kReplacedByNewReporter, Now());
   }
   reporters_[target] = std::move(reporters_[start]);
 }
@@ -281,6 +285,18 @@ bool CompositorFrameReportingController::CanSubmitMainFrame(
           reporter->did_abort_main_frame());
 }
 
+std::unique_ptr<CompositorFrameReporter>
+CompositorFrameReportingController::RestoreReporterAtBeginImpl(
+    const viz::BeginFrameId& id) {
+  auto& main_reporter = reporters_[PipelineStage::kBeginMainFrame];
+  auto& commit_reporter = reporters_[PipelineStage::kCommit];
+  if (main_reporter && main_reporter->frame_id_ == id)
+    return main_reporter->CopyReporterAtBeginImplStage();
+  if (commit_reporter && commit_reporter->frame_id_ == id)
+    return commit_reporter->CopyReporterAtBeginImplStage();
+  return nullptr;
+}
+
 void CompositorFrameReportingController::SetUkmManager(UkmManager* manager) {
   latency_ukm_reporter_->SetUkmManager(manager);
 }

cc/metrics/compositor_frame_reporting_controller.h

@@ -97,6 +97,8 @@ class CC_EXPORT CompositorFrameReportingController {
   void AdvanceReporterStage(PipelineStage start, PipelineStage target);
   bool CanSubmitImplFrame(const viz::BeginFrameId& id) const;
   bool CanSubmitMainFrame(const viz::BeginFrameId& id) const;
+  std::unique_ptr<CompositorFrameReporter> RestoreReporterAtBeginImpl(
+      const viz::BeginFrameId& id);
 
   viz::BeginFrameId last_submitted_frame_id_;
 

cc/metrics/compositor_frame_reporting_controller_unittest.cc

@@ -152,19 +152,28 @@ TEST_F(CompositorFrameReportingControllerTest, ActiveReporterCounts) {
   // - 2 back-to-back BeginImplFrames
   // - 4 Simultaneous Reporters
 
+  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);
+
+  viz::BeginFrameId current_id_3(1, 3);
+  viz::BeginFrameArgs args_3 = SimulateBeginFrameArgs(current_id_3);
+
   // BF
-  reporting_controller_.WillBeginImplFrame(args_);
+  reporting_controller_.WillBeginImplFrame(args_1);
   EXPECT_EQ(1, reporting_controller_.ActiveReporters());
 
   // BF -> BF
   // Should replace previous reporter.
-  reporting_controller_.WillBeginImplFrame(args_);
+  reporting_controller_.WillBeginImplFrame(args_2);
   EXPECT_EQ(1, reporting_controller_.ActiveReporters());
 
   // BF -> BMF -> BF
   // Should add new reporter.
-  reporting_controller_.WillBeginMainFrame(args_);
-  reporting_controller_.WillBeginImplFrame(args_);
+  reporting_controller_.WillBeginMainFrame(args_2);
+  reporting_controller_.WillBeginImplFrame(args_3);
   EXPECT_EQ(2, reporting_controller_.ActiveReporters());
 
   // BF -> BMF -> BF -> Commit
@@ -175,18 +184,25 @@ TEST_F(CompositorFrameReportingControllerTest, ActiveReporterCounts) {
 
   // BF -> BMF -> BF -> Commit -> BMF -> Activate -> Commit -> Activation
   // Having two reporters at Activate phase should delete the older one.
-  reporting_controller_.WillBeginMainFrame(args_);
+  reporting_controller_.WillBeginMainFrame(args_3);
   reporting_controller_.WillActivate();
   reporting_controller_.DidActivate();
-  last_activated_id_ = current_id_;
+
+  // There is a reporters tracking frame_3 in BeginMain state and one reporter
+  // for frame_2 in activate state.
+  EXPECT_EQ(2, reporting_controller_.ActiveReporters());
+
   reporting_controller_.WillCommit();
   reporting_controller_.DidCommit();
   reporting_controller_.WillActivate();
   reporting_controller_.DidActivate();
+  // Reporter in activate state for frame_2 is overwritten by the reporter for
+  // frame_3.
   EXPECT_EQ(1, reporting_controller_.ActiveReporters());
 
+  last_activated_id_ = current_id_3;
   reporting_controller_.DidSubmitCompositorFrame(
-      0, current_id_, last_activated_id_, std::vector<EventMetrics>());
+      0, current_id_3, last_activated_id_, std::vector<EventMetrics>());
   EXPECT_EQ(0, reporting_controller_.ActiveReporters());
 
   // 4 simultaneous reporters active.
@@ -412,6 +428,64 @@ TEST_F(CompositorFrameReportingControllerTest, MainFrameAborted2) {
       3);
 }
 
+TEST_F(CompositorFrameReportingControllerTest, LongMainFrame) {
+  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);
+
+  viz::FrameTimingDetails details = {};
+  reporting_controller_.WillBeginImplFrame(args_1);
+  reporting_controller_.OnFinishImplFrame(current_id_1);
+  reporting_controller_.WillBeginMainFrame(args_1);
+  reporting_controller_.WillCommit();
+  reporting_controller_.DidCommit();
+  reporting_controller_.WillActivate();
+  reporting_controller_.DidActivate();
+  reporting_controller_.DidSubmitCompositorFrame(1, current_id_1, current_id_1,
+                                                 std::vector<EventMetrics>());
+  reporting_controller_.DidPresentCompositorFrame(1, details);
+
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.BeginImplFrameToSendBeginMainFrame", 1);
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.SendBeginMainFrameToCommit", 1);
+  histogram_tester.ExpectTotalCount("CompositorLatency.Commit", 1);
+  histogram_tester.ExpectTotalCount("CompositorLatency.EndCommitToActivation",
+                                    1);
+  histogram_tester.ExpectTotalCount("CompositorLatency.Activation", 1);
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.EndActivateToSubmitCompositorFrame", 1);
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.SubmitCompositorFrameToPresentationCompositorFrame",
+      1);
+
+  // Second frame will not have the main frame update ready and will only submit
+  // the Impl update
+  reporting_controller_.WillBeginImplFrame(args_2);
+  reporting_controller_.WillBeginMainFrame(args_2);
+  reporting_controller_.OnFinishImplFrame(current_id_2);
+  reporting_controller_.DidSubmitCompositorFrame(2, current_id_2, current_id_1,
+                                                 std::vector<EventMetrics>());
+  reporting_controller_.DidPresentCompositorFrame(2, details);
+
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.BeginImplFrameToSendBeginMainFrame", 2);
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.SendBeginMainFrameToCommit", 1);
+  histogram_tester.ExpectTotalCount("CompositorLatency.Commit", 1);
+  histogram_tester.ExpectTotalCount("CompositorLatency.EndCommitToActivation",
+                                    1);
+  histogram_tester.ExpectTotalCount("CompositorLatency.Activation", 1);
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.EndActivateToSubmitCompositorFrame", 2);
+  histogram_tester.ExpectTotalCount(
+      "CompositorLatency.SubmitCompositorFrameToPresentationCompositorFrame",
+      2);
+}
+
 TEST_F(CompositorFrameReportingControllerTest, BlinkBreakdown) {
   base::HistogramTester histogram_tester;