Set process phases in the StackSamplingProfiler.

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>
 #include <vector>
 
 #include "base/containers/hash_tables.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
 #include "base/metrics/histogram.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/process/process_info.h"
+#include "base/profiler/stack_sampling_profiler.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/sys_info.h"
 #include "base/threading/platform_thread.h"
 #include "base/trace_event/trace_event.h"
 #include "build/build_config.h"
+#include "components/metrics/call_stack_profile_metrics_provider.h"
 #include "components/prefs/pref_registry_simple.h"
 #include "components/prefs/pref_service.h"
 #include "components/startup_metric_utils/browser/pref_names.h"
 #include "components/version_info/version_info.h"
 
 #if defined(OS_WIN)
 #include <winternl.h>
 #include "base/win/win_util.h"
 #endif
 
@@ skipping 560 matching lines @@
 
   RecordSameVersionStartupCount(pref_service);
   // Keep RecordHardFaultHistogram() first as much as possible as many other
   // histograms depend on it setting |g_startup_temperature|.
   RecordHardFaultHistogram();
   AddStartupEventsForTelemetry();
   RecordTimeSinceLastStartup(pref_service);
   RecordSystemUptimeHistogram();
   RecordMainEntryTimeHistogram();
 
+  base::StackSamplingProfiler::SetProcessPhase(
+      metrics::CallStackProfileMetricsProvider::MAIN_LOOP_START);

[Mike Wittman, 2016/12/01 18:46:50]

This line should be as close as possible to where we get the time, but
unfortunately that's is in the caller and not proximate to the histogram
recording below.

To keep these three things together I'd suggest making the
base::TimeTicks::Now() call at the start of this function, then setting the
phase.

[Alexei Svitkine (slow), 2016/12/01 19:49:12]

Right, I think we need to clearly define what SetProcessPhase() means - because
its name implies you should call it at the *start* of a phase, but the way this
CL is doing it, is you're calling it at the *end* of a phase - i.e. you're
calling it when the histogram is logged - which is at the end of the time.

I agree that logging the *end* of a phase is nice because then you can keep the
code to set it can live right next to the histogram - as is being done here.
However, then the API should be renamed to make that clear.

[Alexei Svitkine (slow), 2017/01/05 20:54:12]

Ping on this comment.

[bcwhite, 2017/01/06 16:50:56]

In this case, the name indicates that the "main loop has started".  Perhaps
simply changing the name to MAIN_LOOP_STARTED would be sufficient?

[Alexei Svitkine (slow), 2017/01/09 19:12:18]

I guess I'm less concerned with the name and more that I would like to make the
API & comment more explicit by what is meant.

e.g. change SetProcessPhase to something like SetLastCompletedProcessPhase() -
to make it clear that a call to this function implies the phase ended and not
started. Otherwise, its name makes me think you're setting the current phase
that's happening right now.

[bcwhite, 2017/01/10 17:56:54]

That's not what it does, though.  Perhaps "SetProcessMilestone" would be a
better name because it's not specifically beginning or ending of a phase.  For
example, the "shutdown" phase indicates that shutdown in starting.

[Mike Wittman, 2017/01/10 20:10:36]

Just noticed that this comment still remains to be addressed. Please make this
change before submitting.

[bcwhite, 2017/01/11 16:15:48]

If I understand you correctly, this amounts to removing the |ticks| parameter
and getting it directly at the start of the method, then immediately setting the
phase.

[Mike Wittman, 2017/01/11 16:24:47]

Yes, and moving the histogram recording immediately after that.

[bcwhite, 2017/01/11 16:26:39]

Looking further, every other method also takes a time parameter so I think we
should keep the parameter for consistency sake.  But I'll move the histogram
set.

[Mike Wittman, 2017/01/11 16:30:18]

Sounds good to me.

[bcwhite, 2017/01/11 16:53:28]

Done (order) and Done (naming).

+
   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);
   }
 
   // TODO(fdoray): Remove histograms that are only recorded after 7 minutes of
   // OS uptime once M54 hits stable. These histograms are kept for now to allow
@@ skipping 115 matching lines @@
     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;
 
+  base::StackSamplingProfiler::SetProcessPhase(
+      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) {
   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;
 
+  base::StackSamplingProfiler::SetProcessPhase(
+      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);
 }
 
 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())
     return;
 
+  base::StackSamplingProfiler::SetProcessPhase(
+      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);
 }
 
 base::TimeTicks MainEntryPointTicks() {
   return g_browser_main_entry_point_ticks.Get();
 }
 
 }  // namespace startup_metric_utils