Draw the start of input latency using its original/ui timestamp

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"
 
@@ skipping 164 matching lines @@
 
 void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType component,
                                                 int64 id,
                                                 int64 component_sequence_number,
                                                 base::TimeTicks time,
                                                 uint32 event_count) {
   if (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));
+
+    // The timestamp for ASYNC_BEGIN trace event is used for drawing the
+    // beginning of the trace event in trace viewer. For better visualization,
+    // for an input event, we want to draw the beginning as when the event is
+    // originally created, e.g. the timestamp of its ORIGINAL/UI_COMPONENT,
+    // not when we actually issue the ASYNC_BEGIN trace event.
+    LatencyComponent component;
+    if (FindLatency(INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
+                    0,
+                    &component) ||
+        FindLatency(INPUT_EVENT_LATENCY_UI_COMPONENT,
+                    0,
+                    &component)) {
+      // The timestamp stored in ORIGINAL/UI_COMPONENT is using CLOCK_MONOTONIC,
+      // while TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0 expects timestamp
+      // using CLOCK_MONOTONIC or CLOCK_SYSTEM_TRACE (on CrOS). So we need to
+      // adjust the diff between in CLOCK_MONOTONIC and CLOCK_SYSTEM_TRACE.
+      // Note that the diff is drifting overtime so we can't use a static value.
+      int64 diff = base::TimeTicks::HighResNow().ToInternalValue() -

[dsinclair, 2014/07/29 15:35:07]

Do we know how expensive these two timer calls are? We may want to put this all
behind an if() check that the category is enabled. We have code so you can set
the category value into a static and it will be updated as needed.

[Yufeng Shen (Slow to review), 2014/07/29 20:01:33]

Done.

+          base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();
+      TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP0(
+          "benchmark",

[Yufeng Shen (Slow to review), 2014/07/28 23:56:31]

Hey Dan, I want to confirm with you that trace event opened with
TRACE_EVENT_BEGIN_WITH_ID_TID_AND_TIMESTAMP  can be closed with
TRACE_EVENT_ASYNC_END ?

[dsinclair, 2014/07/29 15:35:06]

Why not create a TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0("benchmark",
"InputLatency", TRACE_ID_DONT_MANGLE(trace_id),
component.event_time.ToInternalValue() - diff);

You don't need to pass the TID and ASYNC already takes the ID.  I think that
would make more sense when lined up with the ASYNC end event later.

[Yufeng Shen (Slow to review), 2014/07/29 20:01:33]

Done.

+          "InputLatency",
+          TRACE_ID_DONT_MANGLE(trace_id),
+          static_cast<int>(base::PlatformThread::CurrentId()),
+          component.event_time.ToInternalValue() - diff);
+    } else {
+      TRACE_EVENT_ASYNC_BEGIN0("benchmark",

[dsinclair, 2014/07/29 15:35:06]

Why not have this part of what's above and then, instead of duping everything
just do something like:

int64 ts;
if (FindLatency ...)
  ts = component.event_time.ToInternalValeu() - diff;
else
  ts = base::TimeTicks::NowFromSystemTraceTime().ToInternalValue();

TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP0(..., ts);

saves duplicating the event information and makes the code a bit clearer.

[Yufeng Shen (Slow to review), 2014/07/29 20:01:33]

Done.

+                               "InputLatency",
+                               TRACE_ID_DONT_MANGLE(trace_id));
+    }
+
     TRACE_EVENT_FLOW_BEGIN0(
         "input", "LatencyInfo.Flow", 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;
   } else {
@@ skipping 53 matching lines @@
 }
 
 void LatencyInfo::TraceEventType(const char* event_type) {
   TRACE_EVENT_ASYNC_STEP_INTO0("benchmark",
                                "InputLatency",
                                TRACE_ID_DONT_MANGLE(trace_id),
                                event_type);
 }
 
 }  // namespace ui