Add Startup.BrowserView.FirstPaint / .CompositingEnded histograms.

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 <stddef.h>
 #include <stdint.h>
 
 #include <string>
@@ skipping 21 matching lines @@
 #include <winternl.h>
 #include "base/win/win_util.h"
 #endif
 
 namespace startup_metric_utils {
 
 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;
+volatile bool g_main_window_startup_interrupted = false;
 
 base::LazyInstance<base::TimeTicks>::Leaky g_process_creation_ticks =
     LAZY_INSTANCE_INITIALIZER;
 
 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;
 
@@ skipping 328 matching lines @@
   }
 #endif  // defined(OS_WIN)
 }
 
 // Converts a base::Time value to a base::TimeTicks value. The conversion isn't
 // exact, but by capturing Time::Now() as early as possible, the likelihood of a
 // clock change between it and process start is as low as possible. There is
 // also the time taken to synchronously resolve base::Time::Now() and
 // base::TimeTicks::Now() at play, but in practice it is pretty much instant
 // compared to multi-seconds startup timings.
-base::TimeTicks StartupTimeToTimeTicks(const base::Time& time) {
-  // First get a base which represents the same point in time in both units.
-  // Bump the priority of this thread while doing this as the wall clock time it
-  // takes to resolve these two calls affects the precision of this method and
-  // bumping the priority reduces the likelihood of a context switch interfering
-  // with this computation.
+base::TimeTicks StartupTimeToTimeTicks(const base::Time time) {
+// First get a base which represents the same point in time in both units.
+// Bump the priority of this thread while doing this as the wall clock time it
+// takes to resolve these two calls affects the precision of this method and
+// bumping the priority reduces the likelihood of a context switch interfering
+// with this computation.
 
 // Enabling this logic on OS X causes a significant performance regression.
 // https://crbug.com/601270
 #if !defined(OS_MACOSX)
   static bool statics_initialized = false;
 
   base::ThreadPriority previous_priority = base::ThreadPriority::NORMAL;
   if (!statics_initialized) {
     previous_priority = base::PlatformThread::GetCurrentThreadPriority();
     base::PlatformThread::SetCurrentThreadPriority(
@@ skipping 41 matching lines @@
   // TODO(gabadie): Once startup_with_url.* benchmarks are replaced by
   //    startup_with_url2.*, remove this dirty hack (crbug.com/539287).
   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 =
+  const base::TimeTicks browser_main_entry_point_ticks =
       g_browser_main_entry_point_ticks.Get();
-  const base::TimeTicks& renderer_main_entry_point_ticks =
+  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_TEMPERATURE_AND_SAME_VERSION_COUNT(
         UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserMainToRendererMain",
         browser_main_entry_point_ticks, renderer_main_entry_point_ticks);
   }
 }
 
@@ skipping 70 matching lines @@
   } else {
     g_startups_with_current_version = 1;
     pref_service->SetString(prefs::kLastStartupVersion, current_version);
     pref_service->SetInteger(prefs::kSameVersionStartupCount, 1);
   }
 
   UMA_HISTOGRAM_COUNTS_100("Startup.SameVersionStartupCount",
                            g_startups_with_current_version);
 }
 
+bool ShouldLogProcessCreationTicksHistogram() {

[gab, 2017/04/19 18:45:43]

How about "ShouldLogStartupHistogram"? I find "ProcessCreationTicksHistogram"
hard to parse.

[themblsha, 2017/04/20 10:42:23]

Done.

+  return !WasMainWindowStartupInterrupted() &&
+         !g_process_creation_ticks.Get().is_null();
+}
+
 }  // namespace
 
 void RegisterPrefs(PrefRegistrySimple* registry) {
   DCHECK(registry);
   registry->RegisterInt64Pref(prefs::kLastStartupTimestamp, 0);
   registry->RegisterStringPref(prefs::kLastStartupVersion, std::string());
   registry->RegisterIntegerPref(prefs::kSameVersionStartupCount, 0);
 }
 
