Factor a scheduler object out of MetricsService.

chrome/browser/metrics/metrics_service.cc

 // Copyright (c) 2011 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.
 
 //------------------------------------------------------------------------------
 // Description of the life cycle of a instance of MetricsService.
 //
 //  OVERVIEW
 //
 // A MetricsService instance is typically created at application startup.  It
@@ skipping 152 matching lines @@
 #include "base/string_number_conversions.h"
 #include "base/threading/platform_thread.h"
 #include "base/threading/thread.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
 #include "chrome/browser/bookmarks/bookmark_model.h"
 #include "chrome/browser/browser_process.h"
 #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"
 #include "chrome/browser/search_engines/template_url_model.h"
 #include "chrome/browser/ui/browser_list.h"
 #include "chrome/common/child_process_logging.h"
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/guid.h"
 #include "chrome/common/pref_names.h"
 #include "chrome/common/render_messages.h"
 #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"
 
 // TODO(port): port browser_distribution.h.
 #if !defined(OS_POSIX)
 #include "chrome/installer/util/browser_distribution.h"
 #endif
 
 #if defined(OS_CHROMEOS)
 #include "chrome/browser/chromeos/cros/cros_library.h"
@@ skipping 10 matching lines @@
 }
 
 // TODO(ziadh): Remove this when done with experiment.
 void MakeStoreStatusHistogram(MetricsService::LogStoreStatus status) {
   UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogStore2", status,
                             MetricsService::END_STORE_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.
 static const int kMaxHistogramGatheringWaitDuration = 60000;  // 60 seconds.
 
 // The maximum number of events in a log uploaded to the UMA server.
 static const int kEventLimit = 2400;
 
 // If an upload fails, and the transmission was over this byte count, then we
 // will discard the log, and not try to retransmit it.  We also don't persist
 // the log to the prefs for transmission during the next chrome session if this
 // 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
 
 // The number of "initial" logs we're willing to save, and hope to send during
 // a future Chrome session.  Initial logs contain crash stats, and are pretty
 // small.
 static const size_t kMaxInitialLogsPersisted = 20;
 
 // The number of ongoing logs we're willing to save persistently, and hope to
 // send during a this or future sessions.  Note that each log may be pretty
@@ skipping 158 matching lines @@
 
   local_state->ClearPref(prefs::kStabilityPluginStats);
 
   local_state->ClearPref(prefs::kMetricsInitialLogs);
   local_state->ClearPref(prefs::kMetricsOngoingLogs);
 }
 
 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();
 }
 
 MetricsService::~MetricsService() {
   SetRecording(false);
 }
 
 void MetricsService::Start() {
   HandleIdleSinceLastTransmission(false);
@@ skipping 48 matching lines @@
 
 bool MetricsService::recording_active() const {
   DCHECK(IsSingleThreaded());
   return recording_active_;
 }
 
 void MetricsService::SetReporting(bool enable) {
   if (reporting_active_ != enable) {
     reporting_active_ = enable;
     if (reporting_active_)
-      StartLogTransmissionTimer();
+      scheduler_->Start();
   }
 }
 
 bool MetricsService::reporting_active() const {
   DCHECK(IsSingleThreaded());
   return reporting_active_;
 }
 
 // static
 void MetricsService::SetUpNotifications(NotificationRegistrar* registrar,
@@ skipping 115 matching lines @@
 
   if (current_log_)
     DVLOG(1) << "METRICS: NUMBER OF EVENTS = " << current_log_->num_events();
 }
 
 void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) {
   // If there wasn't a lot of action, maybe the computer was asleep, in which
   // 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;
 }
 
 void MetricsService::RecordStartOfSessionEnd() {
   LogCleanShutdown();
   RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false);
 }
 
 void MetricsService::RecordCompletedSessionEnd() {
   LogCleanShutdown();
   RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
 }
 
