Skip to content

Commit

Permalink
Revert of cc: Measure compositor timing with finer granularity (patch…
Browse files Browse the repository at this point in the history 
…set #8 id:140001 of https://codereview.chromium.org/1192663005/)

Reason for revert:
Flakily fails interactive_ui_tests on Linux Tests (dbg)(1)(32). Link:

https://build.chromium.org/p/chromium.linux/builders/Linux%20Tests%20%28dbg%29%281%29%2832%29/builds/16214

failures:
AppWindowHiddenKeepAliveTest.ShownThenHiddenThenShown

Error:
[1:8:0706/185834:FATAL:compositor_timing_history.cc(104)] Check failed: base::TimeTicks() != begin_main_frame_sent_time_ (0 bogo-microseconds vs. 0 bogo-microseconds)
#0 0x0000ebbb49f4 base::debug::StackTrace::StackTrace()
#1 0x0000ebc17bee logging::LogMessage::~LogMessage()
#2 0x0000eec044b4 cc::CompositorTimingHistory::DidCommit()
#3 0x0000eec043ab cc::CompositorTimingHistory::BeginMainFrameAborted()
#4 0x0000eec0cfa5 cc::Scheduler::BeginMainFrameAborted()
#5 0x0000eed51290 cc::ThreadProxy::BeginMainFrameAbortedOnImplThread()
#6 0x0000eed60235 base::internal::RunnableAdapter\u003C>::Run()

See also:

https://findit-for-me.appspot.com/build-failure?url=https://build.chromium.org/p/chromium.linux/builders/Linux%20Tests%20(dbg)(1)(32)/builds/16214

Original issue's description:
> cc: Measure compositor timing with finer granularity
>
> Measures PrepareTiles, NotifyReadyToActivate, and
> Activation times separately such that idle times
> between actions don't polute results when the
> main thread is in a high latency mode or when
> actions are swap throttled.
>
> Also cleans up how we measure commit times and
> adds DCHECKs to make sure we don't ruin the ordering
> expectations of the CompositorTimingHistory class.
>
> Recording is only enabled while visible and we have
> an output surface in order to avoid cleanup logic
> skewing results.
>
> BUG=406158, 500744
> CQ_INCLUDE_TRYBOTS=tryserver.blink:linux_blink_rel
>
> Committed: https://crrev.com/65acb94f9258f985cbceedcd3b816cc55cc9522f
> Cr-Commit-Position: refs/heads/master@{#337539}

[email protected],[email protected],[email protected],[email protected]
NOPRESUBMIT=true
NOTREECHECKS=true
NOTRY=true
BUG=406158, 500744

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

Cr-Commit-Position: refs/heads/master@{#337553}
  • Loading branch information
@tapted @JulienIsorce
tapted authored and JulienIsorce committed Jul 17, 2015
1 parent d861064 commit 2c6cf7d
Show file tree
Hide file tree
Showing 18 changed files with 96 additions and 410 deletions.
1 change: 0 additions & 1 deletion cc/BUILD.gn
View file
Original file line number Diff line number Diff line change
Expand Up @@ -784,7 +784,6 @@ test("cc_unittests") {
"resources/scoped_resource_unittest.cc",
"resources/video_resource_updater_unittest.cc",
"scheduler/begin_frame_source_unittest.cc",
"scheduler/compositor_timing_history_unittest.cc",
"scheduler/delay_based_time_source_unittest.cc",
"scheduler/scheduler_state_machine_unittest.cc",
"scheduler/scheduler_unittest.cc",
Expand Down
1 change: 0 additions & 1 deletion cc/cc_tests.gyp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -98,7 +98,6 @@
'resources/scoped_resource_unittest.cc',
'resources/video_resource_updater_unittest.cc',
'scheduler/begin_frame_source_unittest.cc',
'scheduler/compositor_timing_history_unittest.cc',
'scheduler/delay_based_time_source_unittest.cc',
'scheduler/scheduler_state_machine_unittest.cc',
'scheduler/scheduler_unittest.cc',
Expand Down
159 changes: 34 additions & 125 deletions cc/scheduler/compositor_timing_history.cc
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,28 +8,18 @@
#include "base/trace_event/trace_event.h"
#include "cc/debug/rendering_stats_instrumentation.h"

// The estimates that affect the compositors deadline use the 100th percentile
// to avoid missing the Browser's deadline.
// The estimates related to main-thread responsiveness affect whether
// we attempt to recovery latency or not and use the 50th percentile.
// TODO(brianderson): Fine tune the percentiles below.
const size_t kDurationHistorySize = 60;
const double kBeginMainFrameToCommitEstimationPercentile = 50.0;
const double kCommitToReadyToActivateEstimationPercentile = 50.0;
const double kPrepareTilesEstimationPercentile = 100.0;
const double kActivateEstimationPercentile = 100.0;
const double kDrawEstimationPercentile = 100.0;
const double kCommitAndActivationDurationEstimationPercentile = 50.0;
const double kDrawDurationEstimationPercentile = 100.0;
const int kDrawDurationEstimatePaddingInMicroseconds = 0;

namespace cc {

CompositorTimingHistory::CompositorTimingHistory(
RenderingStatsInstrumentation* rendering_stats_instrumentation)
: enabled_(false),
: draw_duration_history_(kDurationHistorySize),
begin_main_frame_to_commit_duration_history_(kDurationHistorySize),
commit_to_ready_to_activate_duration_history_(kDurationHistorySize),
prepare_tiles_duration_history_(kDurationHistorySize),
activate_duration_history_(kDurationHistorySize),
draw_duration_history_(kDurationHistorySize),
commit_to_activate_duration_history_(kDurationHistorySize),
rendering_stats_instrumentation_(rendering_stats_instrumentation) {
}

Expand All @@ -40,73 +30,40 @@ void CompositorTimingHistory::AsValueInto(
base::trace_event::TracedValue* state) const {
state->SetDouble("begin_main_frame_to_commit_duration_estimate_ms",
BeginMainFrameToCommitDurationEstimate().InMillisecondsF());
state->SetDouble("commit_to_ready_to_activate_duration_estimate_ms",
CommitToReadyToActivateDurationEstimate().InMillisecondsF());
state->SetDouble("prepare_tiles_duration_estimate_ms",
PrepareTilesDurationEstimate().InMillisecondsF());
state->SetDouble("activate_duration_estimate_ms",
ActivateDurationEstimate().InMillisecondsF());
state->SetDouble("commit_to_activate_duration_estimate_ms",
CommitToActivateDurationEstimate().InMillisecondsF());
state->SetDouble("draw_duration_estimate_ms",
DrawDurationEstimate().InMillisecondsF());
}

base::TimeTicks CompositorTimingHistory::Now() const {
return base::TimeTicks::Now();
}

void CompositorTimingHistory::SetRecordingEnabled(bool enabled) {
enabled_ = enabled;

if (enabled) {
begin_main_frame_sent_time_ = base::TimeTicks();
commit_time_ = base::TimeTicks();
start_prepare_tiles_time_ = base::TimeTicks();
start_activate_time_ = base::TimeTicks();
start_draw_time_ = base::TimeTicks();
}
base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
base::TimeDelta historical_estimate =
draw_duration_history_.Percentile(kDrawDurationEstimationPercentile);
base::TimeDelta padding = base::TimeDelta::FromMicroseconds(
kDrawDurationEstimatePaddingInMicroseconds);
return historical_estimate + padding;
}

base::TimeDelta
CompositorTimingHistory::BeginMainFrameToCommitDurationEstimate() const {
return begin_main_frame_to_commit_duration_history_.Percentile(
kBeginMainFrameToCommitEstimationPercentile);
kCommitAndActivationDurationEstimationPercentile);
}

base::TimeDelta
CompositorTimingHistory::CommitToReadyToActivateDurationEstimate() const {
return commit_to_ready_to_activate_duration_history_.Percentile(
kCommitToReadyToActivateEstimationPercentile);
}

base::TimeDelta CompositorTimingHistory::PrepareTilesDurationEstimate() const {
return prepare_tiles_duration_history_.Percentile(
kPrepareTilesEstimationPercentile);
}

base::TimeDelta CompositorTimingHistory::ActivateDurationEstimate() const {
return activate_duration_history_.Percentile(kActivateEstimationPercentile);
}

base::TimeDelta CompositorTimingHistory::DrawDurationEstimate() const {
return draw_duration_history_.Percentile(kDrawEstimationPercentile);
base::TimeDelta CompositorTimingHistory::CommitToActivateDurationEstimate()
const {
return commit_to_activate_duration_history_.Percentile(
kCommitAndActivationDurationEstimationPercentile);
}

void CompositorTimingHistory::WillBeginMainFrame() {
DCHECK_EQ(base::TimeTicks(), begin_main_frame_sent_time_);
begin_main_frame_sent_time_ = Now();
}

void CompositorTimingHistory::BeginMainFrameAborted() {
DidCommit();
begin_main_frame_sent_time_ = base::TimeTicks::Now();
}

void CompositorTimingHistory::DidCommit() {
DCHECK_NE(base::TimeTicks(), begin_main_frame_sent_time_);

commit_time_ = Now();

commit_complete_time_ = base::TimeTicks::Now();
base::TimeDelta begin_main_frame_to_commit_duration =
commit_time_ - begin_main_frame_sent_time_;
commit_complete_time_ - begin_main_frame_sent_time_;

// Before adding the new data point to the timing history, see what we would
// have predicted for this frame. This allows us to keep track of the accuracy
Expand All @@ -115,74 +72,30 @@ void CompositorTimingHistory::DidCommit() {
begin_main_frame_to_commit_duration,
BeginMainFrameToCommitDurationEstimate());

if (enabled_) {
begin_main_frame_to_commit_duration_history_.InsertSample(
begin_main_frame_to_commit_duration);
}

begin_main_frame_sent_time_ = base::TimeTicks();
}

void CompositorTimingHistory::WillPrepareTiles() {
DCHECK_EQ(base::TimeTicks(), start_prepare_tiles_time_);
start_prepare_tiles_time_ = Now();
}

void CompositorTimingHistory::DidPrepareTiles() {
DCHECK_NE(base::TimeTicks(), start_prepare_tiles_time_);

if (enabled_) {
base::TimeDelta prepare_tiles_duration = Now() - start_prepare_tiles_time_;
prepare_tiles_duration_history_.InsertSample(prepare_tiles_duration);
}

start_prepare_tiles_time_ = base::TimeTicks();
begin_main_frame_to_commit_duration_history_.InsertSample(
begin_main_frame_to_commit_duration);
}

void CompositorTimingHistory::ReadyToActivate() {
// We only care about the first ready to activate signal
// after a commit.
if (commit_time_ == base::TimeTicks())
return;

base::TimeDelta time_since_commit = Now() - commit_time_;
void CompositorTimingHistory::DidActivateSyncTree() {
base::TimeDelta commit_to_activate_duration =
base::TimeTicks::Now() - commit_complete_time_;

// Before adding the new data point to the timing history, see what we would
// have predicted for this frame. This allows us to keep track of the accuracy
// of our predictions.
rendering_stats_instrumentation_->AddCommitToActivateDuration(
time_since_commit, CommitToReadyToActivateDurationEstimate());

if (enabled_) {
commit_to_ready_to_activate_duration_history_.InsertSample(
time_since_commit);
}
commit_to_activate_duration, CommitToActivateDurationEstimate());

commit_time_ = base::TimeTicks();
commit_to_activate_duration_history_.InsertSample(
commit_to_activate_duration);
}

void CompositorTimingHistory::WillActivate() {
DCHECK_EQ(base::TimeTicks(), start_activate_time_);
start_activate_time_ = Now();
void CompositorTimingHistory::DidStartDrawing() {
start_draw_time_ = base::TimeTicks::Now();
}

void CompositorTimingHistory::DidActivate() {
DCHECK_NE(base::TimeTicks(), start_activate_time_);
if (enabled_) {
base::TimeDelta activate_duration = Now() - start_activate_time_;
activate_duration_history_.InsertSample(activate_duration);
}
start_activate_time_ = base::TimeTicks();
}

void CompositorTimingHistory::WillDraw() {
DCHECK_EQ(base::TimeTicks(), start_draw_time_);
start_draw_time_ = Now();
}

void CompositorTimingHistory::DidDraw() {
DCHECK_NE(base::TimeTicks(), start_draw_time_);
base::TimeDelta draw_duration = Now() - start_draw_time_;
void CompositorTimingHistory::DidFinishDrawing() {
base::TimeDelta draw_duration = base::TimeTicks::Now() - start_draw_time_;

// Before adding the new data point to the timing history, see what we would
// have predicted for this frame. This allows us to keep track of the accuracy
Expand All @@ -193,11 +106,7 @@ void CompositorTimingHistory::DidDraw() {

AddDrawDurationUMA(draw_duration, draw_duration_estimate);

if (enabled_) {
draw_duration_history_.InsertSample(draw_duration);
}

start_draw_time_ = base::TimeTicks();
draw_duration_history_.InsertSample(draw_duration);
}

void CompositorTimingHistory::AddDrawDurationUMA(
Expand Down
33 changes: 8 additions & 25 deletions cc/scheduler/compositor_timing_history.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -25,43 +25,26 @@ class CC_EXPORT CompositorTimingHistory {

void AsValueInto(base::trace_event::TracedValue* state) const;

virtual base::TimeDelta BeginMainFrameToCommitDurationEstimate() const;
virtual base::TimeDelta CommitToReadyToActivateDurationEstimate() const;
virtual base::TimeDelta PrepareTilesDurationEstimate() const;
virtual base::TimeDelta ActivateDurationEstimate() const;
virtual base::TimeDelta DrawDurationEstimate() const;

void SetRecordingEnabled(bool enabled);
virtual base::TimeDelta BeginMainFrameToCommitDurationEstimate() const;
virtual base::TimeDelta CommitToActivateDurationEstimate() const;

void WillBeginMainFrame();
void BeginMainFrameAborted();
void DidCommit();
void WillPrepareTiles();
void DidPrepareTiles();
void ReadyToActivate();
void WillActivate();
void DidActivate();
void WillDraw();
void DidDraw();
void DidActivateSyncTree();
void DidStartDrawing();
void DidFinishDrawing();

protected:
virtual base::TimeTicks Now() const;

void AddDrawDurationUMA(base::TimeDelta draw_duration,
base::TimeDelta draw_duration_estimate);

bool enabled_;

RollingTimeDeltaHistory begin_main_frame_to_commit_duration_history_;
RollingTimeDeltaHistory commit_to_ready_to_activate_duration_history_;
RollingTimeDeltaHistory prepare_tiles_duration_history_;
RollingTimeDeltaHistory activate_duration_history_;
RollingTimeDeltaHistory draw_duration_history_;
RollingTimeDeltaHistory begin_main_frame_to_commit_duration_history_;
RollingTimeDeltaHistory commit_to_activate_duration_history_;

base::TimeTicks begin_main_frame_sent_time_;
base::TimeTicks commit_time_;
base::TimeTicks start_prepare_tiles_time_;
base::TimeTicks start_activate_time_;
base::TimeTicks commit_complete_time_;
base::TimeTicks start_draw_time_;

RenderingStatsInstrumentation* rendering_stats_instrumentation_;
Expand Down
Loading

0 comments on commit 2c6cf7d

Please sign in to comment.