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/json/json_writer.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_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_ACKED_MOUSE_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_TOUCH_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_ACKED_GESTURE_COMPONENT);
+    CASE_TYPE(INPUT_EVENT_LATENCY_FRAME_SWAP_COMPONENT);
+    default:
+      DLOG(WARNING) << "Unhandled LatencyComponentType.\n";
+      break;
+  }
+#undef CASE_TYPE
+  return "unknown";
+}
+
+}  // namespace
+
 namespace ui {
 
+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) {
+}
+
 LatencyInfo::LatencyInfo() {
 }
 
 LatencyInfo::~LatencyInfo() {
 }
 
+void LatencyInfo::Report(LatencyComponentType terminal_component) {

[nduca, 2013/10/01 21:43:44]

lets try putting the logic here inside the AddLatencyNumber code

[Rick Byers, 2013/10/03 13:12:41]

It should be illegal to call Report more than once for a given LatencyInfo,
right?  Otherwise we risk skewing the results by double-counting some components
but not others.  Can you enforce that here (poisoning the instance somehow that
will cause a CHECK failure if it's used further)?

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

Done.

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

Yes, added DCHECK to enforce that at most only one begin/terminal
component is allowed to be added.

+  AddLatencyNumber(terminal_component, 0, 0);
+  TRACE_EVENT_INSTANT1("benchmark",

[nduca, 2013/10/01 21:43:44]

can you try to issue async_begin and async_end traces and see what happens

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

Yes, we can see the grey latency rect in tracing UI after using
TRACE_EVENT_ASYNC_BEGIN/END.

+                       "LatencyInfo::IssueTraceEvent",
+                       TRACE_EVENT_SCOPE_THREAD,
+                       "data", AsTraceableData());
+}
+
+scoped_ptr<base::debug::ConvertableToTraceFormat>
+LatencyInfo::AsTraceableData() const {
+  scoped_ptr<base::DictionaryValue> record_data(new base::DictionaryValue());
+  for (LatencyMap::const_iterator it = latency_components.begin();
+       it != latency_components.end();
+       ++it) {
+    record_data->SetString(
+        GetComponentName(it->first.first),
+        base::StringPrintf("%ld %ld %d",

[nduca, 2013/10/01 21:43:44]

this should probably be another dict inside instad of a stringprintf, e.g.

component_info = new DictionaryValue();
component_info->SetString("seq_number", it->first.second);
...

record_data->Set(GetComponetnname(), component_info);

[Yufeng Shen (Slow to review), 2013/10/04 00:29:51]

Done.

+                           it->first.second,
+                           it->second.event_time.ToInternalValue(),
+                           it->second.event_count));
+  }
+  return LatencyInfoTracedValue::FromValue(record_data.release());
+}
+
 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);
   }
@@ skipping 55 matching lines @@
   if (output)
     *output = it->second;
   return true;
 }
 
 void LatencyInfo::Clear() {
   latency_components.clear();
 }
 
 }  // namespace ui