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 "base/debug/trace_event.h"
6 #include "base/json/json_writer.h"
7 #include "base/memory/scoped_ptr.h"
8 #include "base/strings/stringprintf.h"
9 #include "ui/events/latency_info.h"
15 const size_t kMaxLatencyInfoNumber
= 100;
17 const char* GetComponentName(ui::LatencyComponentType type
) {
18 #define CASE_TYPE(t) case ui::t: return #t
20 CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT
);
21 CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT
);
22 CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_SCROLL_UPDATE_MAIN_COMPONENT
);
23 CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_RWH_COMPONENT
);
24 CASE_TYPE(INPUT_EVENT_LATENCY_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_COMPONENT
);
28 CASE_TYPE(INPUT_EVENT_LATENCY_FORWARD_SCROLL_UPDATE_TO_MAIN_COMPONENT
);
29 CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT
);
30 CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT
);
31 CASE_TYPE(WINDOW_OLD_SNAPSHOT_FRAME_NUMBER_COMPONENT
);
32 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT
);
33 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT
);
34 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT
);
35 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT
);
36 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT
);
37 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT
);
38 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT
);
39 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT
);
41 DLOG(WARNING
) << "Unhandled LatencyComponentType.\n";
48 bool IsTerminalComponent(ui::LatencyComponentType type
) {
50 case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT
:
51 case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT
:
52 case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT
:
53 case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT
:
54 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT
:
55 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT
:
56 case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT
:
57 case ui::INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT
:
64 bool IsBeginComponent(ui::LatencyComponentType type
) {
65 return (type
== ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT
||
66 type
== ui::INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT
||
67 type
== ui::INPUT_EVENT_LATENCY_BEGIN_SCROLL_UPDATE_MAIN_COMPONENT
);
70 // This class is for converting latency info to trace buffer friendly format.
71 class LatencyInfoTracedValue
: public base::debug::ConvertableToTraceFormat
{
73 static scoped_refptr
<ConvertableToTraceFormat
> FromValue(
74 scoped_ptr
<base::Value
> value
);
76 virtual void AppendAsTraceFormat(std::string
* out
) const OVERRIDE
;
79 explicit LatencyInfoTracedValue(base::Value
* value
);
80 virtual ~LatencyInfoTracedValue();
82 scoped_ptr
<base::Value
> value_
;
84 DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue
);
87 scoped_refptr
<base::debug::ConvertableToTraceFormat
>
88 LatencyInfoTracedValue::FromValue(scoped_ptr
<base::Value
> value
) {
89 return scoped_refptr
<base::debug::ConvertableToTraceFormat
>(
90 new LatencyInfoTracedValue(value
.release()));
93 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
96 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string
* out
) const {
98 base::JSONWriter::Write(value_
.get(), &tmp
);
102 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value
* value
)
106 // Converts latencyinfo into format that can be dumped into trace buffer.
107 scoped_refptr
<base::debug::ConvertableToTraceFormat
> AsTraceableData(
108 const ui::LatencyInfo
& latency
) {
109 scoped_ptr
<base::DictionaryValue
> record_data(new base::DictionaryValue());
110 for (ui::LatencyInfo::LatencyMap::const_iterator it
=
111 latency
.latency_components
.begin();
112 it
!= latency
.latency_components
.end(); ++it
) {
113 base::DictionaryValue
* component_info
= new base::DictionaryValue();
114 component_info
->SetDouble("comp_id", it
->first
.second
);
115 component_info
->SetDouble("time", it
->second
.event_time
.ToInternalValue());
116 component_info
->SetDouble("count", it
->second
.event_count
);
117 record_data
->Set(GetComponentName(it
->first
.first
), component_info
);
119 record_data
->SetDouble("trace_id", latency
.trace_id
);
120 return LatencyInfoTracedValue::FromValue(record_data
.PassAs
<base::Value
>());
127 LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
130 LatencyInfo::~LatencyInfo() {
133 bool LatencyInfo::Verify(const std::vector
<LatencyInfo
>& latency_info
,
134 const char* referring_msg
) {
135 if (latency_info
.size() > kMaxLatencyInfoNumber
) {
136 LOG(ERROR
) << referring_msg
<< ", LatencyInfo vector size "
137 << latency_info
.size() << " is too big.";
143 void LatencyInfo::CopyLatencyFrom(const LatencyInfo
& other
,
144 LatencyComponentType type
) {
145 for (LatencyMap::const_iterator it
= other
.latency_components
.begin();
146 it
!= other
.latency_components
.end();
148 if (it
->first
.first
== type
) {
149 AddLatencyNumberWithTimestamp(it
->first
.first
,
151 it
->second
.sequence_number
,
152 it
->second
.event_time
,
153 it
->second
.event_count
);
158 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo
& other
) {
159 for (LatencyMap::const_iterator it
= other
.latency_components
.begin();
160 it
!= other
.latency_components
.end();
162 if (!FindLatency(it
->first
.first
, it
->first
.second
, NULL
)) {
163 AddLatencyNumberWithTimestamp(it
->first
.first
,
165 it
->second
.sequence_number
,
166 it
->second
.event_time
,
167 it
->second
.event_count
);
172 void LatencyInfo::AddLatencyNumber(LatencyComponentType component
,
174 int64 component_sequence_number
) {
175 AddLatencyNumberWithTimestamp(component
, id
, component_sequence_number
,
176 base::TimeTicks::HighResNow(), 1);
179 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component
,
181 int64 component_sequence_number
,
182 base::TimeTicks time
,
183 uint32 event_count
) {
185 static const unsigned char* benchmark_enabled
=
186 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("benchmark");
188 if (IsBeginComponent(component
)) {
189 // Should only ever add begin component once.
190 CHECK_EQ(-1, trace_id
);
191 trace_id
= component_sequence_number
;
193 if (*benchmark_enabled
) {
194 // The timestamp for ASYNC_BEGIN trace event is used for drawing the
195 // beginning of the trace event in trace viewer. For better visualization,
196 // for an input event, we want to draw the beginning as when the event is
197 // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
198 // not when we actually issue the ASYNC_BEGIN trace event.
199 LatencyComponent component
;
201 if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT
,
204 FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT
,
207 // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock
208 // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0
209 // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on
210 // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and
211 // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we
212 // can't use a static value.
213 int64 diff
= base::TimeTicks::HighResNow().ToInternalValue() -
214 base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
215 ts
= component
.event_time
.ToInternalValue() - diff
;
217 ts
= base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
219 TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0(
222 TRACE_ID_DONT_MANGLE(trace_id
),
226 TRACE_EVENT_FLOW_BEGIN0(
227 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id
));
230 LatencyMap::key_type key
= std::make_pair(component
, id
);
231 LatencyMap::iterator it
= latency_components
.find(key
);
232 if (it
== latency_components
.end()) {
233 LatencyComponent info
= {component_sequence_number
, time
, event_count
};
234 latency_components
[key
] = info
;
236 it
->second
.sequence_number
= std::max(component_sequence_number
,
237 it
->second
.sequence_number
);
238 uint32 new_count
= event_count
+ it
->second
.event_count
;
239 if (event_count
> 0 && new_count
!= 0) {
240 // Do a weighted average, so that the new event_time is the average of
241 // the times of events currently in this structure with the time passed
243 it
->second
.event_time
+= (time
- it
->second
.event_time
) * event_count
/
245 it
->second
.event_count
= new_count
;
249 if (IsTerminalComponent(component
) && trace_id
!= -1) {
250 // Should only ever add terminal component once.
254 if (*benchmark_enabled
) {
255 TRACE_EVENT_ASYNC_END1("benchmark",
257 TRACE_ID_DONT_MANGLE(trace_id
),
258 "data", AsTraceableData(*this));
261 TRACE_EVENT_FLOW_END0(
262 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id
));
266 bool LatencyInfo::FindLatency(LatencyComponentType type
,
268 LatencyComponent
* output
) const {
269 LatencyMap::const_iterator it
= latency_components
.find(
270 std::make_pair(type
, id
));
271 if (it
== latency_components
.end())
274 *output
= it
->second
;
278 void LatencyInfo::RemoveLatency(LatencyComponentType type
) {
279 LatencyMap::iterator it
= latency_components
.begin();
280 while (it
!= latency_components
.end()) {
281 if (it
->first
.first
== type
) {
282 LatencyMap::iterator tmp
= it
;
284 latency_components
.erase(tmp
);
291 void LatencyInfo::Clear() {
292 latency_components
.clear();
295 void LatencyInfo::TraceEventType(const char* event_type
) {
296 TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
298 TRACE_ID_DONT_MANGLE(trace_id
),