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