metrics: Add random delays to perf collection

When collecting upon resume from suspend or session restore, don't always
collect right away. Introduce a random delay before collecting.

BUG=chromium:358778
TEST=Do the following:
- Add logging to ParseProtoIfValid().
- Set kResumeSamplingFactor=1 and kRestoreSessionSamplingFactor=1. This makes
  collection happen 100% of the time.
- Set kPerfProfilingIntervalMs=20000. This makes the periodic collection happen once every 20-second interval.
- Trigger both types of collections, resume and restore:
  = Suspend and resume the system.
  = Open some tabs in ChromeOS, log out of Chrome, and then log back in so that
    the session is restored.
- Should see the logging trace displayed in /var/log/ui/ui.LATEST after a
  random delay.
- Should also see the periodic collections take place.
  = Open an incognito window. It should continue to attempt to collect. (Add a trace to ScheduleIntervalCollection to see that this is the case).
Signed-off-by: Simon Que <sque@chromium.org>

Review URL: https://codereview.chromium.org/364913007

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@283674 0039d316-1c4b-4281-b951-d872f2087c98

chrome/browser/metrics/perf_provider_chromeos.cc

@@ -54,6 +54,16 @@ const int kRestoreSessionSamplingFactor = 10;
 // much time between collections. The current value is 30 seconds.
 const int kMinIntervalBetweenSessionRestoreCollectionsMs = 30 * 1000;
 
