Make stack sampling profiler sample beyond startup.

components/metrics/call_stack_profile_metrics_provider.cc

 // Copyright 2015 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/metrics/call_stack_profile_metrics_provider.h"
 
 #include <stddef.h>
 #include <stdint.h>
 
 #include <algorithm>
 #include <cstring>
 #include <map>
 #include <string>
 #include <utility>
 #include <vector>
 
 #include "base/bind.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/macros.h"
 #include "base/memory/singleton.h"
-#include "base/metrics/field_trial.h"
+#include "base/metrics/field_trial_params.h"
 #include "base/metrics/metrics_hashes.h"
 #include "base/profiler/stack_sampling_profiler.h"
 #include "base/single_thread_task_runner.h"
 #include "base/synchronization/lock.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/time.h"
 #include "components/metrics/proto/chrome_user_metrics_extension.pb.h"
 
 using base::StackSamplingProfiler;
 
 namespace metrics {
 
 namespace {
 
+// Interval for periodic (post-startup) sampling, when enabled.
+constexpr base::TimeDelta kPeriodicSamplingInterval =
+    base::TimeDelta::FromSeconds(1);
+
 // Provide a mapping from the C++ "enum" definition of various process mile-
 // stones to the equivalent protobuf "enum" definition. This table-lookup
 // conversion allows for the implementation to evolve and still be compatible
 // with the protobuf -- even if there are ever more than 32 defined proto
 // values, though never more than 32 could be in-use in a given C++ version
 // of the code.
 const ProcessPhase
     kProtoPhases[CallStackProfileMetricsProvider::MILESTONES_MAX_VALUE] = {
         ProcessPhase::MAIN_LOOP_START,
         ProcessPhase::MAIN_NAVIGATION_START,
         ProcessPhase::MAIN_NAVIGATION_FINISHED,
         ProcessPhase::FIRST_NONEMPTY_PAINT,
 
         ProcessPhase::SHUTDOWN_START,
 };
 
 // ProfilesState --------------------------------------------------------------
 
 // A set of profiles and the CallStackProfileMetricsProvider state associated
 // with them.
 struct ProfilesState {
   ProfilesState(const CallStackProfileParams& params,
-                StackSamplingProfiler::CallStackProfiles profiles,
-                base::TimeTicks start_timestamp);
+                StackSamplingProfiler::CallStackProfiles profiles);
   ProfilesState(ProfilesState&&);
   ProfilesState& operator=(ProfilesState&&);
 
   // The metrics-related parameters provided to
   // CallStackProfileMetricsProvider::GetProfilerCallback().
   CallStackProfileParams params;
 
   // The call stack profiles collected by the profiler.
   StackSamplingProfiler::CallStackProfiles profiles;
 
-  // The time at which the CallStackProfileMetricsProvider became aware of the
-  // request for profiling. In particular, this is when callback was requested
-  // via CallStackProfileMetricsProvider::GetProfilerCallback(). Used to
-  // determine if collection was disabled during the collection of the profile.
-  base::TimeTicks start_timestamp;
-
  private:
   DISALLOW_COPY_AND_ASSIGN(ProfilesState);
 };
 
 ProfilesState::ProfilesState(const CallStackProfileParams& params,
-                             StackSamplingProfiler::CallStackProfiles profiles,
-                             base::TimeTicks start_timestamp)
-    : params(params),
-      profiles(std::move(profiles)),
-      start_timestamp(start_timestamp) {}
+                             StackSamplingProfiler::CallStackProfiles profiles)
+    : params(params), profiles(std::move(profiles)) {}
 
 ProfilesState::ProfilesState(ProfilesState&&) = default;
 
 // Some versions of GCC need this for push_back to work with std::move.
 ProfilesState& ProfilesState::operator=(ProfilesState&&) = default;
 
 // PendingProfiles ------------------------------------------------------------
 
 // Singleton class responsible for retaining profiles received via the callback
 // created by CallStackProfileMetricsProvider::GetProfilerCallback(). These are
