[Sampling profiler] Skip over samples in the past that we couldn't co…

…llect

Avoids racing to make up lost samples, and the bias resulting from that
behavior, in the case where the sample tasks didn't execute on the
expected schedule. This can happen during system suspend or in cases
of system-wide jank. The correct solution is to skip the samples and
continue sampling at the regular cadence, since the system was not
actively executing in the interim.

Expected impacts:

For the UMA case, reduced bias towards execution immediately following
resume. There will still be some bias towards the first 30 seconds of
execution after resume because the profile scheduling remains unaware
of suspend/resume cycles.

For the tracing case, aligns the sampling exactly to the specified
sampling interval on average. The sampling in the existing implementation
was actually occurring on average at the specified interval plus half
the timer tick interval.

Bug: 876063
Change-Id: I6c0894bc9909131a4632765c6a6acc4678763bdf
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2199918
Commit-Queue: Mike Wittman <wittman@chromium.org>
Reviewed-by: Gabriel Charette <gab@chromium.org>
Reviewed-by: ssid <ssid@chromium.org>
Cr-Commit-Position: refs/heads/master@{#771192}

base/profiler/stack_sampling_profiler.cc

@@ -5,6 +5,7 @@
 #include "base/profiler/stack_sampling_profiler.h"
 
 #include <algorithm>
+#include <cmath>
 #include <map>
 #include <utility>
 
@@ -47,6 +48,36 @@ constexpr WaitableEvent::ResetPolicy kResetPolicy =
 // for referencing the active collection to the SamplingThread.
 const int kNullProfilerId = -1;
 
+TimeTicks GetNextSampleTimeImpl(TimeTicks scheduled_current_sample_time,
+                                TimeDelta sampling_interval,
+                                TimeTicks now) {
+  // Schedule the next sample at the next sampling_interval-aligned time in
+  // the future that's sufficiently far enough from the current sample. In the
+  // general case this will be one sampling_interval from the current
+  // sample. In cases where sample tasks were unable to be executed, such as
+  // during system suspend or bad system-wide jank, we may have missed some
+  // samples. The right thing to do for those cases is to skip the missed
+  // samples since the rest of the systems also wasn't executing.
+
+  // Ensure that the next sample time is at least half a sampling interval
+  // away. This causes the second sample after resume to be taken between 0.5
+  // and 1.5 samples after the first, or 1 sample interval on average. The delay
+  // also serves to provide a grace period in the normal sampling case where the
+  // current sample may be taken slightly later than its scheduled time.
+  const TimeTicks earliest_next_sample_time = now + sampling_interval / 2;
+
+  const TimeDelta minimum_time_delta_to_next_sample =
+      earliest_next_sample_time - scheduled_current_sample_time;
+
+  // The minimum number of sampling intervals required to get from the scheduled
+  // current sample time to the earliest next sample time.
+  const int64_t required_sampling_intervals = static_cast<int64_t>(
+      std::ceil(minimum_time_delta_to_next_sample.InMicrosecondsF() /
+                sampling_interval.InMicroseconds()));
+  return scheduled_current_sample_time +
+         required_sampling_intervals * sampling_interval;
+}
+
 }  // namespace
 
 // StackSamplingProfiler::SamplingThread --------------------------------------
