Factor a scheduler object out of MetricsService.

chrome/browser/metrics/metrics_service.cc

Index: chrome/browser/metrics/metrics_service.cc
diff --git a/chrome/browser/metrics/metrics_service.cc b/chrome/browser/metrics/metrics_service.cc
index cfe83f201e1b60fdd688928b527eb657ee146527..9154d9e2a5484f2129dce5c3ebfd26467c71ef02 100644
--- a/chrome/browser/metrics/metrics_service.cc
+++ b/chrome/browser/metrics/metrics_service.cc
@@ -170,6 +170,7 @@
 #include "chrome/browser/load_notification_details.h"
 #include "chrome/browser/metrics/histogram_synchronizer.h"
 #include "chrome/browser/metrics/metrics_log.h"
+#include "chrome/browser/metrics/metrics_reporting_scheduler.h"
 #include "chrome/browser/prefs/pref_service.h"
 #include "chrome/browser/prefs/scoped_user_pref_update.h"
 #include "chrome/browser/profiles/profile.h"
@@ -183,7 +184,6 @@
 #include "content/browser/renderer_host/render_process_host.h"
 #include "content/common/child_process_info.h"
 #include "content/common/notification_service.h"
-#include "libxml/xmlwriter.h"
 #include "webkit/plugins/npapi/plugin_list.h"
 #include "webkit/plugins/npapi/webplugininfo.h"
 
@@ -214,15 +214,15 @@ void MakeStoreStatusHistogram(MetricsService::LogStoreStatus status) {
 }  // namespace
 
 using base::Time;
-using base::TimeDelta;
 
 // Check to see that we're being called on only one thread.
 static bool IsSingleThreaded();
 
 static const char kMetricsType[] = "application/vnd.mozilla.metrics.bz2";
 
-// The delay, in seconds, after startup before sending the first log message.
-static const int kInitialInterlogDuration = 60;  // one minute
+// The delay, in seconds, after starting recording before doing expensive
+// initialization work.
+static const int kInitializationDelaySeconds = 30;
 
 // This specifies the amount of time to wait for all renderers to send their
 // data.
@@ -237,28 +237,6 @@ static const int kEventLimit = 2400;
 // limit is exceeded.
 static const int kUploadLogAvoidRetransmitSize = 50000;
 
-// When we have logs from previous Chrome sessions to send, how long should we
-// delay (in seconds) between each log transmission.
-static const int kUnsentLogDelay = 15;  // 15 seconds
-
-// Minimum time a log typically exists before sending, in seconds.
-// This number is supplied by the server, but until we parse it out of a server
-// response, we use this duration to specify how long we should wait before
-// sending the next log.  If the channel is busy, such as when there is a
-// failure during an attempt to transmit a previous log, then a log may wait
-// (and continue to accrue new log entries) for a much greater period of time.
-static const int kMinSecondsPerLog = 30 * 60;  // Thirty minutes.
-
-// When we don't succeed at transmitting a log to a server, we progressively
-// wait longer and longer before sending the next log.  This backoff process
-// help reduce load on the server, and makes the amount of backoff vary between
-// clients so that a collision (server overload?) on retransmit is less likely.
-// The following is the constant we use to expand that inter-log duration.
-static const double kBackoff = 1.1;
-// We limit the maximum backoff to be no greater than some multiple of the
-// default kMinSecondsPerLog.  The following is that maximum ratio.
-static const int kMaxBackoff = 10;
-
 // Interval, in seconds, between state saves.
 static const int kSaveStateInterval = 5 * 60;  // five minutes
 
