Commit e792f94e authored by Mohsen Izadi's avatar Mohsen Izadi Committed by Chromium LUCI CQ

Add renderer event dispatch breakdowns to EventLatency UKM

This CL adds renderer-side event dispatch breakdowns to EventLatency
UKM. These include breakdowns of both main and compositor threads.

These changes to EventLatency UKM has been approved in:
https://docs.google.com/document/d/1SDxdua997Gm7ihJFVjinHz9qTdBzTJrEzC7GEeQHs-8/edit?usp=sharing

Bug: 1054009
Change-Id: Ic5a4f6b06a2e2c29165fd38ee95c0320877608dd
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2612931Reviewed-by: default avatarJonathan Ross <jonross@chromium.org>
Reviewed-by: default avatarJesse Doherty <jwd@chromium.org>
Commit-Queue: Mohsen Izadi <mohsen@chromium.org>
Cr-Commit-Position: refs/heads/master@{#843278}
parent c5b3341a
......@@ -301,28 +301,140 @@ void UkmManager::RecordEventLatencyUKM(
}
}
// It is possible for an event to arrive in the compositor in the middle of
// a frame (e.g. the browser received the event *after* renderer received a
// begin-impl, and the event reached the compositor before that frame
// Record event dispatch metrics.
EventMetrics::DispatchStage dispatch_stage =
EventMetrics::DispatchStage::kGenerated;
base::TimeTicks dispatch_timestamp = generated_timestamp;
while (dispatch_stage != EventMetrics::DispatchStage::kMaxValue) {
DCHECK(!dispatch_timestamp.is_null());
int dispatch_index = static_cast<int>(dispatch_stage);
// Find the end dispatch stage.
auto end_stage =
static_cast<EventMetrics::DispatchStage>(dispatch_index + 1);
base::TimeTicks end_timestamp =
event_metrics->GetDispatchStageTimestamp(end_stage);
while (end_timestamp.is_null() &&
end_stage != EventMetrics::DispatchStage::kMaxValue) {
end_stage = static_cast<EventMetrics::DispatchStage>(
static_cast<int>(end_stage) + 1);
end_timestamp = event_metrics->GetDispatchStageTimestamp(end_stage);
}
if (end_timestamp.is_null())
break;
const int64_t dispatch_latency =
(end_timestamp - dispatch_timestamp).InMicroseconds();
switch (dispatch_stage) {
case EventMetrics::DispatchStage::kGenerated:
DCHECK_EQ(end_stage,
EventMetrics::DispatchStage::kArrivedInRendererCompositor);
builder.SetGenerationToRendererCompositor(dispatch_latency);
break;
case EventMetrics::DispatchStage::kArrivedInRendererCompositor:
switch (end_stage) {
case EventMetrics::DispatchStage::kRendererCompositorStarted:
builder.SetRendererCompositorQueueingDelay(dispatch_latency);
break;
case EventMetrics::DispatchStage::kRendererMainStarted:
builder.SetRendererCompositorToMain(dispatch_latency);
break;
default:
NOTREACHED();
break;
}
break;
case EventMetrics::DispatchStage::kRendererCompositorStarted:
DCHECK_EQ(end_stage,
EventMetrics::DispatchStage::kRendererCompositorFinished);
builder.SetRendererCompositorProcessing(dispatch_latency);
break;
case EventMetrics::DispatchStage::kRendererCompositorFinished:
DCHECK_EQ(end_stage,
EventMetrics::DispatchStage::kRendererMainStarted);
builder.SetRendererCompositorToMain(dispatch_latency);
break;
case EventMetrics::DispatchStage::kRendererMainStarted:
DCHECK_EQ(end_stage,
EventMetrics::DispatchStage::kRendererMainFinished);
builder.SetRendererMainProcessing(dispatch_latency);
break;
case EventMetrics::DispatchStage::kRendererMainFinished:
NOTREACHED();
break;
}
dispatch_stage = end_stage;
dispatch_timestamp = end_timestamp;
}
// It is possible for an event to be handled on the renderer in the middle
// of a frame (e.g. the browser received the event *after* renderer received
// a begin-impl, and the event was handled on the renderer before that frame
// ended). To handle such cases, find the first stage that happens after the
// event's arrival in the browser.
// event's processing finished on the renderer.
auto stage_it = std::find_if(
stage_history.begin(), stage_history.end(),
[generated_timestamp](const CompositorFrameReporter::StageData& stage) {
return stage.start_time > generated_timestamp;
[dispatch_timestamp](const CompositorFrameReporter::StageData& stage) {
return stage.start_time > dispatch_timestamp;
});
// TODO(crbug.com/1079116): Ideally, at least the start time of
// SubmitCompositorFrameToPresentationCompositorFrame stage should be
// greater than the event time stamp, but apparently, this is not always the
// case (see crbug.com/1093698). For now, skip to the next event in such
// cases. Hopefully, the work to reduce discrepancies between the new
// EventLatency and the old Event.Latency metrics would fix this issue. If
// not, we need to reconsider investigating this issue.
// greater than the final event dispatch timestamp, but apparently, this is
// not always the case (see crbug.com/1093698). For now, skip to the next
// event in such cases. Hopefully, the work to reduce discrepancies between
// the new EventLatency and the old Event.Latency metrics would fix this
// issue. If not, we need to reconsider investigating this issue.
if (stage_it == stage_history.end())
continue;
builder.SetBrowserToRendererCompositor(
(stage_it->start_time - generated_timestamp).InMicroseconds());
switch (dispatch_stage) {
case EventMetrics::DispatchStage::kRendererCompositorFinished:
switch (stage_it->stage_type) {
#define CASE_FOR_STAGE(stage_name, metrics_suffix) \
case StageType::k##stage_name: \
builder.SetRendererCompositorFinishedTo##metrics_suffix( \
(stage_it->start_time - dispatch_timestamp).InMicroseconds()); \
break;
CASE_FOR_STAGE(BeginImplFrameToSendBeginMainFrame, BeginImplFrame);
CASE_FOR_STAGE(SendBeginMainFrameToCommit, SendBeginMainFrame);
CASE_FOR_STAGE(Commit, Commit);
CASE_FOR_STAGE(EndCommitToActivation, EndCommit);
CASE_FOR_STAGE(Activation, Activation);
CASE_FOR_STAGE(EndActivateToSubmitCompositorFrame, EndActivate);
CASE_FOR_STAGE(SubmitCompositorFrameToPresentationCompositorFrame,
SubmitCompositorFrame);
#undef CASE_FOR_STAGE
default:
NOTREACHED();
break;
}
break;
case EventMetrics::DispatchStage::kRendererMainFinished:
switch (stage_it->stage_type) {
#define CASE_FOR_STAGE(stage_name, metrics_suffix) \
case StageType::k##stage_name: \
builder.SetRendererMainFinishedTo##metrics_suffix( \
(stage_it->start_time - dispatch_timestamp).InMicroseconds()); \
break;
CASE_FOR_STAGE(BeginImplFrameToSendBeginMainFrame, BeginImplFrame);
CASE_FOR_STAGE(SendBeginMainFrameToCommit, SendBeginMainFrame);
CASE_FOR_STAGE(Commit, Commit);
CASE_FOR_STAGE(EndCommitToActivation, EndCommit);
CASE_FOR_STAGE(Activation, Activation);
CASE_FOR_STAGE(EndActivateToSubmitCompositorFrame, EndActivate);
CASE_FOR_STAGE(SubmitCompositorFrameToPresentationCompositorFrame,
SubmitCompositorFrame);
#undef CASE_FOR_STAGE
default:
NOTREACHED();
break;
}
break;
default:
NOTREACHED();
break;
}
for (; stage_it != stage_history.end(); ++stage_it) {
// Total latency is calculated since the event timestamp.
......
......@@ -44,7 +44,14 @@ const char kScrollInputType[] = "ScrollInputType";
// Names of compositor stages and substages used in compositor/event latency UKM
// metrics.
const char kBrowserToRendererCompositor[] = "BrowserToRendererCompositor";
const char kGenerationToRendererCompositor[] = "GenerationToRendererCompositor";
const char kRendererCompositorQueueingDelay[] =
"RendererCompositorQueueingDelay";
const char kRendererCompositorProcessing[] = "RendererCompositorProcessing";
const char kRendererCompositorToMain[] = "RendererCompositorToMain";
const char kRendererMainProcessing[] = "RendererMainProcessing";
const char kRendererMainFinishedToBeginImplFrame[] =
"RendererMainFinishedToBeginImplFrame";
const char kBeginImplFrameToSendBeginMainFrame[] =
"BeginImplFrameToSendBeginMainFrame";
const char kSendBeginMainFrameToCommit[] = "SendBeginMainFrameToCommit";
......@@ -109,20 +116,55 @@ class UkmManagerTest : public testing::Test {
base::Optional<ui::ScrollInputType> scroll_input_type) {
base::TimeTicks event_time = AdvanceNowByMs(10);
AdvanceNowByMs(10);
return EventMetrics::CreateForTesting(type, scroll_update_type,
scroll_input_type, event_time,
std::unique_ptr<EventMetrics> metrics = EventMetrics::CreateForTesting(
type, scroll_update_type, scroll_input_type, event_time,
&test_tick_clock_);
if (metrics) {
AdvanceNowByMs(10);
metrics->SetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererCompositorStarted);
AdvanceNowByMs(10);
metrics->SetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererCompositorFinished);
AdvanceNowByMs(10);
metrics->SetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererMainStarted);
AdvanceNowByMs(10);
metrics->SetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererMainFinished);
}
return metrics;
}
std::vector<base::TimeTicks> GetEventTimestamps(
struct DispatchTimestamps {
base::TimeTicks generated;
base::TimeTicks arrived_in_renderer;
base::TimeTicks renderer_compositor_started;
base::TimeTicks renderer_compositor_finished;
base::TimeTicks renderer_main_started;
base::TimeTicks renderer_main_finished;
};
std::vector<DispatchTimestamps> GetEventDispatchTimestamps(
const EventMetrics::List& events_metrics) {
std::vector<base::TimeTicks> event_times;
std::vector<DispatchTimestamps> event_times;
event_times.reserve(events_metrics.size());
std::transform(events_metrics.cbegin(), events_metrics.cend(),
std::back_inserter(event_times),
[](const auto& event_metrics) {
return event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kGenerated);
std::transform(
events_metrics.cbegin(), events_metrics.cend(),
std::back_inserter(event_times), [](const auto& event_metrics) {
return DispatchTimestamps{
event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kGenerated),
event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kArrivedInRendererCompositor),
event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererCompositorStarted),
event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererCompositorFinished),
event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererMainStarted),
event_metrics->GetDispatchStageTimestamp(
EventMetrics::DispatchStage::kRendererMainFinished),
};
});
return event_times;
}
......@@ -378,7 +420,8 @@ TEST_F(UkmManagerTest, EventLatency) {
EventMetrics::List events_metrics(
std::make_move_iterator(std::begin(event_metrics_ptrs)),
std::make_move_iterator(std::end(event_metrics_ptrs)));
std::vector<base::TimeTicks> event_times = GetEventTimestamps(events_metrics);
std::vector<DispatchTimestamps> event_dispatch_times =
GetEventDispatchTimestamps(events_metrics);
const base::TimeTicks begin_impl_time = AdvanceNowByMs(10);
const base::TimeTicks end_activate_time = AdvanceNowByMs(10);
......@@ -439,8 +482,34 @@ TEST_F(UkmManagerTest, EventLatency) {
static_cast<int64_t>(*event_metrics->scroll_type()));
test_ukm_recorder_->ExpectEntryMetric(
entry, kBrowserToRendererCompositor,
(begin_impl_time - event_times[i]).InMicroseconds());
entry, kGenerationToRendererCompositor,
(event_dispatch_times[i].arrived_in_renderer -
event_dispatch_times[i].generated)
.InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kRendererCompositorQueueingDelay,
(event_dispatch_times[i].renderer_compositor_started -
event_dispatch_times[i].arrived_in_renderer)
.InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kRendererCompositorProcessing,
(event_dispatch_times[i].renderer_compositor_finished -
event_dispatch_times[i].renderer_compositor_started)
.InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kRendererCompositorToMain,
(event_dispatch_times[i].renderer_main_started -
event_dispatch_times[i].renderer_compositor_finished)
.InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kRendererMainProcessing,
(event_dispatch_times[i].renderer_main_finished -
event_dispatch_times[i].renderer_main_started)
.InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kRendererMainFinishedToBeginImplFrame,
(begin_impl_time - event_dispatch_times[i].renderer_main_finished)
.InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kBeginImplFrameToSendBeginMainFrame,
(end_activate_time - begin_impl_time).InMicroseconds());
......@@ -458,9 +527,10 @@ TEST_F(UkmManagerTest, EventLatency) {
(present_time - submit_time).InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kTotalLatencyToSwapBegin,
(swap_start_time - event_times[i]).InMicroseconds());
(swap_start_time - event_dispatch_times[i].generated).InMicroseconds());
test_ukm_recorder_->ExpectEntryMetric(
entry, kTotalLatency, (present_time - event_times[i]).InMicroseconds());
entry, kTotalLatency,
(present_time - event_dispatch_times[i].generated).InMicroseconds());
}
}
......
This diff is collapsed.
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment