metrics: Use absolute interval-based perf collection

chrome/browser/metrics/perf_provider_chromeos.cc

 // Copyright (c) 2012 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 <string>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/metrics/histogram.h"
 #include "base/rand_util.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/threading/sequenced_worker_pool.h"
 #include "chrome/browser/metrics/perf_provider_chromeos.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_list.h"
 #include "chrome/browser/ui/browser_list_observer.h"
 #include "chrome/common/chrome_switches.h"
 #include "chromeos/dbus/dbus_thread_manager.h"
 #include "chromeos/dbus/debug_daemon_client.h"
 
 namespace {
 
-// Default time in seconds between invocations of perf.
-// This period is roughly 6.5 hours.
-// This is chosen to be relatively prime with the number of seconds in:
-// - one minute (60)
-// - one hour (3600)
-// - one day (86400)
-const size_t kPerfCommandIntervalDefaultSeconds = 23093;
-
-// The first collection interval is different from the interval above. This is
-// because we want to collect the first profile quickly after Chrome is started.
-// If this period is too long, the user will log off and Chrome will be killed
-// before it is triggered. The following 2 variables determine the upper and
-// lower bound on the interval.
-// The reason we do not always want to collect the initial profile after a fixed
-// period is to not over-represent task X in the profile where task X always
-// runs at a fixed period after start-up. By selecting a period randomly between
-// a lower and upper bound, we will hopefully collect a more fair profile.
-const size_t kPerfCommandStartIntervalLowerBoundMinutes = 10;
-
-const size_t kPerfCommandStartIntervalUpperBoundMinutes = 20;
+// Partition time since the epoch into successive intervals of this size. In
+// each interval that hasn't passed, pick a random time to collect a profile.
+// This interval is four hours.
+const size_t kPerfProfilingIntervalSeconds = 14400;

[tipp, 2014/05/16 22:17:26]

How'd you pick four hours?  You should make some effort to tailor this number to
the volume of data we can actually consume.

[tipp, 2014/05/16 22:17:26]

It's clearer to write 4 * 60 *  60.

[Simon Que, 2014/05/20 20:47:35]

Done.

[Simon Que, 2014/05/20 20:47:35]

I'm not sure we have enough information to make that decision right now.
However, I can increase this to something longer to be on the safe side. e.g. 24
hours.

 
 // Default time in seconds perf is run for.
 const size_t kPerfCommandDurationDefaultSeconds = 2;
 
 // Limit the total size of protobufs that can be cached, so they don't take up
 // too much memory. If the size of cached protobufs exceeds this value, stop
 // collecting further perf data. The current value is 4 MB.
 const size_t kCachedPerfDataProtobufSizeThreshold = 4 * 1024 * 1024;
 
 // Enumeration representing success and various failure modes for collecting and
@@ skipping 46 matching lines @@
   // chrome::BrowserListObserver implementation.
   virtual void OnBrowserAdded(Browser* browser) OVERRIDE {
     if (browser->profile()->IsOffTheRecord())
       incognito_launched_ = true;
   }
 
   bool incognito_launched_;
 };
 
 PerfProvider::PerfProvider()
