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_SCROLL_UPDATE_RWH_COMPONENT);
  23     CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT);
  24     CASE_TYPE(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT);
  25     CASE_TYPE(INPUT_EVENT_LATENCY_UI_COMPONENT);
  26     CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT);
  27     CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT);
  28     CASE_TYPE(WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT);
  29     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT);
  30     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT);
  31     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT);
  32     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT);
  33     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT);
  34     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT);
  35     CASE_TYPE(LATENCY_INFO_LIST_TERMINATED_OVERFLOW_COMPONENT);
  36     CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT);
  37     default:
  38       DLOG(WARNING) << "Unhandled LatencyComponentType.\n";
  39       break;
  40   }
  41 #undef CASE_TYPE
  42   return "unknown";
  43 }
  44
  45 bool IsTerminalComponent(ui::LatencyComponentType type) {
  46   switch (type) {
  47     case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT:
  48     case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT:
  49     case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT:
  50     case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT:
  51     case ui::INPUT_EVENT_LATENCY_TERMINATED_COMMIT_FAILED_COMPONENT:
  52     case ui::INPUT_EVENT_LATENCY_TERMINATED_SWAP_FAILED_COMPONENT:
  53     case ui::LATENCY_INFO_LIST_TERMINATED_OVERFLOW_COMPONENT:
  54     case ui::INPUT_EVENT_LATENCY_TERMINATED_PLUGIN_COMPONENT:
  55       return true;
  56     default:
  57       return false;
  58   }
  59 }
  60
  61 bool IsBeginComponent(ui::LatencyComponentType type) {
  62   return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT ||
  63           type == ui::INPUT_EVENT_LATENCY_BEGIN_PLUGIN_COMPONENT);
  64 }
  65
  66 // This class is for converting latency info to trace buffer friendly format.
  67 class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat {
  68  public:
  69   static scoped_refptr<ConvertableToTraceFormat> FromValue(
  70       scoped_ptr<base::Value> value);
  71
  72   virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE;
  73
  74  private:
  75   explicit LatencyInfoTracedValue(base::Value* value);
  76   virtual ~LatencyInfoTracedValue();
  77
  78   scoped_ptr<base::Value> value_;
  79
  80   DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue);
  81 };
  82
  83 scoped_refptr<base::debug::ConvertableToTraceFormat>
  84 LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
  85   return scoped_refptr<base::debug::ConvertableToTraceFormat>(
  86       new LatencyInfoTracedValue(value.release()));
  87 }
  88
  89 LatencyInfoTracedValue::~LatencyInfoTracedValue() {
  90 }
  91
  92 void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
  93   std::string tmp;
  94   base::JSONWriter::Write(value_.get(), &tmp);
  95   *out += tmp;
  96 }
  97
  98 LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
  99     : value_(value) {
 100 }
 101
 102 // Converts latencyinfo into format that can be dumped into trace buffer.
 103 scoped_refptr<base::debug::ConvertableToTraceFormat> AsTraceableData(
 104     const ui::LatencyInfo& latency) {
 105   scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue());
 106   for (ui::LatencyInfo::LatencyMap::const_iterator it =
 107            latency.latency_components.begin();
 108        it != latency.latency_components.end(); ++it) {
 109     base::DictionaryValue* component_info = new base::DictionaryValue();
 110     component_info->SetDouble("comp_id", it->first.second);
 111     component_info->SetDouble("time", it->second.event_time.ToInternalValue());
 112     component_info->SetDouble("count", it->second.event_count);
 113     record_data->Set(GetComponentName(it->first.first), component_info);
 114   }
 115   record_data->SetDouble("trace_id", latency.trace_id);
 116   return LatencyInfoTracedValue::FromValue(record_data.PassAs<base::Value>());
 117 }
 118
 119 }  // namespace
 120
 121 namespace ui {
 122
 123 LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
 124 }
 125
 126 LatencyInfo::~LatencyInfo() {
 127 }
 128
 129 bool LatencyInfo::Verify(const std::vector<LatencyInfo>& latency_info,
 130                          const char* referring_msg) {
 131   if (latency_info.size() > kMaxLatencyInfoNumber) {
 132     LOG(ERROR) << referring_msg << ", LatencyInfo vector size "
 133                << latency_info.size() << " is too big.";
 134     return false;
 135   }
 136   return true;
 137 }
 138
 139 void LatencyInfo::CopyLatencyFrom(const LatencyInfo& other,
 140                                   LatencyComponentType type) {
 141   for (LatencyMap::const_iterator it = other.latency_components.begin();
 142        it != other.latency_components.end();
 143        ++it) {
 144     if (it->first.first == type) {
 145       AddLatencyNumberWithTimestamp(it->first.first,
 146                                     it->first.second,
 147                                     it->second.sequence_number,
 148                                     it->second.event_time,
 149                                     it->second.event_count);
 150     }
 151   }
 152 }
 153
 154 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
 155     for (LatencyMap::const_iterator it = other.latency_components.begin();
 156          it != other.latency_components.end();
 157          ++it) {
 158       if (!FindLatency(it->first.first, it->first.second, NULL)) {
 159         AddLatencyNumberWithTimestamp(it->first.first,
 160                                       it->first.second,
 161                                       it->second.sequence_number,
 162                                       it->second.event_time,
 163                                       it->second.event_count);
 164       }
 165     }
 166 }
 167
 168 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
 169                                    int64 id,
 170                                    int64 component_sequence_number) {
 171   AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
 172                                 base::TimeTicks::HighResNow(), 1);
 173 }
 174
 175 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
 176                                                 int64 id,
 177                                                 int64 component_sequence_number,
 178                                                 base::TimeTicks time,
 179                                                 uint32 event_count) {
 180   if (IsBeginComponent(component)) {
 181     // Should only ever add begin component once.
 182     CHECK_EQ(-1, trace_id);
 183     trace_id = component_sequence_number;
 184     TRACE_EVENT_ASYNC_BEGIN0("benchmark",
 185                              "InputLatency",
 186                              TRACE_ID_DONT_MANGLE(trace_id));
 187     TRACE_EVENT_FLOW_BEGIN0(
 188         "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
 189   }
 190
 191   LatencyMap::key_type key = std::make_pair(component, id);
 192   LatencyMap::iterator it = latency_components.find(key);
 193   if (it == latency_components.end()) {
 194     LatencyComponent info = {component_sequence_number, time, event_count};
 195     latency_components[key] = info;
 196   } else {
 197     it->second.sequence_number = std::max(component_sequence_number,
 198                                           it->second.sequence_number);
 199     uint32 new_count = event_count + it->second.event_count;
 200     if (event_count > 0 && new_count != 0) {
 201       // Do a weighted average, so that the new event_time is the average of
 202       // the times of events currently in this structure with the time passed
 203       // into this method.
 204       it->second.event_time += (time - it->second.event_time) * event_count /
 205           new_count;
 206       it->second.event_count = new_count;
 207     }
 208   }
 209
 210   if (IsTerminalComponent(component) && trace_id != -1) {
 211     // Should only ever add terminal component once.
 212     CHECK(!terminated);
 213     terminated = true;
 214     TRACE_EVENT_ASYNC_END1("benchmark",
 215                            "InputLatency",
 216                            TRACE_ID_DONT_MANGLE(trace_id),
 217                            "data", AsTraceableData(*this));
 218     TRACE_EVENT_FLOW_END0(
 219         "input", "LatencyInfo.Flow", TRACE_ID_DONT_MANGLE(trace_id));
 220   }
 221 }
 222
 223 bool LatencyInfo::FindLatency(LatencyComponentType type,
 224                               int64 id,
 225                               LatencyComponent* output) const {
 226   LatencyMap::const_iterator it = latency_components.find(
 227       std::make_pair(type, id));
 228   if (it == latency_components.end())
 229     return false;
 230   if (output)
 231     *output = it->second;
 232   return true;
 233 }
 234
 235 void LatencyInfo::RemoveLatency(LatencyComponentType type) {
 236   LatencyMap::iterator it = latency_components.begin();
 237   while (it != latency_components.end()) {
 238     if (it->first.first == type) {
 239       LatencyMap::iterator tmp = it;
 240       ++it;
 241       latency_components.erase(tmp);
 242     } else {
 243       it++;
 244     }
 245   }
 246 }
 247
 248 void LatencyInfo::Clear() {
 249   latency_components.clear();
 250 }
 251
 252 void LatencyInfo::TraceEventType(const char* event_type) {
 253   TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
 254                                "InputLatency",
 255                                TRACE_ID_DONT_MANGLE(trace_id),
 256                                event_type);
 257 }
 258
 259 }  // namespace ui