@@ skipping 76 matching lines @@
 }
 
 void PendingProfiles::CollectProfilesIfCollectionEnabled(
     ProfilesState profiles) {
   base::AutoLock scoped_lock(lock_);
 
   // Only collect if collection is not disabled and hasn't been disabled
   // since the start of collection for this profile.
   if (!collection_enabled_ ||
       (!last_collection_disable_time_.is_null() &&
-       last_collection_disable_time_ >= profiles.start_timestamp)) {
+       last_collection_disable_time_ >= profiles.params.start_timestamp)) {
     return;
   }
 
   profiles_.push_back(std::move(profiles));
 }
 
 void PendingProfiles::ResetToDefaultStateForTesting() {
   base::AutoLock scoped_lock(lock_);
 
   collection_enabled_ = true;
   last_collection_disable_time_ = base::TimeTicks();
   profiles_.clear();
 }
 
 // |collection_enabled_| is initialized to true to collect any profiles that are
 // generated prior to creation of the CallStackProfileMetricsProvider. The
 // ultimate disposition of these pre-creation collected profiles will be
 // determined by the initial recording state provided to
 // CallStackProfileMetricsProvider.
 PendingProfiles::PendingProfiles() : collection_enabled_(true) {}
 
 PendingProfiles::~PendingProfiles() {}
 
 // Functions to process completed profiles ------------------------------------
 
 // Will be invoked on either the main thread or the profiler's thread. Provides
 // the profiles to PendingProfiles to append, if the collecting state allows.
-void ReceiveCompletedProfilesImpl(
-    const CallStackProfileParams& params,
-    base::TimeTicks start_timestamp,
+base::Optional<StackSamplingProfiler::SamplingParams>
+ReceiveCompletedProfilesImpl(
+    CallStackProfileParams* params,

[Mike Wittman, 2017/07/06 22:14:02]

We can revert to passing this by const reference again.

[Alexei Svitkine (slow), 2017/07/07 16:18:48]

No, these are the CallStackProfileParams - which we are modifying (see line
216). SamplingParams are no longer being modified, but they're also no longer
being passed.

[Mike Wittman, 2017/07/07 18:15:17]

That's true. I think we could avoid this modification and the need to store an
instance of the CallStackProfileParams by returning a new callback (that binds
the new CallStackProfileParams) along with the SamplingParams from the callback.
But this would require a recursive callback type and it's not obvious how that
would be represented. We can leave any changes here to the follow-on CL as well.

     StackSamplingProfiler::CallStackProfiles profiles) {
   PendingProfiles::GetInstance()->CollectProfilesIfCollectionEnabled(
-      ProfilesState(params, std::move(profiles), start_timestamp));
+      ProfilesState(*params, std::move(profiles)));
+
+  // Now, schedule periodic sampling every 1s, if enabled by trial.
+  if (CallStackProfileMetricsProvider::IsPeriodicSamplingEnabled() &&

[Mike Wittman, 2017/07/06 22:14:02]

If we're not supporting non-browser processes in this CL, then this logic can be
moved to ReceiveCompletedProfiles, which is only invoked by the browser process.

[Alexei Svitkine (slow), 2017/07/07 16:18:48]

Er, that's not correct. Browser process uses
CallStackProfileMetricsProvider::GetProfilerCallback() which returns a callback
to this (*Impl) function. It doesn't go through ReceiveCompletedProfiles.

It's the child process mojo-collected ones that go through
ReceiveCompletedProfiles().

[Mike Wittman, 2017/07/07 18:15:17]

Right. Apparently I shouldn't be relying on my memory of this code. :)

+      params->process == CallStackProfileParams::BROWSER_PROCESS &&
+      params->thread == CallStackProfileParams::UI_THREAD) {
+    params->trigger = metrics::CallStackProfileParams::PERIODIC_COLLECTION;
+    params->start_timestamp = base::TimeTicks::Now();
+
+    StackSamplingProfiler::SamplingParams sampling_params;
+    sampling_params.initial_delay = kPeriodicSamplingInterval;
+    sampling_params.bursts = 1;
+    sampling_params.samples_per_burst = 1;
+    // Below are unused:
+    sampling_params.burst_interval = base::TimeDelta::FromMilliseconds(0);
+    sampling_params.sampling_interval = base::TimeDelta::FromMilliseconds(0);
+    return sampling_params;
+  }
+  return base::Optional<StackSamplingProfiler::SamplingParams>();
 }
 
 // Invoked on an arbitrary thread. Ignores the provided profiles.
