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 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 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 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> 88 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) { 89 return scoped_refptr<base::debug::ConvertableToTraceFormat>( 90 new LatencyInfoTracedValue(value.release())); 91 } 92 93 LatencyInfoTracedValue::~LatencyInfoTracedValue() { 94 } 95 96 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const { 97 std::string tmp; 98 base::JSONWriter::Write(value_.get(), &tmp); 99 *out += tmp; 100 } 101 102 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value) 103 : value_(value) { 104 } 105 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); 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 137 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) { 138 } 139 140 LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) { 141 } 142 143 LatencyInfo::LatencyInfo() 144 : input_coordinates_size(0), trace_id(-1), terminated(false) { 145 } 146 147 LatencyInfo::~LatencyInfo() { 148 } 149 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 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 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 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 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 291 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 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 316 void LatencyInfo::Clear() { 317 latency_components.clear(); 318 } 319 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