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
 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
 135 namespace ui {
 136
 137 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) {
 138 }
 139
 140 LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) {
 141 }
 142
 143 LatencyInfo::LatencyInfo()
 144     : input_coordinates_size(0), trace_id(-1), terminated(false) {
 145 }
 146
 147 LatencyInfo::~LatencyInfo() {
 148 }
 149
 150 bool 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
 168 void 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
 183 void 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
 197 void 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
 204 void 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
 291 bool 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
 303 void 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
 316 void LatencyInfo::Clear() {
 317   latency_components.clear();
 318 }
 319
 320 void 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