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
13namespace {
14
15const size_t kMaxLatencyInfoNumber = 100;
16
17const 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
48bool 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
64bool 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.
71class 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
87scoped_refptr<base::debug::ConvertableToTraceFormat>
88LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
89  return scoped_refptr<base::debug::ConvertableToTraceFormat>(
90      new LatencyInfoTracedValue(value.release()));
91}
92
93LatencyInfoTracedValue::~LatencyInfoTracedValue() {
94}
95
96void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
97  std::string tmp;
98  base::JSONWriter::Write(value_.get(), &tmp);
99  *out += tmp;
100}
101
102LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
103    : value_(value) {
104}
105
106// Converts latencyinfo into format that can be dumped into trace buffer.
107scoped_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
135namespace ui {
136
137LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) {
138}
139
140LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) {
141}
142
143LatencyInfo::LatencyInfo()
144    : input_coordinates_size(0), trace_id(-1), terminated(false) {
145}
146
147LatencyInfo::~LatencyInfo() {
148}
149
150bool 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
168void 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
183void 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
197void 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
204void 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
291bool 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
303void 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
316void LatencyInfo::Clear() {
317  latency_components.clear();
318}
319
320void 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