src/ui/events/latency_info.cc

   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
  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_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
  48 bool 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
  64 bool 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.
  71 class 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
  87 scoped_refptr<base::debug::ConvertableToTraceFormat>
  88 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
  89   return scoped_refptr<base::debug::ConvertableToTraceFormat>(
  90       new LatencyInfoTracedValue(value.release()));
  91 }
  92
  93 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
  94 }
  95
  96 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
  97   std::string tmp;
  98   base::JSONWriter::Write(value_.get(), &tmp);
  99   *out += tmp;
 100 }
 101
 102 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
 103     : value_(value) {
 104 }
 105
 106 // Converts latencyinfo into format that can be dumped into trace buffer.
 107 scoped_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   return LatencyInfoTracedValue::FromValue(record_data.PassAs<base::Value>());
 121 }
 122
 123 }  // namespace
 124
 125 namespace ui {
 126
 127 LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
 128 }
 129
 130 LatencyInfo::~LatencyInfo() {
 131 }
 132
 133 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info,
 134                          const char* referring_msg) {
 135   if (latency_info.size() > kMaxLatencyInfoNumber) {
 136     LOG(ERROR) << referring_msg << ", LatencyInfo vector size "
 137                << latency_info.size() << " is too big.";
 138     return false;
 139   }
 140   return true;
 141 }
 142
 143 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other,
 144                                   LatencyComponentType type) {
 145   for (LatencyMap::const_iterator it = other.latency_components.begin();
 146        it != other.latency_components.end();
 147        ++it) {
 148     if (it->first.first == type) {
 149       AddLatencyNumberWithTimestamp(it->first.first,
 150                                     it->first.second,
 151                                     it->second.sequence_number,
 152                                     it->second.event_time,
 153                                     it->second.event_count);
 154     }
 155   }
 156 }
 157
 158 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
 159     for (LatencyMap::const_iterator it = other.latency_components.begin();
 160          it != other.latency_components.end();
 161          ++it) {
 162       if (!FindLatency(it->first.first, it->first.second, NULL)) {
 163         AddLatencyNumberWithTimestamp(it->first.first,
 164                                       it->first.second,
 165                                       it->second.sequence_number,
 166                                       it->second.event_time,
 167                                       it->second.event_count);
 168       }
 169     }
 170 }
 171
 172 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
 173                                    int64 id,
 174                                    int64 component_sequence_number) {
 175   AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
 176                                 base::TimeTicks::HighResNow(), 1);
 177 }
 178
 179 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
 180                                                 int64 id,
 181                                                 int64 component_sequence_number,
 182                                                 base::TimeTicks time,
 183                                                 uint32 event_count) {
 184
 185   static const unsigned char* benchmark_enabled =
 186       TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("benchmark");
 187
 188   if (IsBeginComponent(component)) {
 189     // Should only ever add begin component once.
 190     CHECK_EQ(-1, trace_id);
 191     trace_id = component_sequence_number;
 192
 193     if (*benchmark_enabled) {
 194       // The timestamp for ASYNC_BEGIN trace event is used for drawing the
 195       // beginning of the trace event in trace viewer. For better visualization,
 196       // for an input event, we want to draw the beginning as when the event is
 197       // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
 198       // not when we actually issue the ASYNC_BEGIN trace event.
 199       LatencyComponent component;
 200       int64 ts = 0;
 201       if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
 202                       0,
 203                       &component) ||
 204           FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT,
 205                       0,
 206                       &component)) {
 207         // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock
 208         // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0
 209         // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on
 210         // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and
 211         // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we
 212         // can't use a static value.
 213         int64 diff = base::TimeTicks::HighResNow().ToInternalValue() -
 214             base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
 215         ts = component.event_time.ToInternalValue() - diff;
 216       } else {
 217         ts = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
 218       }
 219       TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0(
 220           "benchmark",
 221           "InputLatency",
 222           TRACE_ID_DONT_MANGLE(trace_id),
 223           ts);
 224     }
 225
 226     TRACE_EVENT_FLOW_BEGIN0(
 227         "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
 228   }
 229
 230   LatencyMap::key_type key = std::make_pair(component, id);
 231   LatencyMap::iterator it = latency_components.find(key);
 232   if (it == latency_components.end()) {
 233     LatencyComponent info = {component_sequence_number, time, event_count};
 234     latency_components[key] = info;
 235   } else {
 236     it->second.sequence_number = std::max(component_sequence_number,
 237                                           it->second.sequence_number);
 238     uint32 new_count = event_count + it->second.event_count;
 239     if (event_count > 0 && new_count != 0) {
 240       // Do a weighted average, so that the new event_time is the average of
 241       // the times of events currently in this structure with the time passed
 242       // into this method.
 243       it->second.event_time += (time - it->second.event_time) * event_count /
 244           new_count;
 245       it->second.event_count = new_count;
 246     }
 247   }
 248
 249   if (IsTerminalComponent(component) && trace_id != -1) {
 250     // Should only ever add terminal component once.
 251     CHECK(!terminated);
 252     terminated = true;
 253
 254     if (*benchmark_enabled) {
 255       TRACE_EVENT_ASYNC_END1("benchmark",
 256                              "InputLatency",
 257                              TRACE_ID_DONT_MANGLE(trace_id),
 258                              "data", AsTraceableData(*this));
 259     }
 260
 261     TRACE_EVENT_FLOW_END0(
 262         "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
 263   }
 264 }
 265
 266 bool LatencyInfo::FindLatency(LatencyComponentType type,
 267                               int64 id,
 268                               LatencyComponent* output) const {
 269   LatencyMap::const_iterator it = latency_components.find(
 270       std::make_pair(type, id));
 271   if (it == latency_components.end())
 272     return false;
 273   if (output)
 274     *output = it->second;
 275   return true;
 276 }
 277
 278 void LatencyInfo::RemoveLatency(LatencyComponentType type) {
 279   LatencyMap::iterator it = latency_components.begin();
 280   while (it != latency_components.end()) {
 281     if (it->first.first == type) {
 282       LatencyMap::iterator tmp = it;
 283       ++it;
 284       latency_components.erase(tmp);
 285     } else {
 286       it++;
 287     }
 288   }
 289 }
 290
 291 void LatencyInfo::Clear() {
 292   latency_components.clear();
 293 }
 294
 295 void LatencyInfo::TraceEventType(const char* event_type) {
 296   TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
 297                                "InputLatency",
 298                                TRACE_ID_DONT_MANGLE(trace_id),
 299                                event_type);
 300 }
 301
 302 }  // namespace ui