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