-bool WasNonBrowserUIDisplayed() {
-  return g_non_browser_ui_displayed;
+bool WasMainWindowStartupInterrupted() {
+  return g_main_window_startup_interrupted;
 }
 
 void SetNonBrowserUIDisplayed() {
-  g_non_browser_ui_displayed = true;
+  g_main_window_startup_interrupted = true;
 }
 
-void RecordStartupProcessCreationTime(const base::Time& time) {
+void SetBackgroundModeEnabled() {
+  g_main_window_startup_interrupted = 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) {
+void RecordMainEntryPointTime(const base::Time time) {
   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_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 RecordExeMainEntryPointTicks(const base::TimeTicks& ticks) {
+void RecordExeMainEntryPointTicks(const base::TimeTicks ticks) {
   DCHECK(g_browser_exe_main_entry_point_ticks.Get().is_null());
   g_browser_exe_main_entry_point_ticks.Get() = ticks;
   DCHECK(!g_browser_exe_main_entry_point_ticks.Get().is_null());
 }
 
-void RecordBrowserMainMessageLoopStart(const base::TimeTicks& ticks,
+void RecordBrowserMainMessageLoopStart(const base::TimeTicks ticks,
                                        bool is_first_run,
                                        PrefService* pref_service) {
   DCHECK(pref_service);
 
   // Keep RecordSameVersionStartupCount() and RecordHardFaultHistogram()
   // near the top of this method (as much as possible) as many other
   // histograms depend on it setting |g_startup_temperature| and
   // |g_startups_with_current_version|.
   RecordSameVersionStartupCount(pref_service);
   RecordHardFaultHistogram();
 
   // Record timing of the browser message-loop start time.
   base::StackSamplingProfiler::SetProcessMilestone(
       metrics::CallStackProfileMetricsProvider::MAIN_LOOP_START);
-  const base::TimeTicks& process_creation_ticks =
-      g_process_creation_ticks.Get();
+  const base::TimeTicks process_creation_ticks = g_process_creation_ticks.Get();
   if (!is_first_run && !process_creation_ticks.is_null()) {
     UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
         UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserMessageLoopStartTime",
         process_creation_ticks, ticks);
   }
 
   // Record timing between the shared library's main() entry and the browser
   // main message loop start.
   if (is_first_run) {
     UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE(
@@ skipping 31 matching lines @@
         exe_main_ticks, main_entry_ticks);
 
     // 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_TEMPERATURE_AND_SAME_VERSION_COUNT(
         UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToDllMain2",
         main_entry_ticks - process_creation_ticks);
   }
 }
 
-void RecordBrowserWindowDisplay(const base::TimeTicks& 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())
+  if (!ShouldLogProcessCreationTicksHistogram())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
       UMA_HISTOGRAM_LONG_TIMES, "Startup.BrowserWindowDisplay",
       g_process_creation_ticks.Get(), ticks);
 }
 
-void RecordBrowserOpenTabsDelta(const base::TimeDelta& delta) {
+void RecordBrowserOpenTabsDelta(const base::TimeDelta delta) {
   static bool is_first_call = true;
   if (!is_first_call)
     return;
   is_first_call = false;
 
   UMA_HISTOGRAM_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserOpenTabs", delta);
 }
 
-void RecordRendererMainEntryTime(const base::TimeTicks& ticks) {
+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) {
+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())
+  if (!ShouldLogProcessCreationTicksHistogram())
     return;
 
   UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.MainFrameLoad2",
       g_process_creation_ticks.Get(), ticks);
 }
 
-void RecordFirstWebContentsNonEmptyPaint(const base::TimeTicks& ticks) {
+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())
+  if (!ShouldLogProcessCreationTicksHistogram())
     return;
 
   base::StackSamplingProfiler::SetProcessMilestone(
       metrics::CallStackProfileMetricsProvider::FIRST_NONEMPTY_PAINT);
   UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
       UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.NonEmptyPaint2",
       g_process_creation_ticks.Get(), ticks);
 }
 
-void RecordFirstWebContentsMainNavigationStart(const base::TimeTicks& ticks,
+void RecordFirstWebContentsMainNavigationStart(const base::TimeTicks ticks,
                                                WebContentsWorkload workload) {
   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())
+  if (!ShouldLogProcessCreationTicksHistogram())
     return;
 
   base::StackSamplingProfiler::SetProcessMilestone(
       metrics::CallStackProfileMetricsProvider::MAIN_NAVIGATION_START);
   UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
       UMA_HISTOGRAM_LONG_TIMES_100,
       "Startup.FirstWebContents.MainNavigationStart",
       g_process_creation_ticks.Get(), ticks);
 
   // Log extra information about this startup's workload. Only added to this
   // histogram as this extra suffix can help making it less noisy but isn't
   // worth tripling the number of startup histograms either.
   if (workload == WebContentsWorkload::SINGLE_TAB) {
     UMA_HISTOGRAM_WITH_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES_100,
         "Startup.FirstWebContents.MainNavigationStart.SingleTab",
         ticks - g_process_creation_ticks.Get());
   } else {
     UMA_HISTOGRAM_WITH_TEMPERATURE(
         UMA_HISTOGRAM_LONG_TIMES_100,
         "Startup.FirstWebContents.MainNavigationStart.MultiTabs",
         ticks - g_process_creation_ticks.Get());
   }
 }
 
-void RecordFirstWebContentsMainNavigationFinished(
-    const base::TimeTicks& ticks) {
+void RecordFirstWebContentsMainNavigationFinished(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())
+  if (!ShouldLogProcessCreationTicksHistogram())
     return;
 
   base::StackSamplingProfiler::SetProcessMilestone(
       metrics::CallStackProfileMetricsProvider::MAIN_NAVIGATION_FINISHED);
   UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE_AND_SAME_VERSION_COUNT(
       UMA_HISTOGRAM_LONG_TIMES_100,
       "Startup.FirstWebContents.MainNavigationFinished",
       g_process_creation_ticks.Get(), ticks);
 }
 
+void RecordBrowserWindowFirstPaint(const base::TimeTicks ticks) {
+  static bool is_first_call = true;
+  if (!is_first_call || ticks.is_null())
+    return;
+  is_first_call = false;
+  if (!ShouldLogProcessCreationTicksHistogram())
+    return;
+
+  UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE(
+      UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserWindow.FirstPaint",
+      g_process_creation_ticks.Get(), ticks);
+}
+
+void RecordBrowserWindowFirstPaintCompositingEnded(
+    const base::TimeTicks ticks) {
+  static bool is_first_call = true;
+  if (!is_first_call || ticks.is_null())
+    return;
+  is_first_call = false;
+  if (!ShouldLogProcessCreationTicksHistogram())
+    return;
+
+  UMA_HISTOGRAM_AND_TRACE_WITH_TEMPERATURE(
+      UMA_HISTOGRAM_LONG_TIMES_100,
+      "Startup.BrowserWindow.FirstPaint.CompositingEnded",
+      g_process_creation_ticks.Get(), ticks);
+}
+
 base::TimeTicks MainEntryPointTicks() {
   return g_browser_main_entry_point_ticks.Get();
 }
 
 }  // namespace startup_metric_utils