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 {
14const 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
40bool 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
55bool 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.
60class 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
76scoped_refptr<base::debug::ConvertableToTraceFormat>
77LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
78  return scoped_refptr<base::debug::ConvertableToTraceFormat>(
79      new LatencyInfoTracedValue(value.release()));
80}
81
82LatencyInfoTracedValue::~LatencyInfoTracedValue() {
83}
84
85void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
86  std::string tmp;
87  base::JSONWriter::Write(value_.get(), &tmp);
88  *out += tmp;
89}
90
91LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
92    : value_(value) {
93}
94
95// Converts latencyinfo into format that can be dumped into trace buffer.
96scoped_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
114namespace ui {
115
116LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
117}
118
119LatencyInfo::~LatencyInfo() {
120}
121
122void 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
135void 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
150void 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
157void 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
202bool 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
214void 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
227void LatencyInfo::Clear() {
228  latency_components.clear();
229}
230
231void 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