Report LatencyInfo through trace buffer

ui/events/latency_info.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include "base/debug/trace_event.h"
+#include "base/json/json_writer.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/strings/stringprintf.h"
 #include "ui/events/latency_info.h"
 
 #include <algorithm>
 
+namespace {
+const char* GetComponentName(ui::LatencyComponentType type) {
+#define CASE_TYPE(t) case ui::t:  return #t
+  switch (type) {
+    CASE_TYPE(INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_RWH_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_UI_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT);
+    default:
+      DLOG(WARNING) << "Unhandled LatencyComponentType.\n";
+      break;
+  }
+#undef CASE_TYPE
+  return "unknown";
+}
+
+bool IsTerminalComponent(ui::LatencyComponentType type) {
+  switch (type) {
+    case ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT:
+    case ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT:
+    case ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT:
+    case ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT:
+      return true;
+    default:
+      return false;
+  }
+}
+
+bool IsBeginComponent(ui::LatencyComponentType type) {
+  return (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT);
+}
+
+// This class is for converting latency info to trace buffer friendly format.
+class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat {
+ public:
+  static scoped_ptr<ConvertableToTraceFormat> FromValue(
+      scoped_ptr<base::Value> value);
+
+  virtual ~LatencyInfoTracedValue();
+
+  virtual void AppendAsTraceFormat(std::string* out) const OVERRIDE;
+
+ private:
+  explicit LatencyInfoTracedValue(base::Value* value);
+
+  scoped_ptr<base::Value> value_;
+
+  DISALLOW_COPY_AND_ASSIGN(LatencyInfoTracedValue);
+};
+
+scoped_ptr<base::debug::ConvertableToTraceFormat>
+LatencyInfoTracedValue::FromValue(scoped_ptr<base::Value> value) {
+  return scoped_ptr<base::debug::ConvertableToTraceFormat>(
+      new LatencyInfoTracedValue(value.release()));
+}
+
+LatencyInfoTracedValue::~LatencyInfoTracedValue() {
+}
+
+void LatencyInfoTracedValue::AppendAsTraceFormat(std::string* out) const {
+  std::string tmp;
+  base::JSONWriter::Write(value_.get(), &tmp);
+  *out += tmp;
+}
+
+LatencyInfoTracedValue::LatencyInfoTracedValue(base::Value* value)
+    : value_(value) {
+}
+
+// Converts latencyinfo into format that can be dumped into trace buffer.
+scoped_ptr<base::debug::ConvertableToTraceFormat> AsTraceableData(
+    const ui::LatencyInfo& latency) {
+  scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue());
+  for (ui::LatencyInfo::LatencyMap::const_iterator it =
+           latency.latency_components.begin();
+       it != latency.latency_components.end(); ++it) {
+    base::DictionaryValue* component_info = new base::DictionaryValue();
+    component_info->SetDouble("comp_id", it->first.second);
+    component_info->SetDouble("time", it->second.event_time.ToInternalValue());
+    component_info->SetDouble("count", it->second.event_count);
+    record_data->Set(GetComponentName(it->first.first), component_info);
+  }
+  return LatencyInfoTracedValue::FromValue(record_data.PassAs<base::Value>());
+}
+
+}  // namespace
+
 namespace ui {
 
-LatencyInfo::LatencyInfo() {
+LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
 }
 
 LatencyInfo::~LatencyInfo() {
 }
 
 void LatencyInfo::MergeWith(const LatencyInfo& other) {
   for (LatencyMap::const_iterator it = other.latency_components.begin();
        it != other.latency_components.end();
        ++it) {
     AddLatencyNumberWithTimestamp(it->first.first,
                                   it->first.second,
                                   it->second.sequence_number,
                                   it->second.event_time,
-                                  it->second.event_count);
+                                  it->second.event_count,
+                                  false);
   }
 }
 
 void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
     for (LatencyMap::const_iterator it = other.latency_components.begin();
          it != other.latency_components.end();
          ++it) {
       if (!FindLatency(it->first.first, it->first.second, NULL)) {
         AddLatencyNumberWithTimestamp(it->first.first,
                                       it->first.second,
                                       it->second.sequence_number,
                                       it->second.event_time,
-                                      it->second.event_count);
+                                      it->second.event_count,
+                                      false);
       }
     }
 }
 
 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
                                    int64 id,
                                    int64 component_sequence_number) {
   AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
-                                base::TimeTicks::HighResNow(), 1);
+                                base::TimeTicks::HighResNow(), 1, true);
 }
 
 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
                                                 int64 id,
                                                 int64 component_sequence_number,
                                                 base::TimeTicks time,
-                                                uint32 event_count) {
+                                                uint32 event_count,
+                                                bool dump_to_trace) {
+  if (dump_to_trace && IsBeginComponent(component)) {
+    // Should only ever add begin component once.
+    CHECK_EQ(-1, trace_id);
+    trace_id = component_sequence_number;
+    TRACE_EVENT_ASYNC_BEGIN0("benchmark",
+                             "InputLatency",
+                             TRACE_ID_DONT_MANGLE(trace_id));
+  }
+
   LatencyMap::key_type key = std::make_pair(component, id);
   LatencyMap::iterator it = latency_components.find(key);
   if (it == latency_components.end()) {
     LatencyComponent info = {component_sequence_number, time, event_count};
     latency_components[key] = info;
-    return;
+  } else {
+    it->second.sequence_number = std::max(component_sequence_number,
+                                          it->second.sequence_number);
+    uint32 new_count = event_count + it->second.event_count;
+    if (event_count > 0 && new_count != 0) {
+      // Do a weighted average, so that the new event_time is the average of
+      // the times of events currently in this structure with the time passed
+      // into this method.
+      it->second.event_time += (time - it->second.event_time) * event_count /
+          new_count;
+      it->second.event_count = new_count;
+    }
   }
-  it->second.sequence_number = std::max(component_sequence_number,
-                                        it->second.sequence_number);
-  uint32 new_count = event_count + it->second.event_count;
-  if (event_count > 0 && new_count != 0) {
-    // Do a weighted average, so that the new event_time is the average of
-    // the times of events currently in this structure with the time passed
-    // into this method.
-    it->second.event_time += (time - it->second.event_time) * event_count /
-        new_count;
-    it->second.event_count = new_count;
+
+  if (dump_to_trace && IsTerminalComponent(component) && trace_id != -1) {
+    // Should only ever add terminal component once.
+    CHECK(!terminated);
+    terminated = true;
+    TRACE_EVENT_ASYNC_END1("benchmark",
+                           "InputLatency",
+                           TRACE_ID_DONT_MANGLE(trace_id),
+                           "data", AsTraceableData(*this));
   }
 }
 
 bool LatencyInfo::FindLatency(LatencyComponentType type,
                               int64 id,
                               LatencyComponent* output) const {
   LatencyMap::const_iterator it = latency_components.find(
       std::make_pair(type, id));
   if (it == latency_components.end())
     return false;
   if (output)
     *output = it->second;
   return true;
 }
 
 void LatencyInfo::Clear() {
   latency_components.clear();
 }
 
 }  // namespace ui