OLD | NEW |
| (Empty) |
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 "ui/events/latency_info.h" | |
6 | |
7 #include <stddef.h> | |
8 | |
9 #include <algorithm> | |
10 #include <string> | |
11 #include <utility> | |
12 | |
13 #include "base/json/json_writer.h" | |
14 #include "base/lazy_instance.h" | |
15 #include "base/macros.h" | |
16 #include "base/strings/stringprintf.h" | |
17 | |
18 namespace { | |
19 | |
20 const size_t kMaxLatencyInfoNumber = 100; | |
21 | |
22 const char* GetComponentName(ui::LatencyComponentType type) { | |
23 #define CASE_TYPE(t) case ui::t: return #t | |
24 switch (type) { | |
25 CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT); | |
26 CASE_TYPE(LATENCY_BEGIN_SCROLL_LISTENER_UPDATE_MAIN_COMPONENT); | |
27 CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT); | |
28 CASE_TYPE(INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT); | |
29 CASE_TYPE(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT); | |
30 CASE_TYPE(INPUT_EVENT_LATENCY_UI_COMPONENT); | |
31 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT); | |
32 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT); | |
33 CASE_TYPE(INPUT_EVENT_LATENCY_FORWARD_SCROLL_UPDATE_TO_MAIN_COMPONENT); | |
34 CASE_TYPE(INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT); | |
35 CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT); | |
36 CASE_TYPE(TAB_SHOW_COMPONENT); | |
37 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERER_MAIN_COMPONENT); | |
38 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT); | |
39 CASE_TYPE(INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT); | |
40 CASE_TYPE(INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT); | |
41 CASE_TYPE(INPUT_EVENT_LATENCY_GENERATE_SCROLL_UPDATE_FROM_MOUSE_WHEEL); | |
42 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT); | |
43 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_WHEEL_COMPONENT); | |
44 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT); | |
45 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT); | |
46 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT); | |
47 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT); | |
48 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT); | |
49 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT); | |
50 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT); | |
51 default: | |
52 DLOG(WARNING) << "Unhandled LatencyComponentType.\n"; | |
53 break; | |
54 } | |
55 #undef CASE_TYPE | |
56 return "unknown"; | |
57 } | |
58 | |
59 bool IsTerminalComponent(ui::LatencyComponentType type) { | |
60 switch (type) { | |
61 case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT: | |
62 case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_WHEEL_COMPONENT: | |
63 case ui::INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT: | |
64 case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT: | |
65 case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT: | |
66 case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT: | |
67 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT: | |
68 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT: | |
69 case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT: | |
70 return true; | |
71 default: | |
72 return false; | |
73 } | |
74 } | |
75 | |
76 bool IsBeginComponent(ui::LatencyComponentType type) { | |
77 return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT || | |
78 type == ui::LATENCY_BEGIN_SCROLL_LISTENER_UPDATE_MAIN_COMPONENT); | |
79 } | |
80 | |
81 bool IsInputLatencyBeginComponent(ui::LatencyComponentType type) { | |
82 return type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT; | |
83 } | |
84 | |
85 // This class is for converting latency info to trace buffer friendly format. | |
86 class LatencyInfoTracedValue | |
87 : public base::trace_event::ConvertableToTraceFormat { | |
88 public: | |
89 static std::unique_ptr<ConvertableToTraceFormat> FromValue( | |
90 std::unique_ptr<base::Value> value); | |
91 | |
92 void AppendAsTraceFormat(std::string* out) const override; | |
93 | |
94 private: | |
95 explicit LatencyInfoTracedValue(base::Value* value); | |
96 ~LatencyInfoTracedValue() override; | |
97 | |
98 std::unique_ptr<base::Value> value_; | |
99 | |
100 DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue); | |
101 }; | |
102 | |
103 std::unique_ptr<base::trace_event::ConvertableToTraceFormat> | |
104 LatencyInfoTracedValue::FromValue(std::unique_ptr<base::Value> value) { | |
105 return std::unique_ptr<base::trace_event::ConvertableToTraceFormat>( | |
106 new LatencyInfoTracedValue(value.release())); | |
107 } | |
108 | |
109 LatencyInfoTracedValue::~LatencyInfoTracedValue() { | |
110 } | |
111 | |
112 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const { | |
113 std::string tmp; | |
114 base::JSONWriter::Write(*value_, &tmp); | |
115 *out += tmp; | |
116 } | |
117 | |
118 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value) | |
119 : value_(value) { | |
120 } | |
121 | |
122 const char kTraceCategoriesForAsyncEvents[] = "benchmark,latencyInfo"; | |
123 | |
124 struct LatencyInfoEnabledInitializer { | |
125 LatencyInfoEnabledInitializer() : | |
126 latency_info_enabled(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED( | |
127 kTraceCategoriesForAsyncEvents)) { | |
128 } | |
129 | |
130 const unsigned char* latency_info_enabled; | |
131 }; | |
132 | |
133 static base::LazyInstance<LatencyInfoEnabledInitializer>::Leaky | |
134 g_latency_info_enabled = LAZY_INSTANCE_INITIALIZER; | |
135 | |
136 } // namespace | |
137 | |
138 namespace ui { | |
139 | |
140 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) { | |
141 } | |
142 | |
143 LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) { | |
144 } | |
145 | |
146 LatencyInfo::LatencyInfo() | |
147 : input_coordinates_size_(0), | |
148 trace_id_(-1), | |
149 coalesced_(false), | |
150 terminated_(false) {} | |
151 | |
152 LatencyInfo::LatencyInfo(const LatencyInfo& other) = default; | |
153 | |
154 LatencyInfo::~LatencyInfo() {} | |
155 | |
156 LatencyInfo::LatencyInfo(int64_t trace_id, bool terminated) | |
157 : input_coordinates_size_(0), | |
158 trace_id_(trace_id), | |
159 terminated_(terminated) {} | |
160 | |
161 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info, | |
162 const char* referring_msg) { | |
163 if (latency_info.size() > kMaxLatencyInfoNumber) { | |
164 LOG(ERROR) << referring_msg << ", LatencyInfo vector size " | |
165 << latency_info.size() << " is too big."; | |
166 TRACE_EVENT_INSTANT1("input,benchmark", "LatencyInfo::Verify Fails", | |
167 TRACE_EVENT_SCOPE_GLOBAL, | |
168 "size", latency_info.size()); | |
169 return false; | |
170 } | |
171 return true; | |
172 } | |
173 | |
174 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other, | |
175 LatencyComponentType type) { | |
176 for (const auto& lc : other.latency_components()) { | |
177 if (lc.first.first == type) { | |
178 AddLatencyNumberWithTimestamp(lc.first.first, | |
179 lc.first.second, | |
180 lc.second.sequence_number, | |
181 lc.second.event_time, | |
182 lc.second.event_count); | |
183 } | |
184 } | |
185 } | |
186 | |
187 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) { | |
188 for (const auto& lc : other.latency_components()) { | |
189 if (!FindLatency(lc.first.first, lc.first.second, NULL)) { | |
190 AddLatencyNumberWithTimestamp(lc.first.first, | |
191 lc.first.second, | |
192 lc.second.sequence_number, | |
193 lc.second.event_time, | |
194 lc.second.event_count); | |
195 } | |
196 } | |
197 } | |
198 | |
199 void LatencyInfo::AddLatencyNumber(LatencyComponentType component, | |
200 int64_t id, | |
201 int64_t component_sequence_number) { | |
202 AddLatencyNumberWithTimestampImpl(component, id, component_sequence_number, | |
203 base::TimeTicks::Now(), 1, nullptr); | |
204 } | |
205 | |
206 void LatencyInfo::AddLatencyNumberWithTraceName( | |
207 LatencyComponentType component, | |
208 int64_t id, | |
209 int64_t component_sequence_number, | |
210 const char* trace_name_str) { | |
211 AddLatencyNumberWithTimestampImpl(component, id, component_sequence_number, | |
212 base::TimeTicks::Now(), 1, trace_name_str); | |
213 } | |
214 | |
215 void LatencyInfo::AddLatencyNumberWithTimestamp( | |
216 LatencyComponentType component, | |
217 int64_t id, | |
218 int64_t component_sequence_number, | |
219 base::TimeTicks time, | |
220 uint32_t event_count) { | |
221 AddLatencyNumberWithTimestampImpl(component, id, component_sequence_number, | |
222 time, event_count, nullptr); | |
223 } | |
224 | |
225 void LatencyInfo::AddLatencyNumberWithTimestampImpl( | |
226 LatencyComponentType component, | |
227 int64_t id, | |
228 int64_t component_sequence_number, | |
229 base::TimeTicks time, | |
230 uint32_t event_count, | |
231 const char* trace_name_str) { | |
232 const unsigned char* latency_info_enabled = | |
233 g_latency_info_enabled.Get().latency_info_enabled; | |
234 | |
235 if (IsBeginComponent(component)) { | |
236 // Should only ever add begin component once. | |
237 CHECK_EQ(-1, trace_id_); | |
238 trace_id_ = component_sequence_number; | |
239 | |
240 if (*latency_info_enabled) { | |
241 // The timestamp for ASYNC_BEGIN trace event is used for drawing the | |
242 // beginning of the trace event in trace viewer. For better visualization, | |
243 // for an input event, we want to draw the beginning as when the event is | |
244 // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT, | |
245 // not when we actually issue the ASYNC_BEGIN trace event. | |
246 LatencyComponent begin_component; | |
247 int64_t ts = 0; | |
248 if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, | |
249 0, | |
250 &begin_component) || | |
251 FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT, | |
252 0, | |
253 &begin_component)) { | |
254 ts = begin_component.event_time.ToInternalValue(); | |
255 } else { | |
256 ts = base::TimeTicks::Now().ToInternalValue(); | |
257 } | |
258 | |
259 if (trace_name_str) { | |
260 if (IsInputLatencyBeginComponent(component)) | |
261 trace_name_ = std::string("InputLatency::") + trace_name_str; | |
262 else | |
263 trace_name_ = std::string("Latency::") + trace_name_str; | |
264 } | |
265 | |
266 TRACE_EVENT_COPY_ASYNC_BEGIN_WITH_TIMESTAMP0( | |
267 kTraceCategoriesForAsyncEvents, | |
268 trace_name_.c_str(), | |
269 TRACE_ID_DONT_MANGLE(trace_id_), | |
270 ts); | |
271 } | |
272 | |
273 TRACE_EVENT_WITH_FLOW1("input,benchmark", | |
274 "LatencyInfo.Flow", | |
275 TRACE_ID_DONT_MANGLE(trace_id_), | |
276 TRACE_EVENT_FLAG_FLOW_OUT, | |
277 "trace_id", trace_id_); | |
278 } | |
279 | |
280 LatencyMap::key_type key = std::make_pair(component, id); | |
281 LatencyMap::iterator it = latency_components_.find(key); | |
282 if (it == latency_components_.end()) { | |
283 LatencyComponent info = {component_sequence_number, time, event_count}; | |
284 latency_components_[key] = info; | |
285 } else { | |
286 it->second.sequence_number = std::max(component_sequence_number, | |
287 it->second.sequence_number); | |
288 uint32_t new_count = event_count + it->second.event_count; | |
289 if (event_count > 0 && new_count != 0) { | |
290 // Do a weighted average, so that the new event_time is the average of | |
291 // the times of events currently in this structure with the time passed | |
292 // into this method. | |
293 it->second.event_time += (time - it->second.event_time) * event_count / | |
294 new_count; | |
295 it->second.event_count = new_count; | |
296 } | |
297 } | |
298 | |
299 if (IsTerminalComponent(component) && trace_id_ != -1) { | |
300 // Should only ever add terminal component once. | |
301 CHECK(!terminated_); | |
302 terminated_ = true; | |
303 | |
304 if (*latency_info_enabled) { | |
305 TRACE_EVENT_COPY_ASYNC_END2(kTraceCategoriesForAsyncEvents, | |
306 trace_name_.c_str(), | |
307 TRACE_ID_DONT_MANGLE(trace_id_), | |
308 "data", AsTraceableData(), | |
309 "coordinates", CoordinatesAsTraceableData()); | |
310 } | |
311 | |
312 TRACE_EVENT_WITH_FLOW0("input,benchmark", | |
313 "LatencyInfo.Flow", | |
314 TRACE_ID_DONT_MANGLE(trace_id_), | |
315 TRACE_EVENT_FLAG_FLOW_IN); | |
316 } | |
317 } | |
318 | |
319 std::unique_ptr<base::trace_event::ConvertableToTraceFormat> | |
320 LatencyInfo::AsTraceableData() { | |
321 std::unique_ptr<base::DictionaryValue> record_data( | |
322 new base::DictionaryValue()); | |
323 for (const auto& lc : latency_components_) { | |
324 std::unique_ptr<base::DictionaryValue> component_info( | |
325 new base::DictionaryValue()); | |
326 component_info->SetDouble("comp_id", static_cast<double>(lc.first.second)); | |
327 component_info->SetDouble( | |
328 "time", | |
329 static_cast<double>(lc.second.event_time.ToInternalValue())); | |
330 component_info->SetDouble("count", lc.second.event_count); | |
331 component_info->SetDouble("sequence_number", | |
332 lc.second.sequence_number); | |
333 record_data->Set(GetComponentName(lc.first.first), | |
334 std::move(component_info)); | |
335 } | |
336 record_data->SetDouble("trace_id", static_cast<double>(trace_id_)); | |
337 return LatencyInfoTracedValue::FromValue(std::move(record_data)); | |
338 } | |
339 | |
340 std::unique_ptr<base::trace_event::ConvertableToTraceFormat> | |
341 LatencyInfo::CoordinatesAsTraceableData() { | |
342 std::unique_ptr<base::ListValue> coordinates(new base::ListValue()); | |
343 for (size_t i = 0; i < input_coordinates_size_; i++) { | |
344 std::unique_ptr<base::DictionaryValue> coordinate_pair( | |
345 new base::DictionaryValue()); | |
346 coordinate_pair->SetDouble("x", input_coordinates_[i].x); | |
347 coordinate_pair->SetDouble("y", input_coordinates_[i].y); | |
348 coordinates->Append(coordinate_pair.release()); | |
349 } | |
350 return LatencyInfoTracedValue::FromValue(std::move(coordinates)); | |
351 } | |
352 | |
353 bool LatencyInfo::FindLatency(LatencyComponentType type, | |
354 int64_t id, | |
355 LatencyComponent* output) const { | |
356 LatencyMap::const_iterator it = latency_components_.find( | |
357 std::make_pair(type, id)); | |
358 if (it == latency_components_.end()) | |
359 return false; | |
360 if (output) | |
361 *output = it->second; | |
362 return true; | |
363 } | |
364 | |
365 void LatencyInfo::RemoveLatency(LatencyComponentType type) { | |
366 LatencyMap::iterator it = latency_components_.begin(); | |
367 while (it != latency_components_.end()) { | |
368 if (it->first.first == type) { | |
369 LatencyMap::iterator tmp = it; | |
370 ++it; | |
371 latency_components_.erase(tmp); | |
372 } else { | |
373 it++; | |
374 } | |
375 } | |
376 } | |
377 | |
378 bool LatencyInfo::AddInputCoordinate(const InputCoordinate& input_coordinate) { | |
379 if (input_coordinates_size_ >= kMaxInputCoordinates) | |
380 return false; | |
381 input_coordinates_[input_coordinates_size_++] = input_coordinate; | |
382 return true; | |
383 } | |
384 | |
385 } // namespace ui | |
OLD | NEW |