Home | History | Annotate | Download | only in events 
      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
    260