Add UMA metric: Startup.BrowserMainToRendererMain.

components/startup_metric_utils/browser/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/browser/startup_metric_utils.h"
 
 #include "base/containers/hash_tables.h"
 #include "base/environment.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
@@ skipping 12 matching lines @@
 
 namespace {
 
 // Mark as volatile to defensively make sure usage is thread-safe.
 // Note that at the time of this writing, access is only on the UI thread.
 volatile bool g_non_browser_ui_displayed = false;
 
 base::LazyInstance<base::TimeTicks>::Leaky g_process_creation_ticks =
     LAZY_INSTANCE_INITIALIZER;
 
-base::LazyInstance<base::TimeTicks>::Leaky g_main_entry_point_ticks =
+base::LazyInstance<base::TimeTicks>::Leaky g_browser_main_entry_point_ticks =
+    LAZY_INSTANCE_INITIALIZER;
+
+base::LazyInstance<base::TimeTicks>::Leaky g_renderer_main_entry_point_ticks =
     LAZY_INSTANCE_INITIALIZER;
 
 // Only used by RecordMainEntryTimeHistogram(), should go away with it (do not
 // add new uses of this), see crbug.com/317481 for discussion on why it was kept
 // as-is for now.
-base::LazyInstance<base::Time>::Leaky g_main_entry_point_time =
+base::LazyInstance<base::Time>::Leaky g_browser_main_entry_point_time =
     LAZY_INSTANCE_INITIALIZER;
 
 StartupTemperature g_startup_temperature = UNCERTAIN_STARTUP_TEMPERATURE;
 
 #if defined(OS_WIN)
 
 // These values are taken from the Startup.BrowserMessageLoopStartHardFaultCount
 // histogram. If the cold start histogram starts looking strongly bimodal it may
 // be because the binary/resource sizes have grown significantly larger than
 // when these values were set. In this case the new values need to be chosen
@@ skipping 113 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.
+// A metric logged using this macro must have an affected-histogram entry in the
+// definition of the StartupTemperature suffix in histograms.xml.
 #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);                               \
@@ skipping 108 matching lines @@
   // 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(!g_main_entry_point_time.Get().is_null());
+  DCHECK(!g_browser_main_entry_point_time.Get().is_null());
   const base::TimeDelta browser_main_entry_time_absolute =
-      g_main_entry_point_time.Get() - base::Time::UnixEpoch();
+      g_browser_main_entry_point_time.Get() - base::Time::UnixEpoch();
 
   const uint64 browser_main_entry_time_raw_ms =
       browser_main_entry_time_absolute.InMilliseconds();
 
   const base::TimeDelta browser_main_entry_time_raw_ms_high_word =
       base::TimeDelta::FromMilliseconds(
           (browser_main_entry_time_raw_ms >> 32) & kLowWordMask);
   // Shift by one because histograms only support non-negative values.
   const base::TimeDelta browser_main_entry_time_raw_ms_low_word =
       base::TimeDelta::FromMilliseconds(
           (browser_main_entry_time_raw_ms >> 1) & kLower31BitsMask);
 
   // A timestamp is a 64 bit value, yet histograms can only store 32 bits.
   LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteHighWord",
       browser_main_entry_time_raw_ms_high_word);
   LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteLowWord",
       browser_main_entry_time_raw_ms_low_word);
 }
 
