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

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

Currently we draw the start of input event's latencyinfo using the
timestamp when we issue the async trace event when the input event
is passing through RWH. This CL changes that we now draw the start
of input event's latencyinfo using the input event's orignial/ui
component's timestamp so visually we can better see when the input
event was created.

BUG=396236
TEST=do scroll latency tracing on pixel/android, see that now latency
     for TouchMove and GestureScrollUpdate are drawn at the same starting
     time.

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=286705

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

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc
File ui/events/latency_info.cc (right):

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:206: "benchmark",
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:07]

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc
File ui/events/latency_info.cc (right):

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:203: int64 diff =
base::TimeTicks::HighResNow().ToInternalValue() -
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.

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:206: "benchmark",
On 2014/07/28 23:56:31, Yufeng Shen wrote:
> 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 ?


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.

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:212: TRACE_EVENT_ASYNC_BEGIN0("benchmark",
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]

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc
File ui/events/latency_info.cc (right):

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:203: int64 diff =
base::TimeTicks::HighResNow().ToInternalValue() -
On 2014/07/29 15:35:07, dsinclair wrote:
> 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.

Done.

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:206: "benchmark",
On 2014/07/29 15:35:06, dsinclair wrote:
> On 2014/07/28 23:56:31, Yufeng Shen wrote:
> > 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 ?
> 
> 
> 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.

Done.

https://codereview.chromium.org/424833009/diff/1/ui/events/latency_info.cc#ne...
ui/events/latency_info.cc:212: TRACE_EVENT_ASYNC_BEGIN0("benchmark",
On 2014/07/29 15:35:06, dsinclair wrote:
> 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.

Done.

[dsinclair, 2014-07-30 13:38:46]

lgtm

[Yufeng Shen (Slow to review), 2014-07-30 16:55:14]

The CQ bit was checked by miletus@chromium.org

[commit-bot: I haz the power, 2014-07-30 16:55:56]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/miletus@chromium.org/424833009/20001

[commit-bot: I haz the power, 2014-07-30 22:11:35]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  win_chromium_x64_rel on tryserver.chromium.win
(http://build.chromium.org/p/tryserver.chromium.win/builders/win_chromium_x64_...)

[commit-bot: I haz the power, 2014-07-31 03:24:13]

Change committed as 286705