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 "ui/events/latency_info.h"
   6
   7 #include <algorithm>
   8 #include <string>
   9
  10 #include "base/json/json_writer.h"
  11 #include "base/lazy_instance.h"
  12 #include "base/strings/stringprintf.h"
  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(LATENCY_BEGIN_SCROLL_LISTENER_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_MOUSE_WHEEL_COMPONENT);
  38     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT);
  39     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT);
  40     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT);
  41     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT);
  42     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT);
  43     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT);
  44     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_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_MOUSE_WHEEL_COMPONENT:
  57     case ui::INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT:
  58     case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT:
  59     case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT:
  60     case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT:
  61     case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT:
  62     case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_NO_UPDATE_COMPONENT:
  63     case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT:
  64       return true;
  65     default:
  66       return false;
  67   }
  68 }
  69
  70 bool IsBeginComponent(ui::LatencyComponentType type) {
  71   return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT ||
  72           type == ui::LATENCY_BEGIN_SCROLL_LISTENER_UPDATE_MAIN_COMPONENT);
  73 }
  74
  75 bool IsInputLatencyBeginComponent(ui::LatencyComponentType type) {
  76   return type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT;
  77 }
  78
  79 // This class is for converting latency info to trace buffer friendly format.
  80 class LatencyInfoTracedValue
  81     : public base::trace_event::ConvertableToTraceFormat {
  82  public:
  83   static scoped_refptr<ConvertableToTraceFormat> FromValue(
  84       scoped_ptr<base::Value> value);
  85
  86   void AppendAsTraceFormat(std::string* out) const override;
  87
  88  private:
  89   explicit LatencyInfoTracedValue(base::Value* value);
  90   ~LatencyInfoTracedValue() override;
  91
  92   scoped_ptr<base::Value> value_;
  93
  94   DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue);
  95 };
  96
  97 scoped_refptr<base::trace_event::ConvertableToTraceFormat>
  98 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
  99   return scoped_refptr<base::trace_event::ConvertableToTraceFormat>(
 100       new LatencyInfoTracedValue(value.release()));
 101 }
 102
 103 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
 104 }
 105
 106 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
 107   std::string tmp;
 108   base::JSONWriter::Write(*value_, &tmp);
 109   *out += tmp;
 110 }
 111
 112 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
 113     : value_(value) {
 114 }
 115
 116 struct BenchmarkEnabledInitializer {
 117   BenchmarkEnabledInitializer() :
 118       benchmark_enabled(TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
 119           "benchmark")) {
 120   }
 121
 122   const unsigned char* benchmark_enabled;
 123 };
 124
 125 static base::LazyInstance<BenchmarkEnabledInitializer>::Leaky
 126   g_benchmark_enabled = LAZY_INSTANCE_INITIALIZER;
 127
 128 }  // namespace
 129
 130 namespace ui {
 131
 132 LatencyInfo::InputCoordinate::InputCoordinate() : x(0), y(0) {
 133 }
 134
 135 LatencyInfo::InputCoordinate::InputCoordinate(float x, float y) : x(x), y(y) {
 136 }
 137
 138 LatencyInfo::LatencyInfo()
 139     : input_coordinates_size_(0),
 140       coalesced_events_size_(0),
 141       trace_id_(-1),
 142       terminated_(false) {
 143 }
 144
 145 LatencyInfo::~LatencyInfo() {
 146 }
 147
 148 LatencyInfo::LatencyInfo(int64 trace_id, bool terminated)
 149     : input_coordinates_size_(0),
 150       coalesced_events_size_(0),
 151       trace_id_(trace_id),
 152       terminated_(terminated) {}
 153
 154 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info,
 155                          const char* referring_msg) {
 156   if (latency_info.size() > kMaxLatencyInfoNumber) {
 157     LOG(ERROR) << referring_msg << ", LatencyInfo vector size "
 158                << latency_info.size() << " is too big.";
 159     TRACE_EVENT_INSTANT1("input,benchmark", "LatencyInfo::Verify Fails",
 160                          TRACE_EVENT_SCOPE_GLOBAL,
 161                          "size", latency_info.size());
 162     return false;
 163   }
 164   return true;
 165 }
 166
 167 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other,
 168                                   LatencyComponentType type) {
 169   for (const auto& lc : other.latency_components()) {
 170     if (lc.first.first == type) {
 171       AddLatencyNumberWithTimestamp(lc.first.first,
 172                                     lc.first.second,
 173                                     lc.second.sequence_number,
 174                                     lc.second.event_time,
 175                                     lc.second.event_count);
 176     }
 177   }
 178 }
 179
 180 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
 181   for (const auto& lc : other.latency_components()) {
 182     if (!FindLatency(lc.first.first, lc.first.second, NULL)) {
 183       AddLatencyNumberWithTimestamp(lc.first.first,
 184                                     lc.first.second,
 185                                     lc.second.sequence_number,
 186                                     lc.second.event_time,
 187                                     lc.second.event_count);
 188     }
 189   }
 190 }
 191
 192 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
 193                                    int64 id,
 194                                    int64 component_sequence_number) {
 195   AddLatencyNumberWithTimestampImpl(component, id, component_sequence_number,
 196                                     base::TimeTicks::Now(), 1, nullptr);
 197 }
 198
 199 void LatencyInfo::AddLatencyNumberWithTraceName(
 200     LatencyComponentType component,
 201     int64 id,
 202     int64 component_sequence_number,
 203     const char* trace_name_str) {
 204   AddLatencyNumberWithTimestampImpl(component, id, component_sequence_number,
 205                                     base::TimeTicks::Now(), 1, trace_name_str);
 206 }
 207
 208 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
 209                                                 int64 id,
 210                                                 int64 component_sequence_number,
 211                                                 base::TimeTicks time,
 212                                                 uint32 event_count) {
 213   AddLatencyNumberWithTimestampImpl(component, id, component_sequence_number,
 214                                     time, event_count, nullptr);
 215 }
 216
 217 void LatencyInfo::AddLatencyNumberWithTimestampImpl(
 218     LatencyComponentType component,
 219     int64 id,
 220     int64 component_sequence_number,
 221     base::TimeTicks time,
 222     uint32 event_count,
 223     const char* trace_name_str) {
 224
 225   const unsigned char* benchmark_enabled =
 226       g_benchmark_enabled.Get().benchmark_enabled;
 227
 228   if (IsBeginComponent(component)) {
 229     // Should only ever add begin component once.
 230     CHECK_EQ(-1, trace_id_);
 231     trace_id_ = component_sequence_number;
 232
 233     if (*benchmark_enabled) {
 234       // The timestamp for ASYNC_BEGIN trace event is used for drawing the
 235       // beginning of the trace event in trace viewer. For better visualization,
 236       // for an input event, we want to draw the beginning as when the event is
 237       // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
 238       // not when we actually issue the ASYNC_BEGIN trace event.
 239       LatencyComponent begin_component;
 240       int64 ts = 0;
 241       if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
 242                       0,
 243                       &begin_component) ||
 244           FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT,
 245                       0,
 246                       &begin_component)) {
 247         // The timestamp stored in ORIGINAL/UI_COMPONENT is using clock
 248         // CLOCK_MONOTONIC while TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0
 249         // expects timestamp using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on
 250         // CrOS). So we need to adjust the diff between in CLOCK_MONOTONIC and
 251         // CLOCK_SYSTEM_TRACE. Note that the diff is drifting overtime so we
 252         // can't use a static value.
 253         base::TimeDelta diff = (base::TimeTicks::Now() - base::TimeTicks()) -
 254             (base::TraceTicks::Now() - base::TraceTicks());
 255         ts = (begin_component.event_time - diff).ToInternalValue();
 256       } else {
 257         ts = base::TraceTicks::Now().ToInternalValue();
 258       }
 259
 260       if (trace_name_str) {
 261         if (IsInputLatencyBeginComponent(component))
 262           trace_name_ = std::string("InputLatency::") + trace_name_str;
 263         else
 264           trace_name_ = std::string("Latency::") + trace_name_str;
 265       }
 266
 267       TRACE_EVENT_COPY_ASYNC_BEGIN_WITH_TIMESTAMP0(
 268           "benchmark,latencyInfo",
 269           trace_name_.c_str(),
 270           TRACE_ID_DONT_MANGLE(trace_id_),
 271           ts);
 272     }
 273
 274     TRACE_EVENT_WITH_FLOW1("input,benchmark",
 275                            "LatencyInfo.Flow",
 276                            TRACE_ID_DONT_MANGLE(trace_id_),
 277                            TRACE_EVENT_FLAG_FLOW_OUT,
 278                            "trace_id", trace_id_);
 279   }
 280
 281   LatencyMap::key_type key = std::make_pair(component, id);
 282   LatencyMap::iterator it = latency_components_.find(key);
 283   if (it == latency_components_.end()) {
 284     LatencyComponent info = {component_sequence_number, time, event_count};
 285     latency_components_[key] = info;
 286   } else {
 287     it->second.sequence_number = std::max(component_sequence_number,
 288                                           it->second.sequence_number);
 289     uint32 new_count = event_count + it->second.event_count;
 290     if (event_count > 0 && new_count != 0) {
 291       // Do a weighted average, so that the new event_time is the average of
 292       // the times of events currently in this structure with the time passed
 293       // into this method.
 294       it->second.event_time += (time - it->second.event_time) * event_count /
 295           new_count;
 296       it->second.event_count = new_count;
 297     }
 298   }
 299
 300   if (IsTerminalComponent(component) && trace_id_ != -1) {
 301     // Should only ever add terminal component once.
 302     CHECK(!terminated_);
 303     terminated_ = true;
 304
 305     if (*benchmark_enabled) {
 306       TRACE_EVENT_COPY_ASYNC_END1("benchmark,latencyInfo",
 307                                   trace_name_.c_str(),
 308                                   TRACE_ID_DONT_MANGLE(trace_id_),
 309                                   "data", AsTraceableData());
 310     }
 311
 312     TRACE_EVENT_WITH_FLOW0("input,benchmark",
 313                            "LatencyInfo.Flow",
 314                            TRACE_ID_DONT_MANGLE(trace_id_),
 315                            TRACE_EVENT_FLAG_FLOW_IN);
 316   }
 317 }
 318
 319 scoped_refptr<base::trace_event::ConvertableToTraceFormat>
 320 LatencyInfo::AsTraceableData() {
 321   scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue());
 322   for (const auto& lc : latency_components_) {
 323     scoped_ptr<base::DictionaryValue>
 324         component_info(new base::DictionaryValue());
 325     component_info->SetDouble("comp_id", static_cast<double>(lc.first.second));
 326     component_info->SetDouble(
 327         "time",
 328         static_cast<double>(lc.second.event_time.ToInternalValue()));
 329     component_info->SetDouble("count", lc.second.event_count);
 330     component_info->SetDouble("sequence_number",
 331                               lc.second.sequence_number);
 332     record_data->Set(GetComponentName(lc.first.first), component_info.Pass());
 333   }
 334   record_data->SetDouble("trace_id", static_cast<double>(trace_id_));
 335
 336   scoped_ptr<base::ListValue> coordinates(new base::ListValue());
 337   for (size_t i = 0; i < input_coordinates_size_; i++) {
 338     scoped_ptr<base::DictionaryValue> coordinate_pair(
 339         new base::DictionaryValue());
 340     coordinate_pair->SetDouble("x", input_coordinates_[i].x);
 341     coordinate_pair->SetDouble("y", input_coordinates_[i].y);
 342     coordinates->Append(coordinate_pair.release());
 343   }
 344   record_data->Set("coordinates", coordinates.release());
 345   return LatencyInfoTracedValue::FromValue(record_data.Pass());
 346 }
 347
 348 bool LatencyInfo::FindLatency(LatencyComponentType type,
 349                               int64 id,
 350                               LatencyComponent* output) const {
 351   LatencyMap::const_iterator it = latency_components_.find(
 352       std::make_pair(type, id));
 353   if (it == latency_components_.end())
 354     return false;
 355   if (output)
 356     *output = it->second;
 357   return true;
 358 }
 359
 360 void LatencyInfo::RemoveLatency(LatencyComponentType type) {
 361   LatencyMap::iterator it = latency_components_.begin();
 362   while (it != latency_components_.end()) {
 363     if (it->first.first == type) {
 364       LatencyMap::iterator tmp = it;
 365       ++it;
 366       latency_components_.erase(tmp);
 367     } else {
 368       it++;
 369     }
 370   }
 371 }
 372
 373 bool LatencyInfo::AddInputCoordinate(const InputCoordinate& input_coordinate) {
 374   if (input_coordinates_size_ >= kMaxInputCoordinates)
 375     return false;
 376   input_coordinates_[input_coordinates_size_++] = input_coordinate;
 377   return true;
 378 }
 379
 380 bool LatencyInfo::AddCoalescedEventTimestamp(double timestamp) {
 381   if (coalesced_events_size_ >= kMaxCoalescedEventTimestamps)
 382     return false;
 383   timestamps_of_coalesced_events_[coalesced_events_size_++] = timestamp;
 384   return true;
 385 }
 386
 387 }  // namespace ui