+// If collecting after a resume, add a random delay before collecting. The delay
+// should be randomly selected between 0 and this value. Currently the value is
+// equal to 5 seconds.
+const int kMaxResumeCollectionDelayMs = 5 * 1000;
+
+// If collecting after a session restore, add a random delay before collecting.
+// The delay should be randomly selected between 0 and this value. Currently the
+// value is equal to 10 seconds.
+const int kMaxRestoreSessionCollectionDelayMs = 10 * 1000;
+
 // Enumeration representing success and various failure modes for collecting and
 // sending perf data.
 enum GetPerfDataOutcome {
@@ -190,14 +200,20 @@ void PerfProvider::SuspendDone(const base::TimeDelta& sleep_duration) {
   if (base::RandGenerator(kResumeSamplingFactor) != 0)
     return;
 
-  // Fill out a SampledProfile protobuf that will contain the collected data.
-  scoped_ptr<SampledProfile> sampled_profile(new SampledProfile);
-  sampled_profile->set_trigger_event(SampledProfile::RESUME_FROM_SUSPEND);
-  sampled_profile->set_suspend_duration_ms(sleep_duration.InMilliseconds());
-  // TODO(sque): Vary the time after resume at which to collect a profile.
-  // http://crbug.com/358778.
-  sampled_profile->set_ms_after_resume(0);
-  CollectIfNecessary(sampled_profile.Pass());
+  // Override any existing profiling.
+  if (timer_.IsRunning())
+    timer_.Stop();
+
+  // Randomly pick a delay before doing the collection.
+  base::TimeDelta collection_delay =
+      base::TimeDelta::FromMilliseconds(
+          base::RandGenerator(kMaxResumeCollectionDelayMs));
+  timer_.Start(FROM_HERE,
+               collection_delay,
+               base::Bind(&PerfProvider::CollectPerfDataAfterResume,
+                          weak_factory_.GetWeakPtr(),
+                          sleep_duration,
+                          collection_delay));
 }
 
 void PerfProvider::Observe(int type,
@@ -206,6 +222,10 @@ void PerfProvider::Observe(int type,
   // Only handle session restore notifications.
   DCHECK_EQ(type, chrome::NOTIFICATION_SESSION_RESTORE_DONE);
 
+  // Do not collect a profile unless logged in as a normal user.
+  if (!IsNormalUserLoggedIn())
+    return;
+
   // Collect a profile only 1/|kRestoreSessionSamplingFactor| of the time, to
   // avoid collecting too much data and potentially causing UI latency.
   if (base::RandGenerator(kRestoreSessionSamplingFactor) != 0)
@@ -223,21 +243,25 @@ void PerfProvider::Observe(int type,
     return;
   }
 
-  // Fill out a SampledProfile protobuf that will contain the collected data.
-  scoped_ptr<SampledProfile> sampled_profile(new SampledProfile);
-  sampled_profile->set_trigger_event(SampledProfile::RESTORE_SESSION);
-  // TODO(sque): Vary the time after restore at which to collect a profile,
-  // and find a way to determine the number of tabs restored.
-  // http://crbug.com/358778.
-  sampled_profile->set_ms_after_restore(0);
+  // Stop any existing scheduled collection.
+  if (timer_.IsRunning())
+    timer_.Stop();
 
-  CollectIfNecessary(sampled_profile.Pass());
-  last_session_restore_collection_time_ = base::TimeTicks::Now();
+  // Randomly pick a delay before doing the collection.
+  base::TimeDelta collection_delay =
+      base::TimeDelta::FromMilliseconds(
+          base::RandGenerator(kMaxRestoreSessionCollectionDelayMs));
+  timer_.Start(
+      FROM_HERE,
+      collection_delay,
+      base::Bind(&PerfProvider::CollectPerfDataAfterSessionRestore,
+                 weak_factory_.GetWeakPtr(),
+                 collection_delay));
 }
 
 void PerfProvider::OnUserLoggedIn() {
   login_time_ = base::TimeTicks::Now();
-  ScheduleCollection();
+  ScheduleIntervalCollection();
 }
 
 void PerfProvider::Deactivate() {
@@ -245,7 +269,7 @@ void PerfProvider::Deactivate() {
   timer_.Stop();
 }
 
-void PerfProvider::ScheduleCollection() {
+void PerfProvider::ScheduleIntervalCollection() {
   DCHECK(CalledOnValidThread());
   if (timer_.IsRunning())
     return;
@@ -274,6 +298,12 @@ void PerfProvider::CollectIfNecessary(
     scoped_ptr<SampledProfile> sampled_profile) {
   DCHECK(CalledOnValidThread());
 
+  // Schedule another interval collection. This call makes sense regardless of
+  // whether or not the current collection was interval-triggered. If it had
+  // been another type of trigger event, the interval timer would have been
+  // halted, so it makes sense to reschedule a new interval collection.
+  ScheduleIntervalCollection();
+
   // Do not collect further data if we've already collected a substantial amount
   // of data, as indicated by |kCachedPerfDataProtobufSizeThreshold|.
   size_t cached_perf_data_size = 0;
@@ -313,7 +343,29 @@ void PerfProvider::DoPeriodicCollection() {
   sampled_profile->set_trigger_event(SampledProfile::PERIODIC_COLLECTION);
 
   CollectIfNecessary(sampled_profile.Pass());
-  ScheduleCollection();
+}
+
+void PerfProvider::CollectPerfDataAfterResume(
+    const base::TimeDelta& sleep_duration,
+    const base::TimeDelta& time_after_resume) {
+  // Fill out a SampledProfile protobuf that will contain the collected data.
+  scoped_ptr<SampledProfile> sampled_profile(new SampledProfile);
+  sampled_profile->set_trigger_event(SampledProfile::RESUME_FROM_SUSPEND);
+  sampled_profile->set_suspend_duration_ms(sleep_duration.InMilliseconds());
+  sampled_profile->set_ms_after_resume(time_after_resume.InMilliseconds());
+
+  CollectIfNecessary(sampled_profile.Pass());
+}
+
+void PerfProvider::CollectPerfDataAfterSessionRestore(
+    const base::TimeDelta& time_after_restore) {
+  // Fill out a SampledProfile protobuf that will contain the collected data.
+  scoped_ptr<SampledProfile> sampled_profile(new SampledProfile);
+  sampled_profile->set_trigger_event(SampledProfile::RESTORE_SESSION);
+  sampled_profile->set_ms_after_restore(time_after_restore.InMilliseconds());
+
+  CollectIfNecessary(sampled_profile.Pass());
+  last_session_restore_collection_time_ = base::TimeTicks::Now();
 }
 
 void PerfProvider::ParseProtoIfValid(

chrome/browser/metrics/perf_provider_chromeos.h

@@ -75,7 +75,7 @@ class PerfProvider : public base::NonThreadSafe,
   // Selects a random time in the upcoming profiling interval that begins at
   // |next_profiling_interval_start_|. Schedules |timer_| to invoke
   // DoPeriodicCollection() when that time comes.
-  void ScheduleCollection();
+  void ScheduleIntervalCollection();
 
   // Collects perf data for a given |trigger_event|. Calls perf via the ChromeOS
   // debug daemon's dbus interface.
@@ -85,6 +85,17 @@ class PerfProvider : public base::NonThreadSafe,
   // reschedules it to be collected again.
   void DoPeriodicCollection();
 
+  // Collects perf data after a resume. |sleep_duration| is the duration the
+  // system was suspended before resuming. |time_after_resume_ms| is how long
+  // ago the system resumed.
+  void CollectPerfDataAfterResume(const base::TimeDelta& sleep_duration,
+                                  const base::TimeDelta& time_after_resume);
+
+  // Collects perf data after a session restore. |time_after_restore| is how
+  // long ago the session restore started.
+  void CollectPerfDataAfterSessionRestore(
+      const base::TimeDelta& time_after_restore);
+
   // Parses a perf data protobuf from the |data| passed in only if the
   // |incognito_observer| indicates that no incognito window had been opened
   // during the profile collection period.