-void MetricsService:: RecordBreakpadRegistration(bool success) {
+void MetricsService::RecordBreakpadRegistration(bool success) {
   if (!success)
     IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
   else
     IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess);
 }
 
 void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) {
   if (!has_debugger)
     IncrementPrefValue(prefs::kStabilityDebuggerNotPresent);
   else
@@ skipping 154 matching lines @@
   if (state_ == INITIALIZED) {
     // We only need to schedule that run once.
     state_ = INIT_TASK_SCHEDULED;
 
     // Schedules a task on the file thread for execution of slower
     // initialization steps (such as plugin list generation) necessary
     // for sending the initial log.  This avoids blocking the main UI
     // thread.
     g_browser_process->file_thread()->message_loop()->PostDelayedTask(FROM_HERE,
         new InitTask(MessageLoop::current()),
-        kInitialInterlogDuration * 1000 / 2);
+        kInitializationDelaySeconds * 1000);
   }
 }
 
 void MetricsService::StopRecording(MetricsLogBase** log) {
   if (!current_log_)
     return;
 
   current_log_->set_hardware_class(hardware_class_);  // Adds to ongoing logs.
 
   // TODO(jar): Integrate bounds on log recording more consistently, so that we
@@ skipping 46 matching lines @@
   }
   DCHECK(!pending_log());
   StopRecording(&pending_log_);
   PreparePendingLogText();
   PushPendingLogTextToUnsentOngoingLogs();
   DiscardPendingLog();
   StoreUnsentLogs();
 }
 
 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",
                          static_cast<int>(compressed_log_.length()));
     return;
   }
   unsent_ongoing_logs_.push_back(compressed_log_);
 }
 
 //------------------------------------------------------------------------------
 // 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;
+void MetricsService::StartScheduledUpload() {
+  DCHECK(IsSingleThreaded());
 
-  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;
-
-  // 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(
       &MetricsService::OnHistogramSynchronizationDone);
 
   // Set up the callback to task to call after we receive histograms from all
   // renderer processes. Wait time specifies how long to wait before absolutely
   // calling us back on the task.
   HistogramSynchronizer::FetchRendererHistogramsAsynchronously(
       MessageLoop::current(), callback_task,
       kMaxHistogramGatheringWaitDuration);
 
   // Collect WebCore cache information to put into a histogram.
   for (RenderProcessHost::iterator i(RenderProcessHost::AllHostsIterator());
        !i.IsAtEnd(); i.Advance())
     i.GetCurrentValue()->Send(new ViewMsg_GetCacheResourceStats());
 }
 
 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 (current_fetch_.get()) {
+    waiting_for_asynchronus_reporting_step_ = true;
+    return;
+  }
 
   // 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;
+  // 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 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 (!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();
+    scheduler_->UploadCancelled();
     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();
-    return;
-  }
-
   PrepareFetchWithPendingLog();
 
   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);
 }
 
 
 void MetricsService::MakePendingLog() {
   if (pending_log())
     return;
 
@@ skipping 35 matching lines @@
       break;
 
     default:
       NOTREACHED();
       return;
   }
 
   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);
 
   MetricsLog* log = new MetricsLog(client_id_, session_id_);
   log->set_hardware_class(hardware_class_);  // Adds to initial log.
   log->RecordEnvironment(plugins_, profile_dictionary_.get());
 
   // Histograms only get written to current_log_, so setup for the write.
   MetricsLogBase* save_log = current_log_;
   current_log_ = log;
@@ skipping 198 matching lines @@
       return "Unknown";
   }
 }
 
 void MetricsService::OnURLFetchComplete(const URLFetcher* source,
                                         const GURL& url,
                                         const net::URLRequestStatus& status,
                                         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.
 
   // Confirm send so that we can move on.
   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",
                          static_cast<int>(compressed_log_.length()));
     discard_log = true;
   } else if (response_code == 400) {
     // Bad syntax.  Retransmission won't work.
     UMA_HISTOGRAM_COUNTS("UMA.Unacceptable_Log_Discarded", state_);
     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_) {
       case INITIAL_LOG_READY:
         state_ = SEND_OLD_INITIAL_LOGS;
         break;
 
       case SEND_OLD_INITIAL_LOGS:
         DCHECK(!unsent_initial_logs_.empty());
         unsent_initial_logs_.pop_back();
@@ skipping 14 matching lines @@
         break;
     }
 
     DiscardPendingLog();
     // Since we sent a log, make sure our in-memory state is recorded to disk.
     PrefService* local_state = g_browser_process->local_state();
     DCHECK(local_state);
     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_;
   }
 }
 
 void MetricsService::LogWindowChange(NotificationType type,
                                      const NotificationSource& source,
                                      const NotificationDetails& details) {
   int controller_id = -1;
   uintptr_t window_or_tab = source.map_key();
   MetricsLog::WindowEventType window_type;
@@ skipping 297 matching lines @@
     thread_id = base::PlatformThread::CurrentId();
   return base::PlatformThread::CurrentId() == thread_id;
 }
 
 #if defined(OS_CHROMEOS)
 void MetricsService::StartExternalMetrics() {
   external_metrics_ = new chromeos::ExternalMetrics;
   external_metrics_->Start();
 }
 #endif