From 675c2d74e178c64620c155c1953d216336224732 Mon Sep 17 00:00:00 2001 From: Xida Chen Date: Thu, 16 Jan 2020 13:06:48 +0000 Subject: [PATCH] [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 Reviewed-by: Sadrul Chowdhury Cr-Commit-Position: refs/heads/master@{#732367} --- cc/metrics/frame_sequence_tracker.cc | 33 +++++++++++++++++-- cc/metrics/frame_sequence_tracker.h | 15 ++++++++- cc/metrics/frame_sequence_tracker_unittest.cc | 7 +++- 3 files changed, 51 insertions(+), 4 deletions(-) diff --git a/cc/metrics/frame_sequence_tracker.cc b/cc/metrics/frame_sequence_tracker.cc index e003f75404ab96..eddff7bbc39c43 100644 --- a/cc/metrics/frame_sequence_tracker.cc +++ b/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 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; diff --git a/cc/metrics/frame_sequence_tracker.h b/cc/metrics/frame_sequence_tracker.h index cd9fdb46de3f98..3bb4df2c386e0c 100644 --- a/cc/metrics/frame_sequence_tracker.h +++ b/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 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_; } diff --git a/cc/metrics/frame_sequence_tracker_unittest.cc b/cc/metrics/frame_sequence_tracker_unittest.cc index 19a372e974977c..adc9645eb41e7b 100644 --- a/cc/metrics/frame_sequence_tracker_unittest.cc +++ b/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); }