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() {
+  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) {

[Alexei Svitkine (slow), 2017/04/19 16:52:16]

Nit: We don't usually keep const in the qualifiers for non-ref parameters, so
suggest removing them.

[themblsha, 2017/04/19 17:27:41]

I thought that it offers protection from unintended modification, and
semantically suggests that it shouldn't be modified inside the function.

const is already used inside several of the functions for local variables in
this file and parameters are local variables as well.

[Peter Kasting, 2017/04/19 18:12:12]

const on locals is fine.  const on params is more questionable:
* It looks to readers as if this was intended to be a const ref, so people try
to figure out what the intent was or waste time "fixing" things that weren't
broken.
* If the "const" is also used in the declaration, it exposes this implementation
detail to callers.  If it is not, then the declaration and definition have
different qualifiers, which is legal in this case but surprising to readers.

So even though I'm a big fan of local const, I suggest not using it on params.

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

Thanks for explaining this point, now it's clear to me.

   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