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