Report LatencyInfo through trace buffer

ui/events/latency_info.cc

Index: ui/events/latency_info.cc
diff --git a/ui/events/latency_info.cc b/ui/events/latency_info.cc
index 796f442ae6d953de923edf7a131048c4ad046e4c..2ee64e0fe311fd119c8e4e8078970a1cf4e95ef8 100644
--- a/ui/events/latency_info.cc
+++ b/ui/events/latency_info.cc
@@ -2,13 +2,114 @@
 // 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) {
+  if (type == ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT)
+    return true;
+  return false;
+}
+
+// This class is for converting latency info to trace buffer friendly format.
+class LatencyInfoTracedValue : public base::debug::ConvertableToTraceFormat {
+ public:
+  static scoped_ptr<ConvertableToTraceFormat> FromValue(
+      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(base::Value* value) {
+  LatencyInfoTracedValue* ptr = new LatencyInfoTracedValue(value);
+  scoped_ptr<LatencyInfoTracedValue> result(ptr);
+  return result.PassAs<base::debug::ConvertableToTraceFormat>();
+}
+
+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.release());
+}
+
+}  // namespace
+
 namespace ui {
 
-LatencyInfo::LatencyInfo() {
+LatencyInfo::LatencyInfo() : trace_id(-1), terminated(false) {
 }
 
 LatencyInfo::~LatencyInfo() {
@@ -43,8 +144,27 @@ void LatencyInfo::AddNewLatencyFrom(const LatencyInfo& other) {
 void LatencyInfo::AddLatencyNumber(LatencyComponentType component,
                                    int64 id,
                                    int64 component_sequence_number) {
+  if (IsBeginComponent(component)) {
+    // Should only ever add begin component once.
+    DCHECK(trace_id == -1);
+    trace_id = component_sequence_number;
+    TRACE_EVENT_ASYNC_BEGIN0("benchmark",

[WRONG-USE-chromium, 2013/10/04 01:43:43]

If MergeWith is called, then we'll have a lot of dangling (BEGIN but no END)
trace records, right?  Is that a problem?  I know the plan is to eventually
eliminate MergeWith...

[Yufeng Shen (Slow to review), 2013/10/04 18:03:03]

Ideally we would like to totally get rid of MergeWith. The only place I am
worrying about now is when we coalescing events. The coalesced event will be
sent to renderer and can end there, so what should be the latencyinfo for
the coalesced event ?

If the the coalesced event does not end at renderer side and gets acked back,
as long as we keep all the uncoalesced events, we can still call END for each
of them.

+                             "InputLatency",
+                             TRACE_ID_DONT_MANGLE(trace_id));
+  }
+
   AddLatencyNumberWithTimestamp(component, id, component_sequence_number,
                                 base::TimeTicks::HighResNow(), 1);
+
+  if (IsTerminalComponent(component) && trace_id != -1) {
+    // Should only ever add terminal component once.
+    DCHECK(!terminated);

[WRONG-USE-chromium, 2013/10/04 01:43:43]

Since we don't normally run perf tests on Debug builds, can you make this a
CHECK instead?

[Yufeng Shen (Slow to review), 2013/10/04 18:03:03]

Done.

+    terminated = true;
+    TRACE_EVENT_ASYNC_END1("benchmark",
+                           "InputLatency",
+                           TRACE_ID_DONT_MANGLE(trace_id),
+                           "data", AsTraceableData(*this));
+  }
 }
 
 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,