-      : weak_factory_(this) {
-  size_t collection_interval_minutes = base::RandInt(
-      kPerfCommandStartIntervalLowerBoundMinutes,
-      kPerfCommandStartIntervalUpperBoundMinutes);
-  ScheduleCollection(base::TimeDelta::FromMinutes(collection_interval_minutes));
+      : weak_factory_(this),

[Ilya Sherman, 2014/05/16 21:48:57]

The weak pointer factory should always be the last member in the class.  This
ensures that weak pointers are destroyed before other parts of the class start
to be torn down.

[Simon Que, 2014/05/17 03:25:07]

Done.

[Simon Que, 2014/05/19 22:45:01]

Done.

+        login_time_(base::Time::Now()) {
+  ScheduleCollection();
 }
 
 PerfProvider::~PerfProvider() {}
 
-bool PerfProvider::GetPerfData(std::vector<PerfDataProto>* perf_data) {
+bool PerfProvider::GetPerfData(std::vector<SampledProfile>* perf_data) {
   DCHECK(CalledOnValidThread());
   if (cached_perf_data_.empty()) {
     AddToPerfHistogram(NOT_READY_TO_UPLOAD);
     return false;
   }
 
   perf_data->swap(cached_perf_data_);
   cached_perf_data_.clear();
 
   AddToPerfHistogram(SUCCESS);
   return true;
 }
 
-void PerfProvider::ScheduleCollection(const base::TimeDelta& interval) {
+void PerfProvider::ScheduleCollection() {
   DCHECK(CalledOnValidThread());
   if (timer_.IsRunning())
     return;
 
+  // Determine the start of the current interval, which is a multiple of
+  // |kPerfProfilingIntervalSeconds| since the epoch.
+  base::Time now = base::Time::Now();
+  base::Time epoch = base::Time::UnixEpoch();
+  int64 seconds_since_epoch = (now - epoch).InSeconds();

[tipp, 2014/05/17 04:18:29]

How about milliseconds everywhere instead of seconds.  That'll be consistent
with your proto units, and it feels a little weird to align the start time to
such a large unit.

[Simon Que, 2014/05/19 18:37:12]

Will do.

+  int64 interval_start_time_s = seconds_since_epoch -
+      (seconds_since_epoch % kPerfProfilingIntervalSeconds);
+
+  // Pick a random time in the current interval.  If it has already passed, pick
+  // the same time in the next interval.

[Ilya Sherman, 2014/05/16 21:48:57]

So, the next interval might have two random times sampled from it?  I'd suggest
using two timers: One that fires every 4 hours to schedule a collection, and one
that fires at some point within the four-hour window to actually perform the
collection.  Alternately, if you prefer to have just one timer, I'd use
something other than the epoch as the base time -- perhaps the time at which
this class was constructed?

[Simon Que, 2014/05/19 18:37:12]

Yes, using the time of login / initialization would be a good alternative.

If the randomly selected time is already past (and it would only be slightly
past, due to the time it takes to execute the computations), I think we could
just run the collection at the current time. The distribution would only
slightly deviate from even across time.

How does that sound?

+  int64 scheduled_time_s = interval_start_time_s +
+                           base::RandGenerator(kPerfProfilingIntervalSeconds);

[tipp, 2014/05/16 22:17:26]

You want repeated calls to ScheduleCollection to be determinstic (e.g., across
reboots).

So I think you need to seed a rand with two things:
1) a machine-specific identifier (so different machines will get sampled at
different times)
2) the start time of the period

[Simon Que, 2014/05/17 03:46:27]

I'm not sure what your first sentence means. Shouldn't we want it to be as
random and non-deterministic as possible?

That said, I think that seeding with start time since the epoch + machine
specific identifier is fine, but just the start time by itself should be good
enough too, right?

[tipp, 2014/05/17 04:18:29]

You want it to be deterministically random.  For example, suppose the start of
your interval is at time 0, and ScheduleCollection says we should do a
collection at time 17.  Then at time 22 we reboot, and ScheduleCollection gets
called again.  You want ScheduleCollection to know that the collection time (17)
for this machine+interval has already passed.  Otherwise, you'll end up with a
bias toward machines which reboot often.

[Simon Que, 2014/05/19 22:45:01]

Why can't we seed the random generator using the time since epoch (different
each time boot up / login)? In your example, ScheduleCollection will choose 17,
the user reboots, and ScheduleCollection will choose a time other than 17.

+  if (scheduled_time_s < seconds_since_epoch) {
+    scheduled_time_s += kPerfProfilingIntervalSeconds;
+  }
+
+  base::TimeDelta interval =
+      base::TimeDelta::FromSeconds(scheduled_time_s - seconds_since_epoch);
   timer_.Start(FROM_HERE, interval, this,
                &PerfProvider::CollectIfNecessaryAndReschedule);
 }
 
 void PerfProvider::CollectIfNecessary() {
   DCHECK(CalledOnValidThread());
 
   // 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;
@@ skipping 22 matching lines @@
       kPerfCommandDurationDefaultSeconds);
 
   client->GetPerfData(collection_duration.InSeconds(),
                       base::Bind(&PerfProvider::ParseProtoIfValid,
                                  weak_factory_.GetWeakPtr(),
                                  base::Passed(&incognito_observer)));
 }
 
 void PerfProvider::CollectIfNecessaryAndReschedule() {
   CollectIfNecessary();
-  ScheduleCollection(
-      base::TimeDelta::FromSeconds(kPerfCommandIntervalDefaultSeconds));
+  ScheduleCollection();
 }
 
 void PerfProvider::ParseProtoIfValid(
     scoped_ptr<WindowedIncognitoObserver> incognito_observer,
     const std::vector<uint8>& data) {
   DCHECK(CalledOnValidThread());
 
   if (incognito_observer->incognito_launched()) {
     AddToPerfHistogram(INCOGNITO_LAUNCHED);
     return;
   }
 
   PerfDataProto perf_data_proto;
   if (!perf_data_proto.ParseFromArray(data.data(), data.size())) {
     AddToPerfHistogram(PROTOBUF_NOT_PARSED);
     return;
   }
 
-  // Append a new PerfDataProto to the |cached_perf_data_| vector and swap in
-  // the contents.
+  // Populate a profile collection protobuf with the collected perf data and
+  // extra metadata.
   cached_perf_data_.resize(cached_perf_data_.size() + 1);
-  cached_perf_data_.back().Swap(&perf_data_proto);
+  SampledProfile& collection_data = cached_perf_data_.back();
+  collection_data.set_trigger_event(SampledProfile::PERIODIC_COLLECTION);
+  collection_data.set_ms_after_boot(perf_data_proto.timestamp_sec());
+  collection_data.
+      set_ms_after_login((base::Time::Now() - login_time_).InSeconds());

[Ilya Sherman, 2014/05/16 21:48:57]

The field names for the time fields claim the units are milliseconds, but here
you're logging a time delta measured in seconds.  Please decide which units you
want, and either fix the field names or the logging.

[Simon Que, 2014/05/17 03:25:07]

Done.

+  *collection_data.mutable_perf_data() = perf_data_proto;
 }
 
 }  // namespace metrics