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