OLD | NEW |
1 // Copyright 2013 The Chromium Authors. All rights reserved. | 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 | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 | 4 |
5 #include "base/debug/trace_event.h" | 5 #include "base/debug/trace_event.h" |
6 #include "base/json/json_writer.h" | 6 #include "base/json/json_writer.h" |
7 #include "base/memory/scoped_ptr.h" | 7 #include "base/memory/scoped_ptr.h" |
8 #include "base/strings/stringprintf.h" | 8 #include "base/strings/stringprintf.h" |
9 #include "ui/events/latency_info.h" | 9 #include "ui/events/latency_info.h" |
10 | 10 |
(...skipping 160 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
171 int64 component_sequence_number) { | 171 int64 component_sequence_number) { |
172 AddLatencyNumberWithTimestamp(component, id, component_sequence_number, | 172 AddLatencyNumberWithTimestamp(component, id, component_sequence_number, |
173 base::TimeTicks::HighResNow(), 1); | 173 base::TimeTicks::HighResNow(), 1); |
174 } | 174 } |
175 | 175 |
176 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component, | 176 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component, |
177 int64 id, | 177 int64 id, |
178 int64 component_sequence_number, | 178 int64 component_sequence_number, |
179 base::TimeTicks time, | 179 base::TimeTicks time, |
180 uint32 event_count) { | 180 uint32 event_count) { |
| 181 |
| 182 static const unsigned char* benchmark_enabled = |
| 183 TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("benchmark"); |
| 184 |
181 if (IsBeginComponent(component)) { | 185 if (IsBeginComponent(component)) { |
182 // Should only ever add begin component once. | 186 // Should only ever add begin component once. |
183 CHECK_EQ(-1, trace_id); | 187 CHECK_EQ(-1, trace_id); |
184 trace_id = component_sequence_number; | 188 trace_id = component_sequence_number; |
185 TRACE_EVENT_ASYNC_BEGIN0("benchmark", | 189 |
186 "InputLatency", | 190 if (*benchmark_enabled) { |
187 TRACE_ID_DONT_MANGLE(trace_id)); | 191 // The timestamp for ASYNC_BEGIN trace event is used for drawing the |
| 192 // beginning of the trace event in trace viewer. For better visualization, |
| 193 // for an input event, we want to draw the beginning as when the event is |
| 194 // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT, |
| 195 // not when we actually issue the ASYNC_BEGIN trace event. |
| 196 LatencyComponent component; |
| 197 int64 ts = 0; |
| 198 if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, |
| 199 0, |
| 200 &component) || |
| 201 FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT, |
| 202 0, |
| 203 &component)) { |
| 204 // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock |
| 205 // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0 |
| 206 // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on |
| 207 // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and |
| 208 // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we |
| 209 // can't use a static value. |
| 210 int64 diff = base::TimeTicks::HighResNow().ToInternalValue() - |
| 211 base::TimeTicks::NowFromSystemTraceTime().ToInternalValue(); |
| 212 ts = component.event_time.ToInternalValue() - diff; |
| 213 } else { |
| 214 ts = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue(); |
| 215 } |
| 216 TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0( |
| 217 "benchmark", |
| 218 "InputLatency", |
| 219 TRACE_ID_DONT_MANGLE(trace_id), |
| 220 ts); |
| 221 } |
| 222 |
188 TRACE_EVENT_FLOW_BEGIN0( | 223 TRACE_EVENT_FLOW_BEGIN0( |
189 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id)); | 224 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id)); |
190 } | 225 } |
191 | 226 |
192 LatencyMap::key_type key = std::make_pair(component, id); | 227 LatencyMap::key_type key = std::make_pair(component, id); |
193 LatencyMap::iterator it = latency_components.find(key); | 228 LatencyMap::iterator it = latency_components.find(key); |
194 if (it == latency_components.end()) { | 229 if (it == latency_components.end()) { |
195 LatencyComponent info = {component_sequence_number, time, event_count}; | 230 LatencyComponent info = {component_sequence_number, time, event_count}; |
196 latency_components[key] = info; | 231 latency_components[key] = info; |
197 } else { | 232 } else { |
198 it->second.sequence_number = std::max(component_sequence_number, | 233 it->second.sequence_number = std::max(component_sequence_number, |
199 it->second.sequence_number); | 234 it->second.sequence_number); |
200 uint32 new_count = event_count + it->second.event_count; | 235 uint32 new_count = event_count + it->second.event_count; |
201 if (event_count > 0 && new_count != 0) { | 236 if (event_count > 0 && new_count != 0) { |
202 // Do a weighted average, so that the new event_time is the average of | 237 // Do a weighted average, so that the new event_time is the average of |
203 // the times of events currently in this structure with the time passed | 238 // the times of events currently in this structure with the time passed |
204 // into this method. | 239 // into this method. |
205 it->second.event_time += (time - it->second.event_time) * event_count / | 240 it->second.event_time += (time - it->second.event_time) * event_count / |
206 new_count; | 241 new_count; |
207 it->second.event_count = new_count; | 242 it->second.event_count = new_count; |
208 } | 243 } |
209 } | 244 } |
210 | 245 |
211 if (IsTerminalComponent(component) && trace_id != -1) { | 246 if (IsTerminalComponent(component) && trace_id != -1) { |
212 // Should only ever add terminal component once. | 247 // Should only ever add terminal component once. |
213 CHECK(!terminated); | 248 CHECK(!terminated); |
214 terminated = true; | 249 terminated = true; |
215 TRACE_EVENT_ASYNC_END1("benchmark", | 250 |
216 "InputLatency", | 251 if (*benchmark_enabled) { |
217 TRACE_ID_DONT_MANGLE(trace_id), | 252 TRACE_EVENT_ASYNC_END1("benchmark", |
218 "data", AsTraceableData(*this)); | 253 "InputLatency", |
| 254 TRACE_ID_DONT_MANGLE(trace_id), |
| 255 "data", AsTraceableData(*this)); |
| 256 } |
| 257 |
219 TRACE_EVENT_FLOW_END0( | 258 TRACE_EVENT_FLOW_END0( |
220 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id)); | 259 "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id)); |
221 } | 260 } |
222 } | 261 } |
223 | 262 |
224 bool LatencyInfo::FindLatency(LatencyComponentType type, | 263 bool LatencyInfo::FindLatency(LatencyComponentType type, |
225 int64 id, | 264 int64 id, |
226 LatencyComponent* output) const { | 265 LatencyComponent* output) const { |
227 LatencyMap::const_iterator it = latency_components.find( | 266 LatencyMap::const_iterator it = latency_components.find( |
228 std::make_pair(type, id)); | 267 std::make_pair(type, id)); |
(...skipping 22 matching lines...) Expand all Loading... |
251 } | 290 } |
252 | 291 |
253 void LatencyInfo::TraceEventType(const char* event_type) { | 292 void LatencyInfo::TraceEventType(const char* event_type) { |
254 TRACE_EVENT_ASYNC_STEP_INTO0("benchmark", | 293 TRACE_EVENT_ASYNC_STEP_INTO0("benchmark", |
255 "InputLatency", | 294 "InputLatency", |
256 TRACE_ID_DONT_MANGLE(trace_id), | 295 TRACE_ID_DONT_MANGLE(trace_id), |
257 event_type); | 296 event_type); |
258 } | 297 } |
259 | 298 |
260 } // namespace ui | 299 } // namespace ui |
OLD | NEW |