-void IgnoreCompletedProfiles(
-    StackSamplingProfiler::CallStackProfiles profiles) {}
+base::Optional<StackSamplingProfiler::SamplingParams> IgnoreCompletedProfiles(
+    StackSamplingProfiler::CallStackProfiles profiles) {
+  return base::Optional<StackSamplingProfiler::SamplingParams>();
+}
 
 // Functions to encode protobufs ----------------------------------------------
 
 // The protobuf expects the MD5 checksum prefix of the module name.
 uint64_t HashModuleFilename(const base::FilePath& filename) {
   const base::FilePath::StringType basename = filename.BaseName().value();
   // Copy the bytes in basename into a string buffer.
   size_t basename_length_in_bytes =
       basename.size() * sizeof(base::FilePath::CharType);
   std::string name_bytes(basename_length_in_bytes, '\0');
@@ skipping 41 matching lines @@
       sample_proto->add_process_phase(kProtoPhases[bit]);
       new_milestones ^= flag;  // Bit is set so XOR will clear it.
     }
   }
 }
 
 // Transcode |profile| into |proto_profile|.
 void CopyProfileToProto(
     const StackSamplingProfiler::CallStackProfile& profile,
     CallStackProfileParams::SampleOrderingSpec ordering_spec,
+    int64_t sampling_period_ms,
     CallStackProfile* proto_profile) {
   if (profile.samples.empty())
     return;
 
   const bool preserve_order =
       (ordering_spec == CallStackProfileParams::PRESERVE_ORDER);
 
   std::map<StackSamplingProfiler::Sample, int> sample_index;
   uint32_t milestones = 0;
   for (auto it = profile.samples.begin(); it != profile.samples.end(); ++it) {
@@ skipping 30 matching lines @@
 
   for (const StackSamplingProfiler::Module& module : profile.modules) {
     CallStackProfile::ModuleIdentifier* module_id =
         proto_profile->add_module_id();
     module_id->set_build_id(module.id);
     module_id->set_name_md5_prefix(HashModuleFilename(module.filename));
   }
 
   proto_profile->set_profile_duration_ms(
       profile.profile_duration.InMilliseconds());
-  proto_profile->set_sampling_period_ms(
-      profile.sampling_period.InMilliseconds());
+  proto_profile->set_sampling_period_ms(sampling_period_ms);
 }
 
 // Translates CallStackProfileParams's process to the corresponding
 // execution context Process.
 Process ToExecutionContextProcess(CallStackProfileParams::Process process) {
   switch (process) {
     case CallStackProfileParams::UNKNOWN_PROCESS:
       return UNKNOWN_PROCESS;
     case CallStackProfileParams::BROWSER_PROCESS:
       return BROWSER_PROCESS;
@@ skipping 53 matching lines @@
     CallStackProfileParams::Trigger trigger) {
   switch (trigger) {
     case CallStackProfileParams::UNKNOWN:
       return SampledProfile::UNKNOWN_TRIGGER_EVENT;
     case CallStackProfileParams::PROCESS_STARTUP:
       return SampledProfile::PROCESS_STARTUP;
     case CallStackProfileParams::JANKY_TASK:
       return SampledProfile::JANKY_TASK;
     case CallStackProfileParams::THREAD_HUNG:
       return SampledProfile::THREAD_HUNG;
+    case CallStackProfileParams::PERIODIC_COLLECTION:
+      return SampledProfile::PERIODIC_COLLECTION;

[Mike Wittman, 2017/07/06 22:14:02]

This CL seems to be missing the proto change to add PERIODIC_COLLECTION. (And
the corresponding change server-side needs to be approved first as well.)

[Alexei Svitkine (slow), 2017/07/07 16:18:48]

PERIODIC_COLLECTION is already in the proto - I guess because CWP had added it.
(The comment doesn't fully match what we're doing here - since it talks about a
random interval - but I think we can just relax the comment a bit - which I can
do in a separate CL so as not to block this one on logs.)

[Mike Wittman, 2017/07/07 18:15:17]

Ah, didn't consider that this was reusing a CWP enum.

To support this we'll need to update the mechanism for filtering the sampling
profiler data into its own logs source (the IsSamplingProfilerEvent server
function). Currently it's based on trigger value but if we reuse the trigger
then I think we'll need a different mechanism for distinguishing the CWP data
from the sampling profiler data.

[Alexei Svitkine (slow), 2017/07/07 19:04:14]

Thanks for the heads up! Will look at doing that before enabling this new
functionality from the experiment.

   }
   NOTREACHED();
   return SampledProfile::UNKNOWN_TRIGGER_EVENT;
 }
 
 }  // namespace
 
 // CallStackProfileMetricsProvider --------------------------------------------
 
-const char CallStackProfileMetricsProvider::kFieldTrialName[] =
-    "StackProfiling";
-const char CallStackProfileMetricsProvider::kReportProfilesGroupName[] =
-    "Report profiles";
+const base::Feature CallStackProfileMetricsProvider::kEnableReporting = {
+    "SamplingProfilerReporting", base::FEATURE_DISABLED_BY_DEFAULT};
 
 CallStackProfileMetricsProvider::CallStackProfileMetricsProvider() {
 }
 
 CallStackProfileMetricsProvider::~CallStackProfileMetricsProvider() {
 }
 
 // This function can be invoked on an abitrary thread.
 StackSamplingProfiler::CompletedCallback
 CallStackProfileMetricsProvider::GetProfilerCallback(
-    const CallStackProfileParams& params) {
+    CallStackProfileParams* params) {
   // Ignore the profiles if the collection is disabled. If the collection state
   // changes while collecting, this will be detected by the callback and
   // profiles will be ignored at that point.
   if (!PendingProfiles::GetInstance()->IsCollectionEnabled())
     return base::Bind(&IgnoreCompletedProfiles);
 
-  return base::Bind(&ReceiveCompletedProfilesImpl, params,
-                    base::TimeTicks::Now());
+  params->start_timestamp = base::TimeTicks::Now();
+  return base::Bind(&ReceiveCompletedProfilesImpl, params);
 }
 
 // static
 void CallStackProfileMetricsProvider::ReceiveCompletedProfiles(
-    const CallStackProfileParams& params,
-    base::TimeTicks start_timestamp,
-    StackSamplingProfiler::CallStackProfiles profiles) {
-  ReceiveCompletedProfilesImpl(params, start_timestamp, std::move(profiles));
+    CallStackProfileParams* params,
+    base::StackSamplingProfiler::CallStackProfiles profiles) {
+  ReceiveCompletedProfilesImpl(params, std::move(profiles));
+}
+
+// static
+bool CallStackProfileMetricsProvider::IsPeriodicSamplingEnabled() {
+  // Ensure FeatureList has been initialized before calling into an API that
+  // calls base::FeatureList::IsEnabled() internally. While extremely unlikely,
+  // it is possible that the profiler callback and therefore this function get
+  // called before FeatureList initialization (e.g. if machine was suspended).
+  return base::FeatureList::GetInstance() != nullptr &&
+         base::GetFieldTrialParamByFeatureAsBool(kEnableReporting, "periodic",
+                                                 false);
 }
 
 void CallStackProfileMetricsProvider::OnRecordingEnabled() {
   PendingProfiles::GetInstance()->SetCollectionEnabled(true);
 }
 
 void CallStackProfileMetricsProvider::OnRecordingDisabled() {
   PendingProfiles::GetInstance()->SetCollectionEnabled(false);
 }
 
 void CallStackProfileMetricsProvider::ProvideGeneralMetrics(
     ChromeUserMetricsExtension* uma_proto) {
   std::vector<ProfilesState> pending_profiles;
   PendingProfiles::GetInstance()->Swap(&pending_profiles);
 
   DCHECK(IsReportingEnabledByFieldTrial() || pending_profiles.empty());
 
+  // TODO(asvitkine): For post-startup periodic samples, this is currently
+  // wasteful as each sample is reported in its own profile. We should attempt
+  // to merge profiles to save bandwidth.
   for (const ProfilesState& profiles_state : pending_profiles) {
     for (const StackSamplingProfiler::CallStackProfile& profile :
              profiles_state.profiles) {
       SampledProfile* sampled_profile = uma_proto->add_sampled_profile();
-      sampled_profile->set_process(ToExecutionContextProcess(
-          profiles_state.params.process));
-      sampled_profile->set_thread(ToExecutionContextThread(
-          profiles_state.params.thread));
-      sampled_profile->set_trigger_event(ToSampledProfileTriggerEvent(
-          profiles_state.params.trigger));
+      sampled_profile->set_process(
+          ToExecutionContextProcess(profiles_state.params.process));
+      sampled_profile->set_thread(
+          ToExecutionContextThread(profiles_state.params.thread));
+      sampled_profile->set_trigger_event(
+          ToSampledProfileTriggerEvent(profiles_state.params.trigger));
+
+      int64_t sampling_period_ms = profile.sampling_period.InMilliseconds();
+      if (sampled_profile->trigger_event() ==
+          SampledProfile::PERIODIC_COLLECTION) {
+        sampling_period_ms += kPeriodicSamplingInterval.InMilliseconds();
+      }
       CopyProfileToProto(profile, profiles_state.params.ordering_spec,
+                         sampling_period_ms,
                          sampled_profile->mutable_call_stack_profile());
     }
   }
 }
 
 // static
 void CallStackProfileMetricsProvider::ResetStaticStateForTesting() {
   PendingProfiles::GetInstance()->ResetToDefaultStateForTesting();
 }
 
 // static
 bool CallStackProfileMetricsProvider::IsReportingEnabledByFieldTrial() {
-  const std::string group_name = base::FieldTrialList::FindFullName(
-      CallStackProfileMetricsProvider::kFieldTrialName);
-  return group_name ==
-      CallStackProfileMetricsProvider::kReportProfilesGroupName;
+  return base::FeatureList::IsEnabled(kEnableReporting);
 }
 
 }  // namespace metrics