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

components/startup_metric_utils/startup_metric_utils.cc

Index: components/startup_metric_utils/startup_metric_utils.cc
diff --git a/components/startup_metric_utils/startup_metric_utils.cc b/components/startup_metric_utils/startup_metric_utils.cc
index fc052cabb68a73060e18c8e1447658a9293b93d1..53e795a5f7f7e46eb5be37106c874a1103e64f65 100644
--- a/components/startup_metric_utils/startup_metric_utils.cc
+++ b/components/startup_metric_utils/startup_metric_utils.cc
@@ -11,6 +11,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_info.h"
+#include "base/trace_event/trace_event.h"
 
 #if defined(OS_WIN)
 #include <winternl.h>
@@ -162,18 +163,33 @@ bool GetHardFaultCountForCurrentProcess(uint32_t* hard_fault_count,
 // ".ColdStart" or ".WarmStart", as appropriate.
 // |value_expr| is an expression evaluating to the value to be recorded. This
 // will be evaluated exactly once and cached, so side effects are not an issue.
-#define UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(type, basename, value_expr) {  \
-      const auto kValue = value_expr;                                       \
-      /* Always record to the base histogram. */                            \
-      type(basename, kValue);                                               \
-      /* Record to the cold/warm suffixed histogram as appropriate. */      \
-      if (g_startup_temperature == COLD_STARTUP_TEMPERATURE) {              \
-        type(basename ".ColdStartup", kValue);                              \
-      } else if (g_startup_temperature == WARM_STARTUP_TEMPERATURE) {       \
-        type(basename ".WarmStartup", kValue);                              \
-      }                                                                     \
-    }
+#define UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(type, basename, value_expr) \
+  {                                                                        \
+    const auto kValue = value_expr;                                        \
+    /* Always record to the base histogram. */                             \
+    type(basename, kValue);                                                \
+    /* Record to the cold/warm suffixed histogram as appropriate. */       \
+    if (g_startup_temperature == COLD_STARTUP_TEMPERATURE) {               \
+      type(basename ".ColdStartup", kValue);                               \
+    } else if (g_startup_temperature == WARM_STARTUP_TEMPERATURE) {        \
+      type(basename ".WarmStartup", kValue);                               \
+    }                                                                      \
+  }
 
+#define UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(type, basename,       \
+                                                         begin_time, end_time) \
+  {                                                                            \
+    UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(type, basename,                     \
+                                           end_time - begin_time)              \
+    TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP1(                                   \
+        "startup", basename, 0,                                                \
+        StartupTimeToTraceTicks(begin_time).ToInternalValue(), "Temperature",  \
+        g_startup_temperature);                                                \
+    TRACE_EVENT_ASYNC_END_WITH_TIMESTAMP1(                                     \
+        "startup", basename, 0,                                                \
+        StartupTimeToTraceTicks(end_time).ToInternalValue(), "Temperature",    \
+        g_startup_temperature);                                                \
+  }
 
 // On Windows, records the number of hard-faults that have occurred in the
 // current chrome.exe process since it was started. This is a nop on other
@@ -229,6 +245,23 @@ void RecordHardFaultHistogram(bool is_first_run) {
 #endif  // defined(OS_WIN)
 }
 
+// Converts a base::Time value to a base::TraceTicks value. The conversion isn't
+// exact, but is within the time delta taken to synchronously resolve
+// base::Time::Now() and base::TraceTicks::Now() which in practice is pretty
+// much instant compared to multi-seconds startup timings.
+base::TraceTicks StartupTimeToTraceTicks(const base::Time& time) {
+  // First get a base which represents the same point in time in both units.
+  // The wall clock time it takes to gather both of these is the precision of
+  // this method.
+  static const base::Time time_base = base::Time::Now();
+  static const base::TraceTicks trace_ticks_base = base::TraceTicks::Now();
+
+  // Then use the TimeDelta common ground between the two units to make the
+  // conversion.
+  const base::TimeDelta delta_since_base = time_base - time;

[nduca, 2015/10/16 00:22:48]

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]

Not sure I understand what you mean here?
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!

