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