+// Record renderer main entry time histogram.
+void RecordRendererMainEntryHistogram() {
+  const base::TimeTicks& browser_main_entry_point_ticks =
+      g_browser_main_entry_point_ticks.Get();
+  const base::TimeTicks& renderer_main_entry_point_ticks =
+      g_renderer_main_entry_point_ticks.Get();
+
+  if (!browser_main_entry_point_ticks.is_null() &&
+      !renderer_main_entry_point_ticks.is_null()) {
+    UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
+        UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserMainToRendererMain",
+        browser_main_entry_point_ticks, renderer_main_entry_point_ticks);
+  }
+}
+
 // Environment variable that stores the timestamp when the executable's main()
 // function was entered in TimeTicks. This is required because chrome.exe and
 // chrome.dll don't share the same static storage.
 const char kChromeMainTicksEnvVar[] = "CHROME_MAIN_TICKS";
 
 // Returns the time of main entry recorded from RecordExeMainEntryTime.
 base::TimeTicks ExeMainEntryPointTicks() {
   scoped_ptr<base::Environment> env(base::Environment::Create());
   std::string ticks_string;
   int64 time_int = 0;
@@ skipping 14 matching lines @@
   g_non_browser_ui_displayed = true;
 }
 
 void RecordStartupProcessCreationTime(const base::Time& time) {
   DCHECK(g_process_creation_ticks.Get().is_null());
   g_process_creation_ticks.Get() = StartupTimeToTimeTicks(time);
   DCHECK(!g_process_creation_ticks.Get().is_null());
 }
 
 void RecordMainEntryPointTime(const base::Time& time) {
-  DCHECK(g_main_entry_point_ticks.Get().is_null());
-  g_main_entry_point_ticks.Get() = StartupTimeToTimeTicks(time);
-  DCHECK(!g_main_entry_point_ticks.Get().is_null());
+  DCHECK(g_browser_main_entry_point_ticks.Get().is_null());
+  g_browser_main_entry_point_ticks.Get() = StartupTimeToTimeTicks(time);
+  DCHECK(!g_browser_main_entry_point_ticks.Get().is_null());
 
   // TODO(jeremy): Remove this with RecordMainEntryTimeHistogram() when
   // resolving crbug.com/317481.
-  DCHECK(g_main_entry_point_time.Get().is_null());
-  g_main_entry_point_time.Get() = time;
-  DCHECK(!g_main_entry_point_time.Get().is_null());
+  DCHECK(g_browser_main_entry_point_time.Get().is_null());
+  g_browser_main_entry_point_time.Get() = time;
+  DCHECK(!g_browser_main_entry_point_time.Get().is_null());
 }
 
 void RecordExeMainEntryPointTime(const base::Time& time) {
   const std::string exe_load_ticks =
       base::Int64ToString(StartupTimeToTimeTicks(time).ToInternalValue());
   scoped_ptr<base::Environment> env(base::Environment::Create());
   env->SetVar(kChromeMainTicksEnvVar, exe_load_ticks);
 }
 
 void RecordBrowserMainMessageLoopStart(const base::TimeTicks& ticks,
@@ skipping 17 matching lines @@
   // 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.
   if (is_first_run) {
     UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES,
         "Startup.BrowserMessageLoopStartTimeFromMainEntry.FirstRun",
-        g_main_entry_point_ticks.Get(), ticks);
+        g_browser_main_entry_point_ticks.Get(), ticks);
   } else {
     UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES,
         "Startup.BrowserMessageLoopStartTimeFromMainEntry",
-        g_main_entry_point_ticks.Get(), ticks);
+        g_browser_main_entry_point_ticks.Get(), ticks);
   }
 
   // Record timings between process creation, the main() in the executable being
   // reached and the main() in the shared library being reached.
   if (!process_creation_ticks.is_null()) {
     const base::TimeTicks exe_main_ticks = ExeMainEntryPointTicks();
     if (!exe_main_ticks.is_null()) {
       // Process create to chrome.exe:main().
       UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
           UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToExeMain",
           process_creation_ticks, exe_main_ticks);
 
       // chrome.exe:main() to chrome.dll:main().
       UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
           UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ExeMainToDllMain",
-          exe_main_ticks, g_main_entry_point_ticks.Get());
+          exe_main_ticks, g_browser_main_entry_point_ticks.Get());
 
       // 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",
-          g_main_entry_point_ticks.Get() - process_creation_ticks);
+          g_browser_main_entry_point_ticks.Get() - process_creation_ticks);
     }
   }
 }
 
 void RecordBrowserWindowDisplay(const base::TimeTicks& ticks) {
   static bool is_first_call = true;
   if (!is_first_call || ticks.is_null())
     return;
   is_first_call = false;
   if (WasNonBrowserUIDisplayed() || g_process_creation_ticks.Get().is_null())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES, "Startup.BrowserWindowDisplay",
       g_process_creation_ticks.Get(), ticks);
 }
 
 void RecordBrowserOpenTabsDelta(const base::TimeDelta& delta) {
   static bool is_first_call = true;
   if (!is_first_call)
     return;
   is_first_call = false;
 
   UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(UMA_HISTOGRAM_LONG_TIMES_100,
                                          "Startup.BrowserOpenTabs", delta);
 }
 
+void RecordRendererMainEntryTime(const base::TimeTicks& ticks) {
+  // Record the renderer main entry time, but don't log the UMA metric
+  // immediately because the startup temperature is not known yet.
+  if (g_renderer_main_entry_point_ticks.Get().is_null())
+    g_renderer_main_entry_point_ticks.Get() = ticks;
+}
+
 void RecordFirstWebContentsMainFrameLoad(const base::TimeTicks& ticks) {
   static bool is_first_call = true;
   if (!is_first_call || ticks.is_null())
     return;
   is_first_call = false;
   if (WasNonBrowserUIDisplayed() || g_process_creation_ticks.Get().is_null())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.MainFrameLoad2",
@@ skipping 12 matching lines @@
   UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.MainFrameLoad",
       ticks - g_process_creation_ticks.Get());
 }
 
 void RecordFirstWebContentsNonEmptyPaint(const base::TimeTicks& ticks) {
   static bool is_first_call = true;
   if (!is_first_call || ticks.is_null())
     return;
   is_first_call = false;
+
+  // Log Startup.BrowserMainToRendererMain now that the first renderer main
+  // entry time and the startup temperature are known.
+  RecordRendererMainEntryHistogram();
+
   if (WasNonBrowserUIDisplayed() || g_process_creation_ticks.Get().is_null())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.NonEmptyPaint2",
       g_process_creation_ticks.Get(), ticks);
 }
 
 void RecordDeprecatedFirstWebContentsNonEmptyPaint(
     const base::TimeTicks& ticks) {
@@ skipping 32 matching lines @@
   if (WasNonBrowserUIDisplayed() || g_process_creation_ticks.Get().is_null())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
       UMA_HISTOGRAM_LONG_TIMES_100,
       "Startup.FirstWebContents.MainNavigationFinished",
       g_process_creation_ticks.Get(), ticks);
 }
 
 base::TimeTicks MainEntryPointTicks() {
-  return g_main_entry_point_ticks.Get();
+  return g_browser_main_entry_point_ticks.Get();
 }
 
 StartupTemperature GetStartupTemperature() {
   return g_startup_temperature;
 }
 
 }  // namespace startup_metric_utils