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_SCROLL_UPDATE_RWH_COMPONENT);
23 CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT);
24 CASE_TYPE(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT);
25 CASE_TYPE(INPUT_EVENT_LATENCY_UI_COMPONENT);
26 CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT);
27 CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT);
28 CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT);
29 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT);
30 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT);
31 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT);
32 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT);
33 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT);
34 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT);
35 CASE_TYPE(LATENCY_INFO_LIST_TERMINATED_OVERFLOW_COMPONENT);
36 CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT);
37 default:
38 DLOG(WARNING) << "Unhandled LatencyComponentType.\n";
39 break;
40 }
41 #undef CASE_TYPE
42 return "unknown";
43 }
44
IsTerminalComponent(ui::LatencyComponentType type)45 bool IsTerminalComponent(ui::LatencyComponentType type) {
46 switch (type) {
47 case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT:
48 case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT:
49 case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT:
50 case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT:
51 case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT:
52 case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT:
53 case ui::LATENCY_INFO_LIST_TERMINATED_OVERFLOW_COMPONENT:
54 case ui::INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT:
55 return true;
56 default:
57 return false;
58 }
59 }
60
IsBeginComponent(ui::LatencyComponentType type)61 bool IsBeginComponent(ui::LatencyComponentType type) {
62 return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT ||
63 type == ui::INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT);
64 }
65
66 // This class is for converting latency info to trace buffer friendly format.
67 class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat {
68 public:
69 static scoped_refptr<ConvertableToTraceFormat> FromValue(
70 scoped_ptr<base::Value> value);
71
72 virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE;
73
74 private:
75 explicit LatencyInfoTracedValue(base::Value* value);
76 virtual ~LatencyInfoTracedValue();
77
78 scoped_ptr<base::Value> value_;
79
80 DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue);
81 };
82
83 scoped_refptr<base::debug::ConvertableToTraceFormat>
FromValue(scoped_ptr<base::Value> value)84 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
85 return scoped_refptr<base::debug::ConvertableToTraceFormat>(
86 new LatencyInfoTracedValue(value.release()));
87 }
88
~LatencyInfoTracedValue()89 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
90 }
91
AppendAsTraceFormat(std::string * out) const92 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
93 std::string tmp;
94 base::JSONWriter::Write(value_.get(), &tmp);
95 *out += tmp;
96 }
97
LatencyInfoTracedValue(base::Value * value)98 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
99 : value_(value) {
100 }
101
102 // Converts latencyinfo into format that can be dumped into trace buffer.
AsTraceableData(const ui::LatencyInfo & latency)103 scoped_refptr<base::debug::ConvertableToTraceFormat> AsTraceableData(
104 const ui::LatencyInfo& latency) {
105 scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue());
106 for (ui::LatencyInfo::LatencyMap::const_iterator it =
107 latency.latency_components.begin();
108 it != latency.latency_components.end(); ++it) {
109 base::DictionaryValue* component_info = new base::DictionaryValue();
110 component_info->SetDouble("comp_id", it->first.second);
111 component_info->SetDouble("time", it->second.event_time.ToInternalValue());
112 component_info->SetDouble("count", it->second.event_count);
113 record_data->Set(GetComponentName(it->first.first), component_info);
114 }
115 record_data->SetDouble("trace_id", latency.trace_id);
116 return LatencyInfoTracedValue::FromValue(record_data.PassAs<base::Value>());
117 }
118
119 } // namespace
120
121 namespace ui {
122
LatencyInfo()123 LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
124 }
125
~LatencyInfo()126 LatencyInfo::~LatencyInfo() {
127 }
128
Verify(const std::vector<LatencyInfo> & latency_info,const char * referring_msg)129 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info,
130 const char* referring_msg) {
131 if (latency_info.size() > kMaxLatencyInfoNumber) {
132 LOG(ERROR) << referring_msg << ", LatencyInfo vector size "
133 << latency_info.size() << " is too big.";
134 return false;
135 }
136 return true;
137 }
138
CopyLatencyFrom(const LatencyInfo & other,LatencyComponentType type)139 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other,
140 LatencyComponentType type) {
141 for (LatencyMap::const_iterator it = other.latency_components.begin();
142 it != other.latency_components.end();
143 ++it) {
144 if (it->first.first == type) {
145 AddLatencyNumberWithTimestamp(it->first.first,
146 it->first.second,
147 it->second.sequence_number,
148 it->second.event_time,
149 it->second.event_count);
150 }
151 }
152 }
153
AddNewLatencyFrom(const LatencyInfo & other)154 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
155 for (LatencyMap::const_iterator it = other.latency_components.begin();
156 it != other.latency_components.end();
157 ++it) {
158 if (!FindLatency(it->first.first, it->first.second, NULL)) {
159 AddLatencyNumberWithTimestamp(it->first.first,
160 it->first.second,
161 it->second.sequence_number,
162 it->second.event_time,
163 it->second.event_count);
164 }
165 }
166 }
167
AddLatencyNumber(LatencyComponentType component,int64 id,int64 component_sequence_number)168 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
169 int64 id,
170 int64 component_sequence_number) {
171 AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
172 base::TimeTicks::HighResNow(), 1);
173 }
174
AddLatencyNumberWithTimestamp(LatencyComponentType component,int64 id,int64 component_sequence_number,base::TimeTicks time,uint32 event_count)175 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
176 int64 id,
177 int64 component_sequence_number,
178 base::TimeTicks time,
179 uint32 event_count) {
180 if (IsBeginComponent(component)) {
181 // Should only ever add begin component once.
182 CHECK_EQ(-1, trace_id);
183 trace_id = component_sequence_number;
184 TRACE_EVENT_ASYNC_BEGIN0("benchmark",
185 "InputLatency",
186 TRACE_ID_DONT_MANGLE(trace_id));
187 TRACE_EVENT_FLOW_BEGIN0(
188 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
189 }
190
191 LatencyMap::key_type key = std::make_pair(component, id);
192 LatencyMap::iterator it = latency_components.find(key);
193 if (it == latency_components.end()) {
194 LatencyComponent info = {component_sequence_number, time, event_count};
195 latency_components[key] = info;
196 } else {
197 it->second.sequence_number = std::max(component_sequence_number,
198 it->second.sequence_number);
199 uint32 new_count = event_count + it->second.event_count;
200 if (event_count > 0 && new_count != 0) {
201 // Do a weighted average, so that the new event_time is the average of
202 // the times of events currently in this structure with the time passed
203 // into this method.
204 it->second.event_time += (time - it->second.event_time) * event_count /
205 new_count;
206 it->second.event_count = new_count;
207 }
208 }
209
210 if (IsTerminalComponent(component) && trace_id != -1) {
211 // Should only ever add terminal component once.
212 CHECK(!terminated);
213 terminated = true;
214 TRACE_EVENT_ASYNC_END1("benchmark",
215 "InputLatency",
216 TRACE_ID_DONT_MANGLE(trace_id),
217 "data", AsTraceableData(*this));
218 TRACE_EVENT_FLOW_END0(
219 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
220 }
221 }
222
FindLatency(LatencyComponentType type,int64 id,LatencyComponent * output) const223 bool LatencyInfo::FindLatency(LatencyComponentType type,
224 int64 id,
225 LatencyComponent* output) const {
226 LatencyMap::const_iterator it = latency_components.find(
227 std::make_pair(type, id));
228 if (it == latency_components.end())
229 return false;
230 if (output)
231 *output = it->second;
232 return true;
233 }
234
RemoveLatency(LatencyComponentType type)235 void LatencyInfo::RemoveLatency(LatencyComponentType type) {
236 LatencyMap::iterator it = latency_components.begin();
237 while (it != latency_components.end()) {
238 if (it->first.first == type) {
239 LatencyMap::iterator tmp = it;
240 ++it;
241 latency_components.erase(tmp);
242 } else {
243 it++;
244 }
245 }
246 }
247
Clear()248 void LatencyInfo::Clear() {
249 latency_components.clear();
250 }
251
TraceEventType(const char * event_type)252 void LatencyInfo::TraceEventType(const char* event_type) {
253 TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
254 "InputLatency",
255 TRACE_ID_DONT_MANGLE(trace_id),
256 event_type);
257 }
258
259 } // namespace ui
260