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

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 021b3c9c95c083cf984609dc2032e37745299102..bb4b2634212ebd844888a6542b4e08b43afa9760 100644
--- a/ui/events/latency_info.cc
+++ b/ui/events/latency_info.cc
@@ -182,9 +182,38 @@ void LatencyInfo::AddLatencyNumberWithTimestamp(LatencyComponentType 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));
   }