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_ACK_RWH_COMPONENT);
  30     CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT);
  31     CASE_TYPE(WINDOW_OLD_SNAPSHOT_FRAME_NUMBER_COMPONENT);
  32     CASE_TYPE(INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT);
  33     CASE_TYPE(INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT);
  34     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT);
  35     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT);
  36     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT);
  37     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT);
  38     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT);
  39     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT);
  40     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT);
  41     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT);
  42     default:
  43       DLOG(WARNING) << "Unhandled LatencyComponentType.\n";
  44       break;
  45   }
  46 #undef CASE_TYPE
  47   return "unknown";
  48 }
  49
  50 bool IsTerminalComponent(ui::LatencyComponentType type) {
  51   switch (type) {
  52     case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT:
  53     case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT:
  54     case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT:
  55     case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT:
  56     case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT:
  57     case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT:
  58     case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT:
  59     case ui::INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT:
  60       return true;
  61     default:
  62       return false;
  63   }
  64 }
  65
  66 bool IsBeginComponent(ui::LatencyComponentType type) {
  67   return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT ||
  68           type == ui::INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT ||
  69           type == ui::INPUT_EVENT_LATENCY_BEGIN_SCROLL_UPDATE_MAIN_COMPONENT);
  70 }
  71
  72 // This class is for converting latency info to trace buffer friendly format.
  73 class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat {
  74  public:
  75   static scoped_refptr<ConvertableToTraceFormat> FromValue(
  76       scoped_ptr<base::Value> value);
  77
  78   void AppendAsTraceFormat(std::string* out) const override;
  79
  80  private:
  81   explicit LatencyInfoTracedValue(base::Value* value);
  82   ~LatencyInfoTracedValue() override;
  83
  84   scoped_ptr<base::Value> value_;
  85
  86   DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue);
  87 };
  88
  89 scoped_refptr<base::debug::ConvertableToTraceFormat>
  90 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
  91   return scoped_refptr<base::debug::ConvertableToTraceFormat>(
  92       new LatencyInfoTracedValue(value.release()));
  93 }
  94
  95 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
  96 }
  97
  98 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
  99   std::string tmp;
 100   base::JSONWriter::Write(value_.get(), &tmp);
 101   *out += tmp;
 102 }
 103
 104 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
 105     : value_(value) {
 106 }
 107
 108 // Converts latencyinfo into format that can be dumped into trace buffer.
 109 scoped_refptr<base::debug::ConvertableToTraceFormat> AsTraceableData(
 110     const ui::LatencyInfo& latency) {
 111   scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue());
 112   for (ui::LatencyInfo::LatencyMap::const_iterator it =
 113            latency.latency_components.begin();
 114        it != latency.latency_components.end(); ++it) {
 115     base::DictionaryValue* component_info = new base::DictionaryValue();
 116     component_info->SetDouble("comp_id", static_cast<double>(it->first.second));
 117     component_info->SetDouble(
 118         "time", static_cast<double>(it->second.event_time.ToInternalValue()));
 119     component_info->SetDouble("count", it->second.event_count);
 120     record_data->Set(GetComponentName(it->first.first), component_info);
 121   }
 122   record_data->SetDouble("trace_id", static_cast<double>(latency.trace_id));
 123
 124   scoped_ptr<base::ListValue> coordinates(new base::ListValue());
 125   for (size_t i = 0; i < latency.input_coordinates_size; i++) {
 126     scoped_ptr<base::DictionaryValue> coordinate_pair(
 127         new base::DictionaryValue());
 128     coordinate_pair->SetDouble("x", latency.input_coordinates[i].x);
 129     coordinate_pair->SetDouble("y", latency.input_coordinates[i].y);
 130     coordinates->Append(coordinate_pair.release());
 131   }
 132   record_data->Set("coordinates", coordinates.release());
 133   return LatencyInfoTracedValue::FromValue(record_data.Pass());
 134 }
 135
 136 }  // namespace
 137
 138 namespace ui {
 139
 140 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) {
 141 }
 142
 143 LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) {
 144 }
 145
 146 LatencyInfo::LatencyInfo()
 147     : input_coordinates_size(0), trace_id(-1), terminated(false) {
 148 }
 149
 150 LatencyInfo::~LatencyInfo() {
 151 }
 152
 153 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info,
 154                          const char* referring_msg) {
 155   if (latency_info.size() > kMaxLatencyInfoNumber) {
 156     LOG(ERROR) << referring_msg << ", LatencyInfo vector size "
 157                << latency_info.size() << " is too big.";
 158     return false;
 159   }
 160   for (size_t i = 0; i < latency_info.size(); i++) {
 161     if (latency_info[i].input_coordinates_size > kMaxInputCoordinates) {
 162       LOG(ERROR) << referring_msg << ", coordinate vector size "
 163                  << latency_info[i].input_coordinates_size << " is too big.";
 164       return false;
 165     }
 166   }
 167
 168   return true;
 169 }
 170
 171 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other,
 172                                   LatencyComponentType type) {
 173   for (LatencyMap::const_iterator it = other.latency_components.begin();
 174        it != other.latency_components.end();
 175        ++it) {
 176     if (it->first.first == type) {
 177       AddLatencyNumberWithTimestamp(it->first.first,
 178                                     it->first.second,
 179                                     it->second.sequence_number,
 180                                     it->second.event_time,
 181                                     it->second.event_count);
 182     }
 183   }
 184 }
 185
 186 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
 187     for (LatencyMap::const_iterator it = other.latency_components.begin();
 188          it != other.latency_components.end();
 189          ++it) {
 190       if (!FindLatency(it->first.first, it->first.second, NULL)) {
 191         AddLatencyNumberWithTimestamp(it->first.first,
 192                                       it->first.second,
 193                                       it->second.sequence_number,
 194                                       it->second.event_time,
 195                                       it->second.event_count);
 196       }
 197     }
 198 }
 199
 200 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
 201                                    int64 id,
 202                                    int64 component_sequence_number) {
 203   AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
 204                                 base::TimeTicks::HighResNow(), 1);
 205 }
 206
 207 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
 208                                                 int64 id,
 209                                                 int64 component_sequence_number,
 210                                                 base::TimeTicks time,
 211                                                 uint32 event_count) {
 212
 213   static const unsigned char* benchmark_enabled =
 214       TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED("benchmark");
 215
 216   if (IsBeginComponent(component)) {
 217     // Should only ever add begin component once.
 218     CHECK_EQ(-1, trace_id);
 219     trace_id = component_sequence_number;
 220
 221     if (*benchmark_enabled) {
 222       // The timestamp for ASYNC_BEGIN trace event is used for drawing the
 223       // beginning of the trace event in trace viewer. For better visualization,
 224       // for an input event, we want to draw the beginning as when the event is
 225       // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
 226       // not when we actually issue the ASYNC_BEGIN trace event.
 227       LatencyComponent component;
 228       int64 ts = 0;
 229       if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
 230                       0,
 231                       &component) ||
 232           FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT,
 233                       0,
 234                       &component)) {
 235         // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock
 236         // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0
 237         // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on
 238         // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and
 239         // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we
 240         // can't use a static value.
 241         int64 diff = base::TimeTicks::HighResNow().ToInternalValue() -
 242             base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
 243         ts = component.event_time.ToInternalValue() - diff;
 244       } else {
 245         ts = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
 246       }
 247       TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0(
 248           "benchmark",
 249           "InputLatency",
 250           TRACE_ID_DONT_MANGLE(trace_id),
 251           ts);
 252     }
 253
 254     TRACE_EVENT_FLOW_BEGIN0(
 255         "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
 256   }
 257
 258   LatencyMap::key_type key = std::make_pair(component, id);
 259   LatencyMap::iterator it = latency_components.find(key);
 260   if (it == latency_components.end()) {
 261     LatencyComponent info = {component_sequence_number, time, event_count};
 262     latency_components[key] = info;
 263   } else {
 264     it->second.sequence_number = std::max(component_sequence_number,
 265                                           it->second.sequence_number);
 266     uint32 new_count = event_count + it->second.event_count;
 267     if (event_count > 0 && new_count != 0) {
 268       // Do a weighted average, so that the new event_time is the average of
 269       // the times of events currently in this structure with the time passed
 270       // into this method.
 271       it->second.event_time += (time - it->second.event_time) * event_count /
 272           new_count;
 273       it->second.event_count = new_count;
 274     }
 275   }
 276
 277   if (IsTerminalComponent(component) && trace_id != -1) {
 278     // Should only ever add terminal component once.
 279     CHECK(!terminated);
 280     terminated = true;
 281
 282     if (*benchmark_enabled) {
 283       TRACE_EVENT_ASYNC_END1("benchmark",
 284                              "InputLatency",
 285                              TRACE_ID_DONT_MANGLE(trace_id),
 286                              "data", AsTraceableData(*this));
 287     }
 288
 289     TRACE_EVENT_FLOW_END0(
 290         "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
 291   }
 292 }
 293
 294 bool LatencyInfo::FindLatency(LatencyComponentType type,
 295                               int64 id,
 296                               LatencyComponent* output) const {
 297   LatencyMap::const_iterator it = latency_components.find(
 298       std::make_pair(type, id));
 299   if (it == latency_components.end())
 300     return false;
 301   if (output)
 302     *output = it->second;
 303   return true;
 304 }
 305
 306 void LatencyInfo::RemoveLatency(LatencyComponentType type) {
 307   LatencyMap::iterator it = latency_components.begin();
 308   while (it != latency_components.end()) {
 309     if (it->first.first == type) {
 310       LatencyMap::iterator tmp = it;
 311       ++it;
 312       latency_components.erase(tmp);
 313     } else {
 314       it++;
 315     }
 316   }
 317 }
 318
 319 void LatencyInfo::Clear() {
 320   latency_components.clear();
 321 }
 322
 323 void LatencyInfo::TraceEventType(const char* event_type) {
 324   TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
 325                                "InputLatency",
 326                                TRACE_ID_DONT_MANGLE(trace_id),
 327                                event_type);
 328 }
 329
 330 }  // namespace ui