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.
+// TODO(gab): Find a precise way to do this (http://crbug.com/544131).
+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;
+  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