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.
4
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"
10
11 #include <algorithm>
12
13 namespace {
14
15 const size_t kMaxLatencyInfoNumber = 100;
16
GetComponentName(ui::LatencyComponentType type)17 const char* GetComponentName(ui::LatencyComponentType type) {
18 #define CASE_TYPE(t) case ui::t: return #t
19 switch (type) {
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);
40 default:
41 DLOG(WARNING) << "Unhandled LatencyComponentType.\n";
42 break;
43 }
44 #undef CASE_TYPE
45 return "unknown";
46 }
47
IsTerminalComponent(ui::LatencyComponentType type)48 bool IsTerminalComponent(ui::LatencyComponentType type) {
49 switch (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:
58 return true;
59 default:
60 return false;
61 }
62 }
63
IsBeginComponent(ui::LatencyComponentType type)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);
68 }
69
70 // This class is for converting latency info to trace buffer friendly format.
71 class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat {
72 public:
73 static scoped_refptr<ConvertableToTraceFormat> FromValue(
74 scoped_ptr<base::Value> value);
75
76 virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE;
77
78 private:
79 explicit LatencyInfoTracedValue(base::Value* value);
80 virtual ~LatencyInfoTracedValue();
81
82 scoped_ptr<base::Value> value_;
83
84 DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue);
85 };
86
87 scoped_refptr<base::debug::ConvertableToTraceFormat>
FromValue(scoped_ptr<base::Value> value)88 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
89 return scoped_refptr<base::debug::ConvertableToTraceFormat>(
90 new LatencyInfoTracedValue(value.release()));
91 }
92
~LatencyInfoTracedValue()93 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
94 }
95
AppendAsTraceFormat(std::string * out) const96 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
97 std::string tmp;
98 base::JSONWriter::Write(value_.get(), &tmp);
99 *out += tmp;
100 }
101
LatencyInfoTracedValue(base::Value * value)102 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
103 : value_(value) {
104 }
105
106 // Converts latencyinfo into format that can be dumped into trace buffer.
AsTraceableData(const ui::LatencyInfo & latency)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);
118 }
119 record_data->SetDouble("trace_id", latency.trace_id);
120
121 scoped_ptr<base::ListValue> coordinates(new base::ListValue());
122 for (size_t i = 0; i < latency.input_coordinates_size; i++) {
123 scoped_ptr<base::DictionaryValue> coordinate_pair(
124 new base::DictionaryValue());
125 coordinate_pair->SetDouble("x", latency.input_coordinates[i].x);
126 coordinate_pair->SetDouble("y", latency.input_coordinates[i].y);
127 coordinates->Append(coordinate_pair.release());
128 }
129 record_data->Set("coordinates", coordinates.release());
130 return LatencyInfoTracedValue::FromValue(record_data.PassAs<base::Value>());
131 }
132
133 } // namespace
134
135 namespace ui {
136
InputCoordinate()137 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) {
138 }
139
InputCoordinate(float x,float y)140 LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) {
141 }
142
LatencyInfo()143 LatencyInfo::LatencyInfo()
144 : input_coordinates_size(0), trace_id(-1), terminated(false) {
145 }
146
~LatencyInfo()147 LatencyInfo::~LatencyInfo() {
148 }
149
Verify(const std::vector<LatencyInfo> & latency_info,const char * referring_msg)150 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info,
151 const char* referring_msg) {
152 if (latency_info.size() > kMaxLatencyInfoNumber) {
153 LOG(ERROR) << referring_msg << ", LatencyInfo vector size "
154 << latency_info.size() << " is too big.";
155 return false;
156 }
157 for (size_t i = 0; i < latency_info.size(); i++) {
158 if (latency_info[i].input_coordinates_size > kMaxInputCoordinates) {
159 LOG(ERROR) << referring_msg << ", coordinate vector size "
160 << latency_info[i].input_coordinates_size << " is too big.";
161 return false;
162 }
163 }
164
165 return true;
166 }
167
CopyLatencyFrom(const LatencyInfo & other,LatencyComponentType type)168 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other,
169 LatencyComponentType type) {
170 for (LatencyMap::const_iterator it = other.latency_components.begin();
171 it != other.latency_components.end();
172 ++it) {
173 if (it->first.first == type) {
174 AddLatencyNumberWithTimestamp(it->first.first,
175 it->first.second,
176 it->second.sequence_number,
177 it->second.event_time,
178 it->second.event_count);
179 }
180 }
181 }
182
AddNewLatencyFrom(const LatencyInfo & other)183 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
184 for (LatencyMap::const_iterator it = other.latency_components.begin();
185 it != other.latency_components.end();
186 ++it) {
187 if (!FindLatency(it->first.first, it->first.second, NULL)) {
188 AddLatencyNumberWithTimestamp(it->first.first,
189 it->first.second,
190 it->second.sequence_number,
191 it->second.event_time,
192 it->second.event_count);
193 }
194 }
195 }
196
AddLatencyNumber(LatencyComponentType component,int64 id,int64 component_sequence_number)197 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
198 int64 id,
199 int64 component_sequence_number) {
200 AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
201 base::TimeTicks::HighResNow(), 1);
202 }
203
AddLatencyNumberWithTimestamp(LatencyComponentType component,int64 id,int64 component_sequence_number,base::TimeTicks time,uint32 event_count)204 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
205 int64 id,
206 int64 component_sequence_number,
207 base::TimeTicks time,
208 uint32 event_count) {
209
210 static const unsigned char* benchmark_enabled =
211 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("benchmark");
212
213 if (IsBeginComponent(component)) {
214 // Should only ever add begin component once.
215 CHECK_EQ(-1, trace_id);
216 trace_id = component_sequence_number;
217
218 if (*benchmark_enabled) {
219 // The timestamp for ASYNC_BEGIN trace event is used for drawing the
220 // beginning of the trace event in trace viewer. For better visualization,
221 // for an input event, we want to draw the beginning as when the event is
222 // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
223 // not when we actually issue the ASYNC_BEGIN trace event.
224 LatencyComponent component;
225 int64 ts = 0;
226 if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
227 0,
228 &component) ||
229 FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT,
230 0,
231 &component)) {
232 // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock
233 // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0
234 // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on
235 // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and
236 // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we
237 // can't use a static value.
238 int64 diff = base::TimeTicks::HighResNow().ToInternalValue() -
239 base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
240 ts = component.event_time.ToInternalValue() - diff;
241 } else {
242 ts = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
243 }
244 TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0(
245 "benchmark",
246 "InputLatency",
247 TRACE_ID_DONT_MANGLE(trace_id),
248 ts);
249 }
250
251 TRACE_EVENT_FLOW_BEGIN0(
252 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
253 }
254
255 LatencyMap::key_type key = std::make_pair(component, id);
256 LatencyMap::iterator it = latency_components.find(key);
257 if (it == latency_components.end()) {
258 LatencyComponent info = {component_sequence_number, time, event_count};
259 latency_components[key] = info;
260 } else {
261 it->second.sequence_number = std::max(component_sequence_number,
262 it->second.sequence_number);
263 uint32 new_count = event_count + it->second.event_count;
264 if (event_count > 0 && new_count != 0) {
265 // Do a weighted average, so that the new event_time is the average of
266 // the times of events currently in this structure with the time passed
267 // into this method.
268 it->second.event_time += (time - it->second.event_time) * event_count /
269 new_count;
270 it->second.event_count = new_count;
271 }
272 }
273
274 if (IsTerminalComponent(component) && trace_id != -1) {
275 // Should only ever add terminal component once.
276 CHECK(!terminated);
277 terminated = true;
278
279 if (*benchmark_enabled) {
280 TRACE_EVENT_ASYNC_END1("benchmark",
281 "InputLatency",
282 TRACE_ID_DONT_MANGLE(trace_id),
283 "data", AsTraceableData(*this));
284 }
285
286 TRACE_EVENT_FLOW_END0(
287 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
288 }
289 }
290
FindLatency(LatencyComponentType type,int64 id,LatencyComponent * output) const291 bool LatencyInfo::FindLatency(LatencyComponentType type,
292 int64 id,
293 LatencyComponent* output) const {
294 LatencyMap::const_iterator it = latency_components.find(
295 std::make_pair(type, id));
296 if (it == latency_components.end())
297 return false;
298 if (output)
299 *output = it->second;
300 return true;
301 }
302
RemoveLatency(LatencyComponentType type)303 void LatencyInfo::RemoveLatency(LatencyComponentType type) {
304 LatencyMap::iterator it = latency_components.begin();
305 while (it != latency_components.end()) {
306 if (it->first.first == type) {
307 LatencyMap::iterator tmp = it;
308 ++it;
309 latency_components.erase(tmp);
310 } else {
311 it++;
312 }
313 }
314 }
315
Clear()316 void LatencyInfo::Clear() {
317 latency_components.clear();
318 }
319
TraceEventType(const char * event_type)320 void LatencyInfo::TraceEventType(const char* event_type) {
321 TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
322 "InputLatency",
323 TRACE_ID_DONT_MANGLE(trace_id),
324 event_type);
325 }
326
327 } // namespace ui
328