0

Revert "cc: Don't record first two frames in CompositorTimingHistory"

This reverts commit a79c946759.

BUG=516010
CQ_INCLUDE_TRYBOTS=tryserver.blink:linux_blink_rel

Review URL: https://codereview.chromium.org/1349633006

Cr-Commit-Position: refs/heads/master@{#350309}
This commit is contained in:
brianderson
2015-09-22 22:58:22 -07:00
committed by Commit bot
parent 58fefc1677
commit d7478de1ae
4 changed files with 21 additions and 142 deletions

@ -38,7 +38,6 @@ namespace {
// second. // second.
// TODO(brianderson): Fine tune the percentiles below. // TODO(brianderson): Fine tune the percentiles below.
const size_t kDurationHistorySize = 60; const size_t kDurationHistorySize = 60;
const size_t kDrawsBeforeEstimatesAffected = 2;
const double kBeginMainFrameToCommitEstimationPercentile = 90.0; const double kBeginMainFrameToCommitEstimationPercentile = 90.0;
const double kCommitToReadyToActivateEstimationPercentile = 90.0; const double kCommitToReadyToActivateEstimationPercentile = 90.0;
const double kPrepareTilesEstimationPercentile = 90.0; const double kPrepareTilesEstimationPercentile = 90.0;
@ -199,7 +198,6 @@ CompositorTimingHistory::CompositorTimingHistory(
UMACategory uma_category, UMACategory uma_category,
RenderingStatsInstrumentation* rendering_stats_instrumentation) RenderingStatsInstrumentation* rendering_stats_instrumentation)
: enabled_(false), : enabled_(false),
draws_left_before_estimates_affected_(0),
begin_main_frame_to_commit_duration_history_(kDurationHistorySize), begin_main_frame_to_commit_duration_history_(kDurationHistorySize),
commit_to_ready_to_activate_duration_history_(kDurationHistorySize), commit_to_ready_to_activate_duration_history_(kDurationHistorySize),
prepare_tiles_duration_history_(kDurationHistorySize), prepare_tiles_duration_history_(kDurationHistorySize),
@ -246,18 +244,8 @@ base::TimeTicks CompositorTimingHistory::Now() const {
return base::TimeTicks::Now(); return base::TimeTicks::Now();
} }
bool CompositorTimingHistory::AffectsEstimate() const {
return enabled_ && (draws_left_before_estimates_affected_ == 0);
}
void CompositorTimingHistory::SetRecordingEnabled(bool enabled) { void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
if (enabled == enabled_)
return;
enabled_ = enabled; enabled_ = enabled;
if (enabled_)
draws_left_before_estimates_affected_ = kDrawsBeforeEstimatesAffected;
} }
base::TimeDelta base::TimeDelta
@ -307,15 +295,13 @@ void CompositorTimingHistory::DidCommit() {
// of our predictions. // of our predictions.
base::TimeDelta begin_main_frame_to_commit_estimate = base::TimeDelta begin_main_frame_to_commit_estimate =
BeginMainFrameToCommitDurationEstimate(); BeginMainFrameToCommitDurationEstimate();
uma_reporter_->AddBeginMainFrameToCommitDuration(
begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate,
enabled_);
rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration( rendering_stats_instrumentation_->AddBeginMainFrameToCommitDuration(
begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate); begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate);
bool affects_estimate = AffectsEstimate(); if (enabled_) {
uma_reporter_->AddBeginMainFrameToCommitDuration(
begin_main_frame_to_commit_duration, begin_main_frame_to_commit_estimate,
affects_estimate);
if (affects_estimate) {
begin_main_frame_to_commit_duration_history_.InsertSample( begin_main_frame_to_commit_duration_history_.InsertSample(
begin_main_frame_to_commit_duration); begin_main_frame_to_commit_duration);
} }
@ -332,11 +318,9 @@ void CompositorTimingHistory::DidPrepareTiles() {
DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_); DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);
base::TimeDelta prepare_tiles_duration = Now() - start_prepare_tiles_time_; base::TimeDelta prepare_tiles_duration = Now() - start_prepare_tiles_time_;
bool affects_estimate = AffectsEstimate();
uma_reporter_->AddPrepareTilesDuration( uma_reporter_->AddPrepareTilesDuration(
prepare_tiles_duration, PrepareTilesDurationEstimate(), affects_estimate); prepare_tiles_duration, PrepareTilesDurationEstimate(), enabled_);
if (affects_estimate) if (enabled_)
prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration); prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
start_prepare_tiles_time_ = base::TimeTicks(); start_prepare_tiles_time_ = base::TimeTicks();
@ -356,14 +340,12 @@ void CompositorTimingHistory::ReadyToActivate() {
base::TimeDelta commit_to_ready_to_activate_estimate = base::TimeDelta commit_to_ready_to_activate_estimate =
CommitToReadyToActivateDurationEstimate(); CommitToReadyToActivateDurationEstimate();
uma_reporter_->AddCommitToReadyToActivateDuration(
time_since_commit, commit_to_ready_to_activate_estimate, enabled_);
rendering_stats_instrumentation_->AddCommitToActivateDuration( rendering_stats_instrumentation_->AddCommitToActivateDuration(
time_since_commit, commit_to_ready_to_activate_estimate); time_since_commit, commit_to_ready_to_activate_estimate);
bool affects_estimate = AffectsEstimate(); if (enabled_) {
uma_reporter_->AddCommitToReadyToActivateDuration(
time_since_commit, commit_to_ready_to_activate_estimate,
affects_estimate);
if (affects_estimate) {
commit_to_ready_to_activate_duration_history_.InsertSample( commit_to_ready_to_activate_duration_history_.InsertSample(
time_since_commit); time_since_commit);
} }
@ -380,10 +362,9 @@ void CompositorTimingHistory::DidActivate() {
DCHECK_NE(base::TimeTicks(), start_activate_time_); DCHECK_NE(base::TimeTicks(), start_activate_time_);
base::TimeDelta activate_duration = Now() - start_activate_time_; base::TimeDelta activate_duration = Now() - start_activate_time_;
bool affects_estimate = AffectsEstimate(); uma_reporter_->AddActivateDuration(activate_duration,
uma_reporter_->AddActivateDuration( ActivateDurationEstimate(), enabled_);
activate_duration, ActivateDurationEstimate(), affects_estimate); if (enabled_)
if (affects_estimate)
activate_duration_history_.InsertSample(activate_duration); activate_duration_history_.InsertSample(activate_duration);
start_activate_time_ = base::TimeTicks(); start_activate_time_ = base::TimeTicks();
@ -405,14 +386,11 @@ void CompositorTimingHistory::DidDraw() {
rendering_stats_instrumentation_->AddDrawDuration(draw_duration, rendering_stats_instrumentation_->AddDrawDuration(draw_duration,
draw_estimate); draw_estimate);
bool affects_estimate = AffectsEstimate(); uma_reporter_->AddDrawDuration(draw_duration, draw_estimate, enabled_);
uma_reporter_->AddDrawDuration(draw_duration, draw_estimate,
affects_estimate);
if (affects_estimate)
draw_duration_history_.InsertSample(draw_duration);
if (draws_left_before_estimates_affected_ > 0) if (enabled_) {
draws_left_before_estimates_affected_--; draw_duration_history_.InsertSample(draw_duration);
}
start_draw_time_ = base::TimeTicks(); start_draw_time_ = base::TimeTicks();
} }

@ -57,10 +57,7 @@ class CC_EXPORT CompositorTimingHistory {
static scoped_ptr<UMAReporter> CreateUMAReporter(UMACategory category); static scoped_ptr<UMAReporter> CreateUMAReporter(UMACategory category);
virtual base::TimeTicks Now() const; virtual base::TimeTicks Now() const;
bool AffectsEstimate() const;
bool enabled_; bool enabled_;
int draws_left_before_estimates_affected_;
RollingTimeDeltaHistory begin_main_frame_to_commit_duration_history_; RollingTimeDeltaHistory begin_main_frame_to_commit_duration_history_;
RollingTimeDeltaHistory commit_to_ready_to_activate_duration_history_; RollingTimeDeltaHistory commit_to_ready_to_activate_duration_history_;

@ -16,9 +16,7 @@ class TestCompositorTimingHistory : public CompositorTimingHistory {
public: public:
TestCompositorTimingHistory(CompositorTimingHistoryTest* test, TestCompositorTimingHistory(CompositorTimingHistoryTest* test,
RenderingStatsInstrumentation* rendering_stats) RenderingStatsInstrumentation* rendering_stats)
: CompositorTimingHistory(CompositorTimingHistory::NULL_UMA, : CompositorTimingHistory(NULL_UMA, rendering_stats), test_(test) {}
rendering_stats),
test_(test) {}
protected: protected:
base::TimeTicks Now() const override; base::TimeTicks Now() const override;
@ -42,25 +40,6 @@ class CompositorTimingHistoryTest : public testing::Test {
base::TimeTicks Now() { return now_; } base::TimeTicks Now() { return now_; }
void TriggerAllNotificationsWithoutAdvancingTime() {
timing_history_.WillBeginMainFrame();
timing_history_.DidCommit();
timing_history_.WillPrepareTiles();
timing_history_.DidPrepareTiles();
timing_history_.ReadyToActivate();
timing_history_.WillActivate();
timing_history_.DidActivate();
timing_history_.WillDraw();
timing_history_.DidDraw();
}
void TriggerInitialUnrecordedActions() {
// The first two cycles are not used since
// they are generally more expensive then subsequent frames.
TriggerAllNotificationsWithoutAdvancingTime();
TriggerAllNotificationsWithoutAdvancingTime();
}
protected: protected:
scoped_ptr<RenderingStatsInstrumentation> rendering_stats_; scoped_ptr<RenderingStatsInstrumentation> rendering_stats_;
TestCompositorTimingHistory timing_history_; TestCompositorTimingHistory timing_history_;
@ -71,80 +50,7 @@ base::TimeTicks TestCompositorTimingHistory::Now() const {
return test_->Now(); return test_->Now();
} }
TEST_F(CompositorTimingHistoryTest, FirstTwoFramesNotRecorded) {
base::TimeDelta one_second = base::TimeDelta::FromSeconds(1);
base::TimeDelta begin_main_frame_to_commit_duration =
base::TimeDelta::FromMilliseconds(1);
base::TimeDelta prepare_tiles_duration = base::TimeDelta::FromMilliseconds(2);
base::TimeDelta prepare_tiles_end_to_ready_to_activate_duration =
base::TimeDelta::FromMilliseconds(1);
base::TimeDelta commit_to_ready_to_activate_duration =
base::TimeDelta::FromMilliseconds(3);
base::TimeDelta activate_duration = base::TimeDelta::FromMilliseconds(4);
base::TimeDelta draw_duration = base::TimeDelta::FromMilliseconds(5);
// Verify first two frames don't affect results.
for (int i = 0; i < 2; i++) {
timing_history_.WillBeginMainFrame();
AdvanceNowBy(begin_main_frame_to_commit_duration);
timing_history_.DidCommit();
timing_history_.WillPrepareTiles();
AdvanceNowBy(prepare_tiles_duration);
timing_history_.DidPrepareTiles();
AdvanceNowBy(prepare_tiles_end_to_ready_to_activate_duration);
timing_history_.ReadyToActivate();
AdvanceNowBy(one_second);
timing_history_.WillActivate();
AdvanceNowBy(activate_duration);
timing_history_.DidActivate();
AdvanceNowBy(one_second);
timing_history_.WillDraw();
AdvanceNowBy(draw_duration);
timing_history_.DidDraw();
EXPECT_EQ(base::TimeDelta(),
timing_history_.BeginMainFrameToCommitDurationEstimate());
EXPECT_EQ(base::TimeDelta(),
timing_history_.CommitToReadyToActivateDurationEstimate());
EXPECT_EQ(base::TimeDelta(),
timing_history_.PrepareTilesDurationEstimate());
EXPECT_EQ(base::TimeDelta(), timing_history_.ActivateDurationEstimate());
EXPECT_EQ(base::TimeDelta(), timing_history_.DrawDurationEstimate());
}
timing_history_.WillBeginMainFrame();
AdvanceNowBy(begin_main_frame_to_commit_duration);
timing_history_.DidCommit();
timing_history_.WillPrepareTiles();
AdvanceNowBy(prepare_tiles_duration);
timing_history_.DidPrepareTiles();
AdvanceNowBy(prepare_tiles_end_to_ready_to_activate_duration);
timing_history_.ReadyToActivate();
// Do not count idle time between notification and actual activation.
AdvanceNowBy(one_second);
timing_history_.WillActivate();
AdvanceNowBy(activate_duration);
timing_history_.DidActivate();
// Do not count idle time between activate and draw.
AdvanceNowBy(one_second);
timing_history_.WillDraw();
AdvanceNowBy(draw_duration);
timing_history_.DidDraw();
EXPECT_EQ(begin_main_frame_to_commit_duration,
timing_history_.BeginMainFrameToCommitDurationEstimate());
EXPECT_EQ(commit_to_ready_to_activate_duration,
timing_history_.CommitToReadyToActivateDurationEstimate());
EXPECT_EQ(prepare_tiles_duration,
timing_history_.PrepareTilesDurationEstimate());
EXPECT_EQ(activate_duration, timing_history_.ActivateDurationEstimate());
EXPECT_EQ(draw_duration, timing_history_.DrawDurationEstimate());
}
TEST_F(CompositorTimingHistoryTest, AllSequentialCommit) { TEST_F(CompositorTimingHistoryTest, AllSequentialCommit) {
TriggerInitialUnrecordedActions();
base::TimeDelta one_second = base::TimeDelta::FromSeconds(1); base::TimeDelta one_second = base::TimeDelta::FromSeconds(1);
base::TimeDelta begin_main_frame_to_commit_duration = base::TimeDelta begin_main_frame_to_commit_duration =
@ -159,6 +65,7 @@ TEST_F(CompositorTimingHistoryTest, AllSequentialCommit) {
timing_history_.WillBeginMainFrame(); timing_history_.WillBeginMainFrame();
AdvanceNowBy(begin_main_frame_to_commit_duration); AdvanceNowBy(begin_main_frame_to_commit_duration);
// timing_history_.BeginMainFrameAborted();
timing_history_.DidCommit(); timing_history_.DidCommit();
timing_history_.WillPrepareTiles(); timing_history_.WillPrepareTiles();
AdvanceNowBy(prepare_tiles_duration); AdvanceNowBy(prepare_tiles_duration);
@ -187,8 +94,6 @@ TEST_F(CompositorTimingHistoryTest, AllSequentialCommit) {
} }
TEST_F(CompositorTimingHistoryTest, AllSequentialBeginMainFrameAborted) { TEST_F(CompositorTimingHistoryTest, AllSequentialBeginMainFrameAborted) {
TriggerInitialUnrecordedActions();
base::TimeDelta one_second = base::TimeDelta::FromSeconds(1); base::TimeDelta one_second = base::TimeDelta::FromSeconds(1);
base::TimeDelta begin_main_frame_to_commit_duration = base::TimeDelta begin_main_frame_to_commit_duration =

@ -278,7 +278,6 @@ void Scheduler::SetupNextBeginFrameIfNeeded() {
frame_source_->SetNeedsBeginFrames(true); frame_source_->SetNeedsBeginFrames(true);
devtools_instrumentation::NeedsBeginFrameChanged(layer_tree_host_id_, devtools_instrumentation::NeedsBeginFrameChanged(layer_tree_host_id_,
true); true);
UpdateCompositorTimingHistoryRecordingEnabled();
} else if (state_machine_.begin_impl_frame_state() == } else if (state_machine_.begin_impl_frame_state() ==
SchedulerStateMachine::BEGIN_IMPL_FRAME_STATE_IDLE) { SchedulerStateMachine::BEGIN_IMPL_FRAME_STATE_IDLE) {
// Call SetNeedsBeginFrames(false) in between frames only. // Call SetNeedsBeginFrames(false) in between frames only.
@ -286,7 +285,6 @@ void Scheduler::SetupNextBeginFrameIfNeeded() {
client_->SendBeginMainFrameNotExpectedSoon(); client_->SendBeginMainFrameNotExpectedSoon();
devtools_instrumentation::NeedsBeginFrameChanged(layer_tree_host_id_, devtools_instrumentation::NeedsBeginFrameChanged(layer_tree_host_id_,
false); false);
UpdateCompositorTimingHistoryRecordingEnabled();
} }
} }
@ -741,6 +739,8 @@ void Scheduler::AsValueInto(base::trace_event::TracedValue* state) const {
state->BeginDictionary("scheduler_state"); state->BeginDictionary("scheduler_state");
state->SetDouble("estimated_parent_draw_time_ms", state->SetDouble("estimated_parent_draw_time_ms",
estimated_parent_draw_time_.InMillisecondsF()); estimated_parent_draw_time_.InMillisecondsF());
state->SetBoolean("last_set_needs_begin_frame_",
frame_source_->NeedsBeginFrames());
state->SetInteger("begin_retro_frame_args", state->SetInteger("begin_retro_frame_args",
static_cast<int>(begin_retro_frame_args_.size())); static_cast<int>(begin_retro_frame_args_.size()));
state->SetBoolean("begin_retro_frame_task", state->SetBoolean("begin_retro_frame_task",
@ -766,8 +766,7 @@ void Scheduler::AsValueInto(base::trace_event::TracedValue* state) const {
void Scheduler::UpdateCompositorTimingHistoryRecordingEnabled() { void Scheduler::UpdateCompositorTimingHistoryRecordingEnabled() {
compositor_timing_history_->SetRecordingEnabled( compositor_timing_history_->SetRecordingEnabled(
state_machine_.HasInitializedOutputSurface() && state_machine_.HasInitializedOutputSurface() && state_machine_.visible());
state_machine_.visible() && frame_source_->NeedsBeginFrames());
} }
bool Scheduler::ShouldRecoverMainLatency(const BeginFrameArgs& args) const { bool Scheduler::ShouldRecoverMainLatency(const BeginFrameArgs& args) const {