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

components/startup_metric_utils/startup_metric_utils.cc

 // Copyright 2013 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "components/startup_metric_utils/startup_metric_utils.h"
 
 #include "base/containers/hash_tables.h"
 #include "base/environment.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
 #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>
 #include "base/win/windows_version.h"
 #endif
 
 namespace startup_metric_utils {
 
 namespace {
 
@@ skipping 131 matching lines @@
 // Helper macro for splitting out an UMA histogram based on cold or warm start.
 // |type| is the histogram type, and corresponds to an UMA macro like
 // UMA_HISTOGRAM_LONG_TIMES. It must be itself be a macro that only takes two
 // parameters.
 // |basename| is the basename of the histogram. A histogram of this name will
 // always be recorded to. If the startup is either cold or warm then a value
 // will also be recorded to the histogram with name |basename| and suffix
 // ".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
 // platforms.
 // crbug.com/476923
 // TODO(chrisha): If this proves useful, use it to split startup stats in two.
 void RecordHardFaultHistogram(bool is_first_run) {
 #if defined(OS_WIN)
   uint32_t hard_fault_count = 0;
   bool has_os_support = false;
@@ skipping 35 matching lines @@
   } else if (hard_fault_count >= COLD_START_HARD_FAULT_COUNT_THRESHOLD) {
     g_startup_temperature = COLD_STARTUP_TEMPERATURE;
   }
 
   // Record the startup 'temperature'.
   UMA_HISTOGRAM_ENUMERATION(
       "Startup.Temperature", g_startup_temperature, STARTUP_TEMPERATURE_MAX);
 #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() {
   const int kLowWordMask = 0xFFFFFFFF;
   const int kLower31BitsMask = 0x7FFFFFFF;
   DCHECK(!MainEntryPointTime().is_null());
   base::TimeDelta browser_main_entry_time_absolute =
       MainEntryPointTime() - base::Time::UnixEpoch();
 
   uint64 browser_main_entry_time_raw_ms =
@@ skipping 58 matching lines @@
   env->SetVar(kChromeMainTimeEnvVar, exe_load_time);
 }
 
 void RecordBrowserMainMessageLoopStart(const base::Time& time,
                                        bool is_first_run) {
   RecordHardFaultHistogram(is_first_run);
   RecordMainEntryTimeHistogram();
 
   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
   // autostarted and the machine is under io pressure.
   const int64 kSevenMinutesInMilliseconds =
       base::TimeDelta::FromMinutes(7).InMilliseconds();
   if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds)
     return;
 
   // The Startup.BrowserMessageLoopStartTime histogram exhibits instability in
   // the field which limits its usefulness in all scenarios except when we have
   // a very large sample size. Attempt to mitigate this with a new metric:
   // * Measure time from main entry rather than the OS' notion of process start.
   // * 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
   // reached and the main() in the shared library being reached.
   if (!process_creation_time.is_null()) {
     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);
     }
   }
 }
 
 void RecordBrowserWindowDisplay(const base::Time& time) {
   static bool is_first_call = true;
   if (!is_first_call || time.is_null())
     return;
   is_first_call = false;
   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) {
   static bool is_first_call = true;
   if (!is_first_call)
     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) {
   static bool is_first_call = true;
   if (!is_first_call || time.is_null())
     return;
   is_first_call = false;
   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) {
   static bool is_first_call = true;
   if (!is_first_call || time.is_null())
     return;
   is_first_call = false;
   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() {
   return g_main_entry_point_time.Get();
 }
 
 StartupTemperature GetStartupTemperature() {
   return g_startup_temperature;
 }
 
 }  // namespace startup_metric_utils