@@ -437,15 +415,15 @@ void MetricsService::DiscardOldStabilityStats(PrefService* local_state) {
 MetricsService::MetricsService()
     : recording_active_(false),
       reporting_active_(false),
-      server_permits_upload_(true),
       state_(INITIALIZED),
       current_fetch_(NULL),
       idle_since_last_transmission_(false),
       next_window_id_(0),
       ALLOW_THIS_IN_INITIALIZER_LIST(log_sender_factory_(this)),
       ALLOW_THIS_IN_INITIALIZER_LIST(state_saver_factory_(this)),
-      interlog_duration_(TimeDelta::FromSeconds(kInitialInterlogDuration)),
-      timer_pending_(false) {
+      ALLOW_THIS_IN_INITIALIZER_LIST(scheduler_(
+          new MetricsReportingScheduler(this))),
+      waiting_for_asynchronus_reporting_step_(false) {
   DCHECK(IsSingleThreaded());
   InitializeMetricsState();
 }
@@ -514,7 +492,7 @@ void MetricsService::SetReporting(bool enable) {
   if (reporting_active_ != enable) {
     reporting_active_ = enable;
     if (reporting_active_)
-      StartLogTransmissionTimer();
+      scheduler_->Start();
   }
 }
 
@@ -650,7 +628,7 @@ void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) {
   // case, the log transmissions should have stopped.  Here we start them up
   // again.
   if (!in_idle && idle_since_last_transmission_)
-    StartLogTransmissionTimer();
+    scheduler_->Start();
   idle_since_last_transmission_ = in_idle;
 }
 
@@ -664,7 +642,7 @@ void MetricsService::RecordCompletedSessionEnd() {
   RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
 }
 
-void MetricsService:: RecordBreakpadRegistration(bool success) {
+void MetricsService::RecordBreakpadRegistration(bool success) {
   if (!success)
     IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
   else
@@ -839,7 +817,7 @@ void MetricsService::StartRecording() {
     // thread.
     g_browser_process->file_thread()->message_loop()->PostDelayedTask(FROM_HERE,
         new InitTask(MessageLoop::current()),
-        kInitialInterlogDuration * 1000 / 2);
+        kInitializationDelaySeconds * 1000);
   }
 }
 
@@ -906,10 +884,6 @@ void MetricsService::PushPendingLogsToUnsentLists() {
 }
 
 void MetricsService::PushPendingLogTextToUnsentOngoingLogs() {
-  // If UMA response told us not to upload, there's no need to save the pending
-  // log.  It wasn't supposed to be uploaded anyway.
-  if (!server_permits_upload_)
-    return;
   if (compressed_log_.length() >
       static_cast<size_t>(kUploadLogAvoidRetransmitSize)) {
     UMA_HISTOGRAM_COUNTS("UMA.Large Accumulated Log Not Persisted",
@@ -922,41 +896,16 @@ void MetricsService::PushPendingLogTextToUnsentOngoingLogs() {
 //------------------------------------------------------------------------------
 // Transmission of logs methods
 
-void MetricsService::StartLogTransmissionTimer() {
-  // If we're not reporting, there's no point in starting a log transmission
-  // timer.
-  if (!reporting_active())
-    return;
-
-  if (!current_log_)
-    return;  // Recorder is shutdown.
-
-  // If there is already a timer running, we leave it running.
-  // If timer_pending is true because the fetch is waiting for a response,
-  // we return for now and let the response handler start the timer.
-  if (timer_pending_)
-    return;
+void MetricsService::StartScheduledUpload() {
+  DCHECK(IsSingleThreaded());
 
-  // Before starting the timer, set timer_pending_ to true.
-  timer_pending_ = true;
+  waiting_for_asynchronus_reporting_step_ = true;

[jar (doing other things), 2011/04/16 02:03:13]

If this is part of the timer scheduling, it should be located exclusively in the
TimerScheduling instance.

Note how the old code is more readable in lines 937-941.  We check... bail... or
set the value.

If this value is checked remotely (ilke line 937) we should be able to at least
DCHECK_FALSE(waiting_for_asynchronous_reporting_step_) before we set the value.

[stuartmorgan, 2011/04/18 17:03:00]

It's not, it's for debugging (see my response to your comment in the header).
This method is replacing LogTransmissionTimerDone. 937-941 is part of a method
that doesn't exist any more, the diff algorithm just got confused by the blank
lines they share.
Done.

(FWIW, I'd be fine with eliminating the variable, since DCHECKING a bool just to
make sure nobody accidentally calls an internal method seems like overkill to
me. I was just trying to keep as much of the old behavior as possible when it
wasn't directly related to the refactoring.)

 
   // Right before the UMA transmission gets started, there's one more thing we'd
   // like to record: the histogram of memory usage, so we spawn a task to
-  // collect histograms from all the renderers and when that task is finished,
-  // it will call OnHistogramSynchronizationDone to continue processing.
-  MessageLoop::current()->PostDelayedTask(FROM_HERE,
-      log_sender_factory_.
-          NewRunnableMethod(&MetricsService::LogTransmissionTimerDone),
-      interlog_duration_.InMilliseconds());
-}
-
-void MetricsService::LogTransmissionTimerDone() {
-  DCHECK(IsSingleThreaded());
-
-  // HistogramSynchronizer will Collect histograms from all renderers and it
-  // will call OnHistogramSynchronizationDone (if wait time elapses before it
-  // heard from all renderers, then also it will call
-  // OnHistogramSynchronizationDone).
+  // collect histograms from all the renderers. When finished (or if wait time
+  // elapses before it hears from all renderers), it will call
+  // OnHistogramSynchronizationDone.
 
   // Create a callback_task for OnHistogramSynchronizationDone.
   Task* callback_task = log_sender_factory_.NewRunnableMethod(
@@ -978,53 +927,38 @@ void MetricsService::LogTransmissionTimerDone() {
 void MetricsService::OnHistogramSynchronizationDone() {
   DCHECK(IsSingleThreaded());
 
-  // This function should only be called via timer, so timer_pending_
-  // should be true.
-  DCHECK(timer_pending_);
-  timer_pending_ = false;
+  // This function should only be called as the callback from an ansynchronous
+  // step.
+  DCHECK(waiting_for_asynchronus_reporting_step_);
+  waiting_for_asynchronus_reporting_step_ = false;

[jar (doing other things), 2011/04/16 02:03:13]

If you move this line down to line 944, then you wouldn't need to have line 941
to set it back to true.

[stuartmorgan, 2011/04/18 17:03:00]

Done.

 
+  // If somehow there is a fetch in progress, we return setting
+  // waiting_for_asynchronus_reporting_step_ back to true and hope things work
+  // out. The scheduler isn't informed since if this happens, the scheduler
+  // will get a response from the upload.
   DCHECK(!current_fetch_.get());
-
-  // If we're getting no notifications, then the log won't have much in it, and
-  // it's possible the computer is about to go to sleep, so don't upload and
-  // don't restart the transmission timer.
-  if (idle_since_last_transmission_)
-    return;
-
-  // If somehow there is a fetch in progress, we return setting timer_pending_
-  // to true and hope things work out.
   if (current_fetch_.get()) {
-    timer_pending_ = true;
+    waiting_for_asynchronus_reporting_step_ = true;
     return;
   }
 
-  // If uploads are forbidden by UMA response, there's no point in keeping
-  // the current_log_, and the more often we delete it, the less likely it is
-  // to expand forever.
-  if (!server_permits_upload_ && current_log_) {
-    StopRecording(NULL);
-    StartRecording();
+  // If we're getting no notifications, then the log won't have much in it, and
+  // it's possible the computer is about to go to sleep, so don't upload and
+  // stop the scheduler.
+  // Similarly, if logs should no longer be uploaded, stop here.
+  if (idle_since_last_transmission_ ||
+      !recording_active() || !reporting_active()) {
+    scheduler_->Stop();

[jar (doing other things), 2011/04/16 02:03:13]

Stop() appears to be very permanent.  This seems like it will shut off all UMA
uploads as soon as we've been idle since last transmission.  What will then
cause transmission to re Start()?

[stuartmorgan, 2011/04/18 17:03:00]

The observer calls Start() (just as it used to call StartLogTransmissionTimer).
I haven't actually changed the behavior here, I've just made it more explicit.
In the old code early returns sometimes called StartLogTransmissionTimer, and
sometimes just returned; the latter had the effect of stopping the timer cycle,
but it was much less obvious. I've made it so that the behavior is clear to a
reader (and also much harder for someone to do accidentally), without actually
changing the effect.

+    scheduler_->UploadCancelled();
+    return;
   }
 
-  if (!current_log_)
-    return;  // Logging was disabled.
-  if (!reporting_active())
-    return;  // Don't do work if we're not going to send anything now.
-
   MakePendingLog();
 
   // MakePendingLog should have put something in the pending log, if it didn't,
-  // we start the timer again, return and hope things work out.
+  // we skip this upload and hope things work out next time.
   if (!pending_log()) {
-    StartLogTransmissionTimer();
-    return;
-  }
-
-  // If we're not supposed to upload any UMA data because the response said so,
-  // cancel the upload at this point, but start the timer.
-  if (!ServerPermitsTransmission()) {
-    DiscardPendingLog();
-    StartLogTransmissionTimer();
+    scheduler_->UploadCancelled();
     return;
   }
 
@@ -1033,17 +967,15 @@ void MetricsService::OnHistogramSynchronizationDone() {
   if (!current_fetch_.get()) {
     // Compression failed, and log discarded :-/.
     DiscardPendingLog();
-    StartLogTransmissionTimer();  // Maybe we'll do better next time
+    scheduler_->UploadCancelled();
     // TODO(jar): If compression failed, we should have created a tiny log and
     // compressed that, so that we can signal that we're losing logs.
     return;
   }
 
-  DCHECK(!timer_pending_);
+  DCHECK(!waiting_for_asynchronus_reporting_step_);
 
-  // The URL fetch is a like timer in that after a while we get called back
-  // so we set timer_pending_ true just as we start the url fetch.
-  timer_pending_ = true;
+  waiting_for_asynchronus_reporting_step_ = true;
   current_fetch_->Start();
 
   HandleIdleSinceLastTransmission(true);
@@ -1099,24 +1031,6 @@ void MetricsService::MakePendingLog() {
   DCHECK(pending_log());
 }
 
-bool MetricsService::ServerPermitsTransmission() const {
-  // If the server forbids uploading, we take that to mean it forbids current
-  // logs, but we still send up the inital logs and any old logs.
-  if (server_permits_upload_)
-    return true;
-
-  switch (state_) {
-    case INITIAL_LOG_READY:
-    case SEND_OLD_INITIAL_LOGS:
-    case SENDING_OLD_LOGS:
-      return true;
-
-    case SENDING_CURRENT_LOGS:
-    default:
-      return false;
-  }
-}
-
 void MetricsService::PrepareInitialLog() {
   DCHECK(state_ == INIT_TASK_DONE);
 
@@ -1335,8 +1249,8 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source,
                                         int response_code,
                                         const ResponseCookies& cookies,
                                         const std::string& data) {
-  DCHECK(timer_pending_);
-  timer_pending_ = false;
+  DCHECK(waiting_for_asynchronus_reporting_step_);
+  waiting_for_asynchronus_reporting_step_ = false;
   DCHECK(current_fetch_.get());
   current_fetch_.reset(NULL);  // We're not allowed to re-use it.
 
@@ -1344,10 +1258,12 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source,
   VLOG(1) << "METRICS RESPONSE CODE: " << response_code
           << " status=" << StatusToString(status);
 
+  bool upload_succeeded = response_code == 200;
+
   // Provide boolean for error recovery (allow us to ignore response_code).
   bool discard_log = false;
 
-  if (response_code != 200 &&
+  if (!upload_succeeded &&
       (compressed_log_.length() >
           static_cast<size_t>(kUploadLogAvoidRetransmitSize))) {
     UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded",
@@ -1359,10 +1275,10 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source,
     discard_log = true;
   }
 
-  if (response_code != 200 && !discard_log) {
+  if (!upload_succeeded && !discard_log) {
     VLOG(1) << "METRICS: transmission attempt returned a failure code: "
             << response_code << ". Verify network connectivity";
-    HandleBadResponseCode();
+    LogBadResponseCode();
   } else {  // Successful receipt (or we are discarding log).
     VLOG(1) << "METRICS RESPONSE DATA: " << data;
     switch (state_) {
@@ -1397,38 +1313,24 @@ void MetricsService::OnURLFetchComplete(const URLFetcher* source,
     if (local_state)
       local_state->ScheduleSavePersistentPrefs();
 
-    // Override usual interlog delay if there are unsent logs to transmit,
-    // otherwise reset back to default.
-    if (unsent_logs()) {
+    if (unsent_logs())
       DCHECK(state_ < SENDING_CURRENT_LOGS);
-      interlog_duration_ = TimeDelta::FromSeconds(kUnsentLogDelay);
-    } else {
-      interlog_duration_ = TimeDelta::FromSeconds(kMinSecondsPerLog);
-    }
   }
 
-  StartLogTransmissionTimer();
+  // Error 400 indicates a problem with the log, not with the server, so
+  // don't consider that a sign that the server is in trouble.
+  bool server_is_healthy = upload_succeeded || response_code == 400;
+
+  scheduler_->UploadFinished(server_is_healthy, unsent_logs());
 }
 
-void MetricsService::HandleBadResponseCode() {
+void MetricsService::LogBadResponseCode() {
   VLOG(1) << "Verify your metrics logs are formatted correctly.  Verify server "
              "is active at " << server_url_;
   if (!pending_log()) {
     VLOG(1) << "METRICS: Recorder shutdown during log transmission.";
   } else {
-    // Send progressively less frequently.
-    DCHECK(kBackoff > 1.0);
-    interlog_duration_ = TimeDelta::FromMicroseconds(
-        static_cast<int64>(kBackoff * interlog_duration_.InMicroseconds()));
-
-    if (kMaxBackoff * TimeDelta::FromSeconds(kMinSecondsPerLog) <
-        interlog_duration_) {
-      interlog_duration_ = kMaxBackoff *
-          TimeDelta::FromSeconds(kMinSecondsPerLog);
-    }
-
-    VLOG(1) << "METRICS: transmission retry being scheduled in "
-            << interlog_duration_.InSeconds() << " seconds for "
+    VLOG(1) << "METRICS: transmission retry being scheduled for "
             << compressed_log_;
   }
 }