@@ -597,9 +628,9 @@ void StackSamplingProfiler::SamplingThread::RecordSampleTask(
 
   // Schedule the next sample recording if there is one.
   if (++collection->sample_count < collection->params.samples_per_profile) {
-    if (!collection->params.keep_consistent_sampling_interval)
-      collection->next_sample_time = TimeTicks::Now();
-    collection->next_sample_time += collection->params.sampling_interval;
+    collection->next_sample_time = GetNextSampleTimeImpl(
+        collection->next_sample_time, collection->params.sampling_interval,
+        TimeTicks::Now());
     bool success = GetTaskRunnerOnSamplingThread()->PostDelayedTask(
         FROM_HERE,
         BindOnce(&SamplingThread::RecordSampleTask, Unretained(this),
@@ -689,6 +720,15 @@ void StackSamplingProfiler::TestPeer::PerformSamplingThreadIdleShutdown(
   SamplingThread::TestPeer::ShutdownAssumingIdle(simulate_intervening_start);
 }
 
+// static
+TimeTicks StackSamplingProfiler::TestPeer::GetNextSampleTime(
+    TimeTicks scheduled_current_sample_time,
+    TimeDelta sampling_interval,
+    TimeTicks now) {
+  return GetNextSampleTimeImpl(scheduled_current_sample_time, sampling_interval,
+                               now);
+}
+
 StackSamplingProfiler::StackSamplingProfiler(
     SamplingProfilerThreadToken thread_token,
     const SamplingParams& params,

base/profiler/stack_sampling_profiler.h

@@ -72,16 +72,6 @@ class BASE_EXPORT StackSamplingProfiler {
     // Interval between samples during a sampling profile. This is the desired
     // duration from the start of one sample to the start of the next sample.
     TimeDelta sampling_interval = TimeDelta::FromMilliseconds(100);
-
-    // When true, keeps the average sampling interval = |sampling_interval|,
-    // irrespective of how long each sample takes. If a sample takes too long,
-    // keeping the interval constant will lock out the sampled thread. When
-    // false, sample is created with an interval of |sampling_interval|,
-    // excluding the time taken by a sample. The metrics collected will not be
-    // accurate, since sampling could take arbitrary amount of time, but makes
-    // sure that the sampled thread gets at least the interval amount of time to
-    // run between samples.
-    bool keep_consistent_sampling_interval = true;
   };
 
   // Creates a profiler for the specified thread. |native_unwinder| is required
@@ -153,6 +143,11 @@ class BASE_EXPORT StackSamplingProfiler {
     // runs.
     static void PerformSamplingThreadIdleShutdown(
         bool simulate_intervening_start);
+
+    // Provides access to the method computing the next sample time.
+    static TimeTicks GetNextSampleTime(TimeTicks scheduled_current_sample_time,
+                                       TimeDelta sampling_interval,
+                                       TimeTicks now);
   };
 
  private:

base/profiler/stack_sampling_profiler_unittest.cc

@@ -706,6 +706,73 @@ PROFILER_TEST_F(StackSamplingProfilerTest, StopDuringInterSampleInterval) {
       }));
 }
 
+PROFILER_TEST_F(StackSamplingProfilerTest, GetNextSampleTime_NormalExecution) {
+  const auto& GetNextSampleTime =
+      StackSamplingProfiler::TestPeer::GetNextSampleTime;
+
+  const TimeTicks scheduled_current_sample_time = TimeTicks::UnixEpoch();
+  const TimeDelta sampling_interval = TimeDelta::FromMilliseconds(10);
+
+  // When executing the sample at exactly the scheduled time the next sample
+  // should be one interval later.
+  EXPECT_EQ(scheduled_current_sample_time + sampling_interval,
+            GetNextSampleTime(scheduled_current_sample_time, sampling_interval,
+                              scheduled_current_sample_time));
+
+  // When executing the sample less than half an interval after the scheduled
+  // time the next sample also should be one interval later.
+  EXPECT_EQ(scheduled_current_sample_time + sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 0.4 * sampling_interval));
+
+  // When executing the sample less than half an interval before the scheduled
+  // time the next sample also should be one interval later. This is not
+  // expected to occur in practice since delayed tasks never run early.
+  EXPECT_EQ(scheduled_current_sample_time + sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time - 0.4 * sampling_interval));
+}
+
+PROFILER_TEST_F(StackSamplingProfilerTest, GetNextSampleTime_DelayedExecution) {
+  const auto& GetNextSampleTime =
+      StackSamplingProfiler::TestPeer::GetNextSampleTime;
+
+  const TimeTicks scheduled_current_sample_time = TimeTicks::UnixEpoch();
+  const TimeDelta sampling_interval = TimeDelta::FromMilliseconds(10);
+
+  // When executing the sample between 0.5 and 1.5 intervals after the scheduled
+  // time the next sample should be two intervals later.
+  EXPECT_EQ(scheduled_current_sample_time + 2 * sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 0.6 * sampling_interval));
+  EXPECT_EQ(scheduled_current_sample_time + 2 * sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 1.0 * sampling_interval));
+  EXPECT_EQ(scheduled_current_sample_time + 2 * sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 1.4 * sampling_interval));
+
+  // Similarly when executing the sample between 9.5 and 10.5 intervals after
+  // the scheduled time the next sample should be 11 intervals later.
+  EXPECT_EQ(scheduled_current_sample_time + 11 * sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 9.6 * sampling_interval));
+  EXPECT_EQ(scheduled_current_sample_time + 11 * sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 10.0 * sampling_interval));
+  EXPECT_EQ(scheduled_current_sample_time + 11 * sampling_interval,
+            GetNextSampleTime(
+                scheduled_current_sample_time, sampling_interval,
+                scheduled_current_sample_time + 10.4 * sampling_interval));
+}
+
 // Checks that we can destroy the profiler while profiling.
 PROFILER_TEST_F(StackSamplingProfilerTest, DestroyProfilerWhileProfiling) {
   SamplingParams params;

chrome/common/profiler/stack_sampling_configuration.cc

@@ -107,7 +107,6 @@ StackSamplingConfiguration::GetSamplingParams() const {
       base::TimeDelta::FromSeconds(IsBrowserTestModeEnabled() ? 1 : 30);
   params.sampling_interval = base::TimeDelta::FromMilliseconds(100);
   params.samples_per_profile = duration / params.sampling_interval;
-  params.keep_consistent_sampling_interval = true;
 
   return params;
 }

services/tracing/public/cpp/stack_sampling/tracing_sampler_profiler.cc

@@ -640,10 +640,6 @@ void TracingSamplerProfiler::StartTracing(
   base::StackSamplingProfiler::SamplingParams params;
   params.samples_per_profile = std::numeric_limits<int>::max();
   params.sampling_interval = base::TimeDelta::FromMilliseconds(50);
-  // If the sampled thread is stopped for too long for sampling then it is ok to
-  // get next sample at a later point of time. We do not want very accurate
-  // metrics when looking at traces.
-  params.keep_consistent_sampling_interval = false;
 
   auto profile_builder = std::make_unique<TracingProfileBuilder>(
       sampled_thread_token_.id, std::move(trace_writer),