Use real time instead of event time to compute trace event overhead

Use real time instead of event time to compute trace event overhead

Use real time instead of event time to compute overhead, because
event timestamp may be not the real time that we started to add the event
(e.g. event with zero timestamp or that was generated some time ago).

With this CL the overhead excludes the time between the beginning of
the TRACE_EVENT macro and AddTraceEventWithThreadIdAndTimestamp() which
should be trivial.

BUG=457441
Committed: https://crrev.com/75fa92e381158626c5ffb00bcb2423a868ba81e7
Cr-Commit-Position: refs/heads/master@{#316251}

[Xianzhu, 2015-02-13 17:07:36]

wangxianzhu@chromium.org changed reviewers:
+ dsinclair@chromium.org, nduca@chromium.org

[dsinclair, 2015-02-13 17:44:44]

The CQ bit was checked by dsinclair@chromium.org

[dsinclair, 2015-02-13 17:44:44]

lgtm

[commit-bot: I haz the power, 2015-02-13 17:45:22]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/929443002/1

[commit-bot: I haz the power, 2015-02-13 19:03:44]

Committed patchset #1 (id:1)

[commit-bot: I haz the power, 2015-02-13 19:04:40]

Patchset 1 (id:??) landed as
https://crrev.com/75fa92e381158626c5ffb00bcb2423a868ba81e7
Cr-Commit-Position: refs/heads/master@{#316251}

[nduca, 2015-02-13 19:13:44]

https://codereview.chromium.org/929443002/diff/1/base/trace_event/trace_event...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/929443002/diff/1/base/trace_event/trace_event...
base/trace_event/trace_event_impl.cc:1916: TimeTicks now = OffsetNow();
is this causing us to read the clock twice on every trace event? :(

[Xianzhu, 2015-02-13 19:27:26]

https://codereview.chromium.org/929443002/diff/1/base/trace_event/trace_event...
File base/trace_event/trace_event_impl.cc (right):

https://codereview.chromium.org/929443002/diff/1/base/trace_event/trace_event...
base/trace_event/trace_event_impl.cc:1916: TimeTicks now = OffsetNow();
On 2015/02/13 19:13:44, nduca wrote:
> is this causing us to read the clock twice on every trace event? :(

Yes :(

Possible ways to avoid this:
- check if overhead category is enabled before reading the clock;
- add a flag to indicate whether the event's timestamp is not now.

sg?

[picksi, 2015-02-19 12:18:13]

While perf sheriffing, this CL (along with several others) was reported by the
bisect bots as a possible cause of the regression shown here:

https://chromeperf.appspot.com/group_report?bug_id=459175

Please can you take a moment to confirm that this CL is innocent! Thanks.

[Xianzhu, 2015-02-23 17:35:17]

On 2015/02/19 12:18:13, picksi wrote:
> While perf sheriffing, this CL (along with several others) was reported by the
> bisect bots as a possible cause of the regression shown here:
> 
> https://chromeperf.appspot.com/group_report?bug_id=459175
> 
> Please can you take a moment to confirm that this CL is innocent! Thanks.

This CL may affect performance measurement but doesn't affect the product
performance. If it's the cause, I think we can just rebaseline the expectations.