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