1 // Copyright 2013 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
5 #include "ui/events/latency_info.h"
10 #include "base/json/json_writer.h"
11 #include "base/lazy_instance.h"
12 #include "base/strings/stringprintf.h"
16 const size_t kMaxLatencyInfoNumber
= 100;
18 const char* GetComponentName(ui::LatencyComponentType type
) {
19 #define CASE_TYPE(t) case ui::t: return #t
21 CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT
);
22 CASE_TYPE(LATENCY_BEGIN_SCROLL_LISTENER_UPDATE_MAIN_COMPONENT
);
23 CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT
);
24 CASE_TYPE(INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT
);
25 CASE_TYPE(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT
);
26 CASE_TYPE(INPUT_EVENT_LATENCY_UI_COMPONENT
);
27 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT
);
28 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT
);
29 CASE_TYPE(INPUT_EVENT_LATENCY_FORWARD_SCROLL_UPDATE_TO_MAIN_COMPONENT
);
30 CASE_TYPE(INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT
);
31 CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT
);
32 CASE_TYPE(TAB_SHOW_COMPONENT
);
33 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT
);
34 CASE_TYPE(INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT
);
35 CASE_TYPE(INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT
);
36 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT
);
37 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_WHEEL_COMPONENT
);
38 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT
);
39 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT
);
40 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT
);
41 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT
);
42 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT
);
43 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT
);
44 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT
);
46 DLOG(WARNING
) << "Unhandled LatencyComponentType.\n";
53 bool IsTerminalComponent(ui::LatencyComponentType type
) {
55 case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT
:
56 case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_WHEEL_COMPONENT
:
57 case ui::INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT
:
58 case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT
:
59 case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT
:
60 case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT
:
61 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT
:
62 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT
:
63 case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT
:
70 bool IsBeginComponent(ui::LatencyComponentType type
) {
71 return (type
== ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT
||
72 type
== ui::LATENCY_BEGIN_SCROLL_LISTENER_UPDATE_MAIN_COMPONENT
);
75 bool IsInputLatencyBeginComponent(ui::LatencyComponentType type
) {
76 return type
== ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT
;
79 // This class is for converting latency info to trace buffer friendly format.
80 class LatencyInfoTracedValue
81 : public base::trace_event::ConvertableToTraceFormat
{
83 static scoped_refptr
<ConvertableToTraceFormat
> FromValue(
84 scoped_ptr
<base::Value
> value
);
86 void AppendAsTraceFormat(std::string
* out
) const override
;
89 explicit LatencyInfoTracedValue(base::Value
* value
);
90 ~LatencyInfoTracedValue() override
;
92 scoped_ptr
<base::Value
> value_
;
94 DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue
);
97 scoped_refptr
<base::trace_event::ConvertableToTraceFormat
>
98 LatencyInfoTracedValue::FromValue(scoped_ptr
<base::Value
> value
) {
99 return scoped_refptr
<base::trace_event::ConvertableToTraceFormat
>(
100 new LatencyInfoTracedValue(value
.release()));
103 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
106 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string
* out
) const {
108 base::JSONWriter::Write(*value_
, &tmp
);
112 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value
* value
)
116 struct BenchmarkEnabledInitializer
{
117 BenchmarkEnabledInitializer() :
118 benchmark_enabled(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
122 const unsigned char* benchmark_enabled
;
125 static base::LazyInstance
<BenchmarkEnabledInitializer
>::Leaky
126 g_benchmark_enabled
= LAZY_INSTANCE_INITIALIZER
;
132 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) {
135 LatencyInfo::InputCoordinate::InputCoordinate(float x
, float y
) : x(x
), y(y
) {
138 LatencyInfo::LatencyInfo()
139 : input_coordinates_size_(0), trace_id_(-1), terminated_(false) {
142 LatencyInfo::~LatencyInfo() {
145 LatencyInfo::LatencyInfo(int64 trace_id
, bool terminated
)
146 : input_coordinates_size_(0), trace_id_(trace_id
), terminated_(terminated
) {
149 bool LatencyInfo::Verify(const std::vector
<LatencyInfo
>& latency_info
,
150 const char* referring_msg
) {
151 if (latency_info
.size() > kMaxLatencyInfoNumber
) {
152 LOG(ERROR
) << referring_msg
<< ", LatencyInfo vector size "
153 << latency_info
.size() << " is too big.";
159 void LatencyInfo::CopyLatencyFrom(const LatencyInfo
& other
,
160 LatencyComponentType type
) {
161 for (const auto& lc
: other
.latency_components()) {
162 if (lc
.first
.first
== type
) {
163 AddLatencyNumberWithTimestamp(lc
.first
.first
,
165 lc
.second
.sequence_number
,
166 lc
.second
.event_time
,
167 lc
.second
.event_count
);
172 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo
& other
) {
173 for (const auto& lc
: other
.latency_components()) {
174 if (!FindLatency(lc
.first
.first
, lc
.first
.second
, NULL
)) {
175 AddLatencyNumberWithTimestamp(lc
.first
.first
,
177 lc
.second
.sequence_number
,
178 lc
.second
.event_time
,
179 lc
.second
.event_count
);
184 void LatencyInfo::AddLatencyNumber(LatencyComponentType component
,
186 int64 component_sequence_number
) {
187 AddLatencyNumberWithTimestampImpl(component
, id
, component_sequence_number
,
188 base::TimeTicks::Now(), 1, nullptr);
191 void LatencyInfo::AddLatencyNumberWithTraceName(
192 LatencyComponentType component
,
194 int64 component_sequence_number
,
195 const char* trace_name_str
) {
196 AddLatencyNumberWithTimestampImpl(component
, id
, component_sequence_number
,
197 base::TimeTicks::Now(), 1, trace_name_str
);
200 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component
,
202 int64 component_sequence_number
,
203 base::TimeTicks time
,
204 uint32 event_count
) {
205 AddLatencyNumberWithTimestampImpl(component
, id
, component_sequence_number
,
206 time
, event_count
, nullptr);
209 void LatencyInfo::AddLatencyNumberWithTimestampImpl(
210 LatencyComponentType component
,
212 int64 component_sequence_number
,
213 base::TimeTicks time
,
215 const char* trace_name_str
) {
217 const unsigned char* benchmark_enabled
=
218 g_benchmark_enabled
.Get().benchmark_enabled
;
220 if (IsBeginComponent(component
)) {
221 // Should only ever add begin component once.
222 CHECK_EQ(-1, trace_id_
);
223 trace_id_
= component_sequence_number
;
225 if (*benchmark_enabled
) {
226 // The timestamp for ASYNC_BEGIN trace event is used for drawing the
227 // beginning of the trace event in trace viewer. For better visualization,
228 // for an input event, we want to draw the beginning as when the event is
229 // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
230 // not when we actually issue the ASYNC_BEGIN trace event.
231 LatencyComponent begin_component
;
233 if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT
,
236 FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT
,
239 // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock
240 // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0
241 // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on
242 // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and
243 // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we
244 // can't use a static value.
245 base::TimeDelta diff
= (base::TimeTicks::Now() - base::TimeTicks()) -
246 (base::TraceTicks::Now() - base::TraceTicks());
247 ts
= (begin_component
.event_time
- diff
).ToInternalValue();
249 ts
= base::TraceTicks::Now().ToInternalValue();
252 if (trace_name_str
) {
253 if (IsInputLatencyBeginComponent(component
))
254 trace_name_
= std::string("InputLatency::") + trace_name_str
;
256 trace_name_
= std::string("Latency::") + trace_name_str
;
259 TRACE_EVENT_COPY_ASYNC_BEGIN_WITH_TIMESTAMP0(
260 "benchmark,latencyInfo",
262 TRACE_ID_DONT_MANGLE(trace_id_
),
266 TRACE_EVENT_FLOW_BEGIN1(
267 "input,benchmark", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id_
),
268 "trace_id", trace_id_
);
271 LatencyMap::key_type key
= std::make_pair(component
, id
);
272 LatencyMap::iterator it
= latency_components_
.find(key
);
273 if (it
== latency_components_
.end()) {
274 LatencyComponent info
= {component_sequence_number
, time
, event_count
};
275 latency_components_
[key
] = info
;
277 it
->second
.sequence_number
= std::max(component_sequence_number
,
278 it
->second
.sequence_number
);
279 uint32 new_count
= event_count
+ it
->second
.event_count
;
280 if (event_count
> 0 && new_count
!= 0) {
281 // Do a weighted average, so that the new event_time is the average of
282 // the times of events currently in this structure with the time passed
284 it
->second
.event_time
+= (time
- it
->second
.event_time
) * event_count
/
286 it
->second
.event_count
= new_count
;
290 if (IsTerminalComponent(component
) && trace_id_
!= -1) {
291 // Should only ever add terminal component once.
295 if (*benchmark_enabled
) {
296 TRACE_EVENT_COPY_ASYNC_END1("benchmark,latencyInfo",
298 TRACE_ID_DONT_MANGLE(trace_id_
),
299 "data", AsTraceableData());
302 TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0(
303 "input,benchmark", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id_
));
307 scoped_refptr
<base::trace_event::ConvertableToTraceFormat
>
308 LatencyInfo::AsTraceableData() {
309 scoped_ptr
<base::DictionaryValue
> record_data(new base::DictionaryValue());
310 for (const auto& lc
: latency_components_
) {
311 scoped_ptr
<base::DictionaryValue
>
312 component_info(new base::DictionaryValue());
313 component_info
->SetDouble("comp_id", static_cast<double>(lc
.first
.second
));
314 component_info
->SetDouble(
316 static_cast<double>(lc
.second
.event_time
.ToInternalValue()));
317 component_info
->SetDouble("count", lc
.second
.event_count
);
318 component_info
->SetDouble("sequence_number",
319 lc
.second
.sequence_number
);
320 record_data
->Set(GetComponentName(lc
.first
.first
), component_info
.Pass());
322 record_data
->SetDouble("trace_id", static_cast<double>(trace_id_
));
324 scoped_ptr
<base::ListValue
> coordinates(new base::ListValue());
325 for (size_t i
= 0; i
< input_coordinates_size_
; i
++) {
326 scoped_ptr
<base::DictionaryValue
> coordinate_pair(
327 new base::DictionaryValue());
328 coordinate_pair
->SetDouble("x", input_coordinates_
[i
].x
);
329 coordinate_pair
->SetDouble("y", input_coordinates_
[i
].y
);
330 coordinates
->Append(coordinate_pair
.release());
332 record_data
->Set("coordinates", coordinates
.release());
333 return LatencyInfoTracedValue::FromValue(record_data
.Pass());
336 bool LatencyInfo::FindLatency(LatencyComponentType type
,
338 LatencyComponent
* output
) const {
339 LatencyMap::const_iterator it
= latency_components_
.find(
340 std::make_pair(type
, id
));
341 if (it
== latency_components_
.end())
344 *output
= it
->second
;
348 void LatencyInfo::RemoveLatency(LatencyComponentType type
) {
349 LatencyMap::iterator it
= latency_components_
.begin();
350 while (it
!= latency_components_
.end()) {
351 if (it
->first
.first
== type
) {
352 LatencyMap::iterator tmp
= it
;
354 latency_components_
.erase(tmp
);
361 bool LatencyInfo::AddInputCoordinate(const InputCoordinate
& input_coordinate
) {
362 if (input_coordinates_size_
>= kMaxInputCoordinates
)
364 input_coordinates_
[input_coordinates_size_
++] = input_coordinate
;