+  return trace_ticks_base - delta_since_base;
+}
+
 // Record time of main entry so it can be read from Telemetry performance tests.
 // TODO(jeremy): Remove once crbug.com/317481 is fixed.
 void RecordMainEntryTimeHistogram() {
@@ -307,10 +340,9 @@ void RecordBrowserMainMessageLoopStart(const base::Time& time,
 
   const base::Time& process_creation_time = g_process_creation_time.Get();
   if (!is_first_run && !process_creation_time.is_null()) {
-    UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
-        UMA_HISTOGRAM_LONG_TIMES_100,
-        "Startup.BrowserMessageLoopStartTime",
-        time - process_creation_time);
+    UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
+        UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserMessageLoopStartTime",
+        process_creation_time, time);
   }
 
   // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been
@@ -327,17 +359,16 @@ void RecordBrowserMainMessageLoopStart(const base::Time& time,
   // * Only measure launches that occur 7 minutes after boot to try to avoid
   //   cases where Chrome is auto-started and IO is heavily loaded.
   const base::Time dll_main_time = MainEntryPointTime();
-  base::TimeDelta startup_time_from_main_entry = time - dll_main_time;
   if (is_first_run) {
-    UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+    UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES,
         "Startup.BrowserMessageLoopStartTimeFromMainEntry.FirstRun",
-        startup_time_from_main_entry);
+        dll_main_time, time);
   } else {
-    UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+    UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES,
-        "Startup.BrowserMessageLoopStartTimeFromMainEntry",
-        startup_time_from_main_entry);
+        "Startup.BrowserMessageLoopStartTimeFromMainEntry", dll_main_time,
+        time);
   }
 
   // Record timings between process creation, the main() in the executable being
@@ -346,17 +377,18 @@ void RecordBrowserMainMessageLoopStart(const base::Time& time,
     const base::Time exe_main_time = ExeMainEntryPointTime();
     if (!exe_main_time.is_null()) {
       // Process create to chrome.exe:main().
-      UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+      UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
           UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToExeMain",
-          exe_main_time - process_creation_time);
+          process_creation_time, exe_main_time);
 
       // chrome.exe:main() to chrome.dll:main().
-      UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+      UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
           UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ExeMainToDllMain",
-          dll_main_time - exe_main_time);
+          exe_main_time, dll_main_time);
 
-      // Process create to chrome.dll:main().
-      UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+      // Process create to chrome.dll:main(). Reported as a histogram only as
+      // the other two events above are sufficient for tracing purposes.
+      UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
           UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToDllMain",
           dll_main_time - process_creation_time);
     }
@@ -371,9 +403,9 @@ void RecordBrowserWindowDisplay(const base::Time& time) {
   if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
     return;
 
-  UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+  UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES, "Startup.BrowserWindowDisplay",
-      time - g_process_creation_time.Get());
+      g_process_creation_time.Get(), time);
 }
 
 void RecordBrowserOpenTabsDelta(const base::TimeDelta& delta) {
@@ -382,8 +414,8 @@ void RecordBrowserOpenTabsDelta(const base::TimeDelta& delta) {
     return;
   is_first_call = false;
 
-  UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
-      UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserOpenTabs", delta);
+  UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(UMA_HISTOGRAM_LONG_TIMES_100,
+                                         "Startup.BrowserOpenTabs", delta);
 }
 
 void RecordFirstWebContentsMainFrameLoad(const base::Time& time) {
@@ -394,9 +426,9 @@ void RecordFirstWebContentsMainFrameLoad(const base::Time& time) {
   if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
     return;
 
-  UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+  UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.MainFrameLoad",
-      time - g_process_creation_time.Get());
+      g_process_creation_time.Get(), time);
 }
 
 void RecordFirstWebContentsNonEmptyPaint(const base::Time& time) {
@@ -407,9 +439,9 @@ void RecordFirstWebContentsNonEmptyPaint(const base::Time& time) {
   if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
     return;
 
-  UMA_HISTOGRAM_BY_STARTUP_TEMPERATURE(
+  UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.NonEmptyPaint",
-      time - g_process_creation_time.Get());
+      g_process_creation_time.Get(), time);
 }
 
 base::Time MainEntryPointTime() {