#include "ui/latency/latency_tracker.h"
#include <algorithm>
#include <cstdint>
#include "base/metrics/histogram.h"
#include "base/metrics/histogram_base.h"
#include "base/metrics/histogram_macros.h"
#include "base/notreached.h"
#include "base/strings/strcat.h"
#include "base/strings/string_piece_forward.h"
#include "base/time/time.h"
#include "services/metrics/public/cpp/ukm_entry_builder.h"
#include "services/metrics/public/cpp/ukm_recorder.h"
#include "ui/latency/jank_tracker_for_experiments_buildflags.h"
#include "ui/latency/janky_duration_tracker.h"
#include "base/trace_event/trace_event.h"
#define DCHECK_AND_RETURN_ON_FAIL(x) \
DCHECK(x); \
if (!(x)) \
return;
#define UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(name, latency) \
UMA_HISTOGRAM_CUSTOM_COUNTS(name, latency.InMicroseconds(), 1, \
base::Seconds(5).InMicroseconds(), 100);
#define UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP( \
suffix, scroll_type, input_modality, latency) \
STATIC_HISTOGRAM_POINTER_GROUP( \
GetHistogramName(suffix, scroll_type, input_modality), \
GetHistogramIndex(scroll_type, input_modality), kMaxHistogramIndex, \
Add(latency.InMicroseconds()), \
base::Histogram::FactoryGet( \
GetHistogramName(suffix, scroll_type, input_modality), 1, \
base::Seconds(5).InMicroseconds(), 100, \
base::HistogramBase::kUmaTargetedHistogramFlag));
#define UMA_HISTOGRAM_INPUT_LATENCY_CUSTOM_MICROSECONDS(name, latency) \
UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES( \
name, latency, base::Microseconds(1), base::Milliseconds(100), 100);
#define UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(name, \
latency) \
UMA_HISTOGRAM_CUSTOM_COUNTS(name, latency.InMicroseconds(), 1, \
base::Seconds(1).InMicroseconds(), 100);
#define UMA_HISTOGRAM_INPUT_LATENCY_CUSTOM_1_SECOND_MAX_MICROSECONDS(name, \
latency) \
UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES( \
name, latency, base::Microseconds(1), base::Seconds(1), 100);
#define UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(name, latency) \
UMA_HISTOGRAM_CUSTOM_COUNTS(name, latency.InMicroseconds(), \
base::Milliseconds(1).InMicroseconds(), \
base::Milliseconds(200).InMicroseconds(), 50);
#define UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2_GROUP(suffix, scroll_type, \
input_modality, latency) \
STATIC_HISTOGRAM_POINTER_GROUP( \
GetHistogramName(suffix, scroll_type, input_modality), \
GetHistogramIndex(scroll_type, input_modality), kMaxHistogramIndex, \
Add(latency.InMicroseconds()), \
base::Histogram::FactoryGet( \
GetHistogramName(suffix, scroll_type, input_modality), \
base::Milliseconds(1).InMicroseconds(), \
base::Milliseconds(200).InMicroseconds(), 50, \
base::HistogramBase::kUmaTargetedHistogramFlag));
#define UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2_GROUP(suffix, scroll_type, \
input_modality, latency) \
STATIC_HISTOGRAM_POINTER_GROUP( \
GetHistogramName(suffix, scroll_type, input_modality), \
GetHistogramIndex(scroll_type, input_modality), kMaxHistogramIndex, \
Add(latency.InMicroseconds()), \
base::Histogram::FactoryGet( \
GetHistogramName(suffix, scroll_type, input_modality), 1, \
base::Milliseconds(50).InMicroseconds(), 50, \
base::HistogramBase::kUmaTargetedHistogramFlag));
namespace ui {
namespace {
base::TimeDelta ComputeLatency(base::TimeTicks start, base::TimeTicks end) {
DCHECK(!start.is_null());
DCHECK(!end.is_null());
base::TimeDelta latency = end - start;
if (latency.is_negative()) {
return base::Milliseconds(0);
}
return latency;
}
bool IsInertialScroll(const LatencyInfo& latency) {
return latency.source_event_type() == ui::SourceEventType::INERTIAL;
}
enum Jank : int {
kNonJanky = 0,
kJanky,
};
void EmitScrollUpdateTime(base::TimeDelta dur, bool janky) {
int count = dur.InMilliseconds();
if (count <= 0) {
return;
}
static auto* histogram = base::BooleanHistogram::FactoryGet(
"Event.Jank.ScrollUpdate.TotalJankyAndNonJankyDuration2",
base::HistogramBase::kUmaTargetedHistogramFlag);
histogram->AddCount(janky ? kJanky : kNonJanky, count);
#if BUILDFLAG(JANK_TRACKER_FOR_EXPERIMENTS)
AdvanceJankyDurationForBenchmarking(janky, count);
#endif
}
}
base::StringPiece LatencyTracker::ToString(ScrollInputModality modality) {
switch (modality) {
case ScrollInputModality::kWheel:
return "Wheel";
case ScrollInputModality::kTouch:
return "Touch";
case ScrollInputModality::kScrollbar:
return "Scrollbar";
}
}
base::StringPiece LatencyTracker::ToString(ScrollType type) {
switch (type) {
case ScrollType::kBegin:
return "ScrollBegin";
case ScrollType::kUpdate:
return "ScrollUpdate";
case ScrollType::kInertial:
return "ScrollInertial";
}
}
int LatencyTracker::GetHistogramIndex(ScrollType scroll_type,
ScrollInputModality input_modality) {
return static_cast<int>(scroll_type) +
(static_cast<int>(ScrollType::kLastValue) + 1) *
static_cast<int>(input_modality);
}
std::string LatencyTracker::GetHistogramName(
base::StringPiece suffix,
ScrollType scroll_type,
ScrollInputModality input_modality) {
return base::StrCat({"Event.Latency.", ToString(scroll_type), ".",
ToString(input_modality), ".", suffix});
}
LatencyTracker::ScrollInputModality LatencyTracker::ToScrollInputModality(
ui::SourceEventType type) {
switch (type) {
case ui::SourceEventType::WHEEL:
return ScrollInputModality::kWheel;
case ui::SourceEventType::TOUCH:
case ui::SourceEventType::INERTIAL:
return ScrollInputModality::kTouch;
case ui::SourceEventType::SCROLLBAR:
return ScrollInputModality::kScrollbar;
default:
NOTREACHED();
}
return ScrollInputModality::kLastValue;
}
LatencyTracker::LatencyTracker() = default;
LatencyTracker::~LatencyTracker() = default;
void LatencyTracker::OnGpuSwapBuffersCompleted(
std::vector<ui::LatencyInfo> latency_info,
bool top_controls_visible_height_changed) {
std::sort(latency_info.begin(), latency_info.end(),
[](const LatencyInfo& x, const LatencyInfo& y) {
return x.trace_id() < y.trace_id();
});
for (const auto& latency : latency_info) {
base::TimeTicks gpu_swap_end_timestamp;
if (!latency.FindLatency(INPUT_EVENT_LATENCY_FRAME_SWAP_COMPONENT,
&gpu_swap_end_timestamp)) {
continue;
}
base::TimeTicks gpu_swap_begin_timestamp;
bool found_component = latency.FindLatency(
ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, &gpu_swap_begin_timestamp);
DCHECK_AND_RETURN_ON_FAIL(found_component);
if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
nullptr)) {
continue;
}
base::TimeTicks first_scroll_start_timestamp;
base::TimeTicks original_scroll_start_timestamp;
if (latency.FindLatency(
INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
&first_scroll_start_timestamp)) {
TRACE_EVENT1("input", "OnGpuSwapBuffersCompleted::FirstScrollUpdate",
"time",
(gpu_swap_begin_timestamp - first_scroll_start_timestamp)
.InMillisecondsF());
} else if (latency.FindLatency(
INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
&original_scroll_start_timestamp)) {
TRACE_EVENT1("input", "OnGpuSwapBuffersCompleted::OriginalScrollUpdate",
"time",
(gpu_swap_begin_timestamp - original_scroll_start_timestamp)
.InMillisecondsF());
}
ui::SourceEventType source_event_type = latency.source_event_type();
if (source_event_type == ui::SourceEventType::WHEEL ||
source_event_type == ui::SourceEventType::MOUSE ||
source_event_type == ui::SourceEventType::TOUCH ||
source_event_type == ui::SourceEventType::INERTIAL ||
source_event_type == ui::SourceEventType::KEY_PRESS ||
source_event_type == ui::SourceEventType::TOUCHPAD ||
source_event_type == ui::SourceEventType::SCROLLBAR) {
ComputeEndToEndLatencyHistograms(gpu_swap_begin_timestamp,
gpu_swap_end_timestamp, latency,
top_controls_visible_height_changed);
}
}
}
void LatencyTracker::ReportUkmScrollLatency(
const InputMetricEvent& metric_event,
base::TimeTicks start_timestamp,
base::TimeTicks time_to_scroll_update_swap_begin_timestamp,
base::TimeTicks time_to_handled_timestamp,
bool is_main_thread,
const ukm::SourceId ukm_source_id) {
DCHECK(!start_timestamp.is_null());
DCHECK(!time_to_scroll_update_swap_begin_timestamp.is_null());
DCHECK(!time_to_handled_timestamp.is_null());
ukm::UkmRecorder* ukm_recorder = ukm::UkmRecorder::Get();
if (ukm_source_id == ukm::kInvalidSourceId || !ukm_recorder)
return;
std::string event_name = "";
switch (metric_event) {
case InputMetricEvent::SCROLL_BEGIN_TOUCH:
event_name = "Event.ScrollBegin.Touch";
break;
case InputMetricEvent::SCROLL_UPDATE_TOUCH:
event_name = "Event.ScrollUpdate.Touch";
break;
case InputMetricEvent::SCROLL_BEGIN_WHEEL:
event_name = "Event.ScrollBegin.Wheel";
break;
case InputMetricEvent::SCROLL_UPDATE_WHEEL:
event_name = "Event.ScrollUpdate.Wheel";
break;
}
ukm::UkmEntryBuilder builder(ukm_source_id, event_name.c_str());
builder.SetMetric(
"TimeToScrollUpdateSwapBegin",
std::max(static_cast<int64_t>(0),
(time_to_scroll_update_swap_begin_timestamp - start_timestamp)
.InMicroseconds()));
builder.SetMetric(
"TimeToHandled",
std::max(static_cast<int64_t>(0),
(time_to_handled_timestamp - start_timestamp).InMicroseconds()));
builder.SetMetric("IsMainThread", is_main_thread);
builder.Record(ukm_recorder);
}
static bool IsJankyComparison(double tested_frames, double basis_frames) {
return tested_frames > basis_frames + 0.5 + 1e-9;
}
void LatencyTracker::ReportJankyFrame(base::TimeTicks original_timestamp,
base::TimeTicks gpu_swap_end_timestamp,
const ui::LatencyInfo& latency,
bool first_frame) {
DCHECK(!original_timestamp.is_null());
DCHECK(!gpu_swap_end_timestamp.is_null());
base::TimeDelta dur = gpu_swap_end_timestamp - original_timestamp;
if (first_frame) {
if (jank_state_.total_update_events_ > 0) {
UMA_HISTOGRAM_MEDIUM_TIMES("Event.Latency.ScrollUpdate.TotalDuration",
jank_state_.total_update_duration_);
UMA_HISTOGRAM_MEDIUM_TIMES("Event.Latency.ScrollUpdate.JankyDuration",
jank_state_.janky_update_duration_);
UMA_HISTOGRAM_COUNTS_10000("Event.Latency.ScrollUpdate.TotalEvents",
jank_state_.total_update_events_);
UMA_HISTOGRAM_COUNTS_10000("Event.Latency.ScrollUpdate.JankyEvents",
jank_state_.janky_update_events_);
if (!jank_state_.total_update_duration_.is_zero()) {
UMA_HISTOGRAM_PERCENTAGE(
"Event.Latency.ScrollUpdate.JankyDurationPercentage",
static_cast<int>(100 * (jank_state_.janky_update_duration_ /
jank_state_.total_update_duration_)));
}
}
jank_state_ = JankTrackerState{};
}
jank_state_.total_update_events_++;
jank_state_.total_update_duration_ += dur;
if (!first_frame) {
double frames_taken = dur.InSecondsF() * 60;
double prev_frames_taken = jank_state_.prev_duration_.InSecondsF() * 60;
if (!jank_state_.prev_scroll_update_reported_) {
bool janky = false;
if (IsJankyComparison(prev_frames_taken, frames_taken)) {
janky = true;
jank_state_.janky_update_events_++;
jank_state_.janky_update_duration_ += jank_state_.prev_duration_;
}
UMA_HISTOGRAM_BOOLEAN("Event.Latency.ScrollJank", janky);
EmitScrollUpdateTime(jank_state_.prev_duration_, janky);
}
if (IsJankyComparison(frames_taken, prev_frames_taken)) {
UMA_HISTOGRAM_BOOLEAN("Event.Latency.ScrollJank", true);
EmitScrollUpdateTime(dur, true);
jank_state_.janky_update_events_++;
jank_state_.janky_update_duration_ += dur;
jank_state_.prev_scroll_update_reported_ = true;
} else {
jank_state_.prev_scroll_update_reported_ = false;
}
}
jank_state_.prev_duration_ = dur;
}
void LatencyTracker::ComputeEndToEndLatencyHistograms(
base::TimeTicks gpu_swap_begin_timestamp,
base::TimeTicks gpu_swap_end_timestamp,
const ui::LatencyInfo& latency,
bool top_controls_visible_height_changed) {
DCHECK_AND_RETURN_ON_FAIL(!latency.coalesced());
base::TimeTicks original_timestamp;
if (latency.FindLatency(
ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
&original_timestamp)) {
ReportJankyFrame(original_timestamp, gpu_swap_end_timestamp, latency, true);
ScrollInputModality input_modality =
ToScrollInputModality(latency.source_event_type());
ScrollType scroll_type =
IsInertialScroll(latency) ? ScrollType::kInertial : ScrollType::kBegin;
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
"Event.Latency.ScrollBegin.TimeToScrollUpdateSwapBegin2",
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP(
"TimeToScrollUpdateSwapBegin4", scroll_type, input_modality,
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
if (top_controls_visible_height_changed) {
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP(
"TimeToScrollUpdateSwapBegin4.TopControlsMoved", scroll_type,
input_modality,
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
} else {
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP(
"TimeToScrollUpdateSwapBegin4.NoTopControlsMoved", scroll_type,
input_modality,
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
}
EmitLatencyHistograms(gpu_swap_begin_timestamp, gpu_swap_end_timestamp,
original_timestamp, latency, scroll_type,
input_modality);
} else if (latency.FindLatency(
ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
&original_timestamp)) {
ReportJankyFrame(original_timestamp, gpu_swap_end_timestamp, latency,
false);
ScrollInputModality input_modality =
ToScrollInputModality(latency.source_event_type());
ScrollType scroll_type =
IsInertialScroll(latency) ? ScrollType::kInertial : ScrollType::kUpdate;
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
"Event.Latency.ScrollUpdate.TimeToScrollUpdateSwapBegin2",
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP(
"TimeToScrollUpdateSwapBegin4", scroll_type, input_modality,
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
if (top_controls_visible_height_changed) {
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP(
"TimeToScrollUpdateSwapBegin4.TopControlsMoved", scroll_type,
input_modality,
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
} else {
UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS_GROUP(
"TimeToScrollUpdateSwapBegin4.NoTopControlsMoved", scroll_type,
input_modality,
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
}
EmitLatencyHistograms(gpu_swap_begin_timestamp, gpu_swap_end_timestamp,
original_timestamp, latency, scroll_type,
input_modality);
} else if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
&original_timestamp)) {
if (latency.source_event_type() == SourceEventType::KEY_PRESS) {
UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
"Event.Latency.EndToEnd.KeyPress",
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
} else if (latency.source_event_type() == SourceEventType::MOUSE) {
UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
"Event.Latency.EndToEnd.Mouse",
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
} else if (latency.source_event_type() == SourceEventType::TOUCHPAD) {
UMA_HISTOGRAM_INPUT_LATENCY_CUSTOM_1_SECOND_MAX_MICROSECONDS(
"Event.Latency.EndToEnd.TouchpadPinch2",
ComputeLatency(original_timestamp, gpu_swap_begin_timestamp));
}
}
}
void LatencyTracker::EmitLatencyHistograms(
base::TimeTicks gpu_swap_begin_timestamp,
base::TimeTicks gpu_swap_end_timestamp,
base::TimeTicks original_timestamp,
const ui::LatencyInfo& latency,
ScrollType scroll_type,
ScrollInputModality input_modality) {
DCHECK(!IsInertialScroll(latency) || scroll_type == ScrollType::kInertial);
if (!((input_modality == ScrollInputModality::kTouch &&
!IsInertialScroll(latency)) ||
input_modality == ScrollInputModality::kWheel)) {
return;
}
base::TimeTicks rendering_scheduled_timestamp;
bool rendering_scheduled_on_main = latency.FindLatency(
ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT,
&rendering_scheduled_timestamp);
if (!rendering_scheduled_on_main) {
bool found_component = latency.FindLatency(
ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT,
&rendering_scheduled_timestamp);
DCHECK_AND_RETURN_ON_FAIL(found_component);
}
InputMetricEvent input_metric_event;
if (scroll_type == ScrollType::kBegin) {
input_metric_event = input_modality == ScrollInputModality::kTouch
? InputMetricEvent::SCROLL_BEGIN_TOUCH
: InputMetricEvent::SCROLL_BEGIN_WHEEL;
} else {
DCHECK_EQ(scroll_type, ScrollType::kUpdate);
input_metric_event = input_modality == ScrollInputModality::kTouch
? InputMetricEvent::SCROLL_UPDATE_TOUCH
: InputMetricEvent::SCROLL_UPDATE_WHEEL;
}
ReportUkmScrollLatency(
input_metric_event, original_timestamp, gpu_swap_begin_timestamp,
rendering_scheduled_timestamp, rendering_scheduled_on_main,
latency.ukm_source_id());
}
}