Add top-level async trace events for the main startup timings.

Add top-level async trace events for the main startup timings.

Allows to quickly see core metrics at a glance of a startup trace.
See SS in bug for an example.

As an added bonus, this also makes startup traces correctly consider 0s as the process creation time (instead of the first tracing event which is a fair bit later in practice).

BUG=542798
Committed: https://crrev.com/2074803ffea32a02ed40b7f1a79a432fe2dd3492
Cr-Commit-Position: refs/heads/master@{#354522}

[gab, 2015-10-13 19:09:24]

gab@chromium.org changed reviewers:
+ simonhatch@chromium.org

[gab, 2015-10-13 19:09:24]

Hey Simon, could you PTAL as a base/trace_event OWNER. In particular I'm curious
whether my usage of TraceTicks is reasonable (seems to work..!).

I own startup_metric_utils.cc so I'd like a review of the whole CL from you and
will then land it directly if you're okay with that.

Thanks!
Gab

[shatch, 2015-10-13 20:47:37]

base/trace_event/trace_event_common.h lgtm

[gab, 2015-10-14 00:35:02]

On 2015/10/13 20:47:37, shatch wrote:
> base/trace_event/trace_event_common.h lgtm

Did you also take a look at the bigger change? In particular usage of TraceTicks
in the other file?

Thanks!
Gab

[shatch, 2015-10-14 14:57:50]

On 2015/10/14 00:35:02, gab wrote:
> On 2015/10/13 20:47:37, shatch wrote:
> > base/trace_event/trace_event_common.h lgtm
> 
> Did you also take a look at the bigger change? In particular usage of
TraceTicks
> in the other file?
> 
> Thanks!
> Gab

Sorry, only looked at the macro. As discussed offline, at speed infra thingy all
week :( Feel free to grab another reviewer for faster turnaround.

[gab, 2015-10-14 15:01:12]

gab@chromium.org changed reviewers:
+ nduca@chromium.org

[gab, 2015-10-14 15:01:57]

On 2015/10/14 14:57:50, shatch wrote:
> On 2015/10/14 00:35:02, gab wrote:
> > On 2015/10/13 20:47:37, shatch wrote:
> > > base/trace_event/trace_event_common.h lgtm
> > 
> > Did you also take a look at the bigger change? In particular usage of
> TraceTicks
> > in the other file?
> > 
> > Thanks!
> > Gab
> 
> Sorry, only looked at the macro. As discussed offline, at speed infra thingy
all
> week :( Feel free to grab another reviewer for faster turnaround.

Nat can you PTAL at the change in startup_metric_utils.cc (e.g. usage of
TraceTicks).

Thanks,
Gab

[gab, 2015-10-14 15:02:12]

gab@chromium.org changed reviewers:
- simonhatch@chromium.org

[nduca, 2015-10-16 00:20:20]

lgtm

[nduca, 2015-10-16 00:22:49]

https://codereview.chromium.org/1408483002/diff/1/components/startup_metric_u...
File components/startup_metric_utils/startup_metric_utils.cc (right):

https://codereview.chromium.org/1408483002/diff/1/components/startup_metric_u...
components/startup_metric_utils/startup_metric_utils.cc:261: const
base::TimeDelta delta_since_base = time_base - time;
actually, now that i look at this, my lg is only conditional on you doing this
better down the road, by which i mean you filing and self-assigning a bug and
then noting in this patch that this is known  bad and you will fix it to be
better.

Critically, these conversions are very imprecise --- the clocks all drift
slightly with regard to each other. You might instead want to make either a
base::AllTheTimeStampsTogether {} struct that the callers of this file use, and
plumb that inot this file, or change the api on this file and how the startup
code interacts to be WILL_DO_X and DID_DO_X so that this can internally drive
uma but then talk to traciing async events without explicit timestamps.

[gab, 2015-10-16 14:39:16]

Thanks, filed a bug and added TODO.

https://codereview.chromium.org/1408483002/diff/1/components/startup_metric_u...
File components/startup_metric_utils/startup_metric_utils.cc (right):

https://codereview.chromium.org/1408483002/diff/1/components/startup_metric_u...
components/startup_metric_utils/startup_metric_utils.cc:261: const
base::TimeDelta delta_since_base = time_base - time;
On 2015/10/16 00:22:48, nduca wrote:
> actually, now that i look at this, my lg is only conditional on you doing this
> better down the road, by which i mean you filing and self-assigning a bug and
> then noting in this patch that this is known  bad and you will fix it to be
> better.
> 
> Critically, these conversions are very imprecise --- the clocks all drift
> slightly with regard to each other. You might instead want to make either a
> base::AllTheTimeStampsTogether {} struct that the callers of this file use,
and
> plumb that inot this file, 

Not sure I understand what you mean here?

> or change the api on this file and how the startup
> code interacts to be WILL_DO_X and DID_DO_X so that this can internally drive
> uma but then talk to traciing async events without explicit timestamps.

We can't do this because the |g_process_creation_time| is already set after the
fact (we get that time from the OS much after it has occurred). So we at least
need to convert that one from Time to TraceTicks and given we have to do one
conversation, we might as well convert everybody the same way (notice the static
in the basis above which make sure that any imprecision is at least the same for
every computation here -- so it's only a relative imprecision versus the
synchronous trace events).

Though looking at the details of CurrentProcessInfo::CreationTime() and
Time::FromFileTime() on Windows, maybe there is something to be done there to be
able to get process creation time as TraceTicks (then this entire API can use
TraceTicks as UMA only cares about TimeDeltas not absolute Times and callers can
easily use TraceTicks::Now() instead of Time::Now() in most places).

That's on Windows.. on other platforms (e.g. Android) the process creation time
also comes as base::Time() (from Java on Android =S...).

Not sure how to either make all callers speak TraceTicks or how to have a
precise conversation on all platforms...

What are TraceTicks anyways (in comparison to Time)? Do they also use the system
clock, but a more (or less?) precise one? I assume they don't start at zero but
that tracing merely makes the smaller one "zero" and then draws all others
relative to it?

Anyways, filed http://crbug.com/544131 let's continue the discussion there.
Thanks!

[gab, 2015-10-16 14:39:20]

The CQ bit was checked by gab@chromium.org

[gab, 2015-10-16 14:39:21]

The patchset sent to the CQ was uploaded after l-g-t-m from nduca@chromium.org,
simonhatch@chromium.org
Link to the patchset: https://codereview.chromium.org/1408483002/#ps20001
(title: "added TODO")

[commit-bot: I haz the power, 2015-10-16 14:39:38]

CQ is trying da patch. Follow status at
 https://chromium-cq-status.appspot.com/patch-status/1408483002/20001
View timeline at
 https://chromium-cq-status.appspot.com/patch-timeline/1408483002/20001

[commit-bot: I haz the power, 2015-10-16 16:21:03]

Committed patchset #2 (id:20001)

[commit-bot: I haz the power, 2015-10-16 16:21:43]

Patchset 2 (id:??) landed as
https://crrev.com/2074803ffea32a02ed40b7f1a79a432fe2dd3492
Cr-Commit-Position: refs/heads/master@{#354522}