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