Upload UMA data using protocol buffers.

chrome/browser/metrics/metrics_service.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.
 
 //------------------------------------------------------------------------------
 // Description of the life cycle of a instance of MetricsService.
 //
 //  OVERVIEW
 //
 // A MetricsService instance is typically created at application startup.  It
@@ skipping 182 matching lines @@
 #include "chrome/browser/chromeos/cros/cros_library.h"
 #include "chrome/browser/chromeos/external_metrics.h"
 #include "chrome/browser/chromeos/system/statistics_provider.h"
 #endif
 
 using base::Time;
 using content::BrowserThread;
 using content::ChildProcessData;
 using content::PluginService;
 
+namespace {
+
 // Check to see that we're being called on only one thread.
-static bool IsSingleThreaded();
+bool IsSingleThreaded() {
+  static base::PlatformThreadId thread_id = 0;
+  if (!thread_id)
+    thread_id = base::PlatformThread::CurrentId();
+  return base::PlatformThread::CurrentId() == thread_id;
+}
 
-static const char kMetricsType[] = "application/vnd.mozilla.metrics.bz2";
+const char kMetricsTypeXml[] = "application/vnd.mozilla.metrics.bz2";
+// TODO(isherman): What should the MIME type be?
+const char kMetricsTypeProto[] = "application/vnd.chrome.uma";
+
+const char kServerUrlXml[] =
+    "https://clients4.google.com/firefox/metrics/collect";
+// TODO(isherman): Update to a real URL...
+const char kServerUrlProto[] = "http://isherman.mtv.corp.google.com:8888/uma";
 
 // The delay, in seconds, after starting recording before doing expensive
 // initialization work.
-static const int kInitializationDelaySeconds = 30;
+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.
+const int kMaxHistogramGatheringWaitDuration = 60000;  // 60 seconds.
 
 // The maximum number of events in a log uploaded to the UMA server.
-static const int kEventLimit = 2400;
+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;
+const size_t kUploadLogAvoidRetransmitSize = 50000;
 
 // Interval, in minutes, between state saves.
-static const int kSaveStateIntervalMinutes = 5;
+const int kSaveStateIntervalMinutes = 5;
+
+}
 
 // static
 MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ =
     MetricsService::CLEANLY_SHUTDOWN;
 
 // This is used to quickly log stats from child process related notifications in
 // MetricsService::child_stats_buffer_.  The buffer's contents are transferred
 // out when Local State is periodically saved.  The information is then
 // reported to the UMA server on next launch.
 struct MetricsService::ChildProcessStats {
@@ skipping 79 matching lines @@
                                    0);
 #endif  // OS_CHROMEOS
 
   local_state->RegisterDictionaryPref(prefs::kProfileMetrics);
   local_state->RegisterIntegerPref(prefs::kNumBookmarksOnBookmarkBar, 0);
   local_state->RegisterIntegerPref(prefs::kNumFoldersOnBookmarkBar, 0);
   local_state->RegisterIntegerPref(prefs::kNumBookmarksInOtherBookmarkFolder,
                                    0);
   local_state->RegisterIntegerPref(prefs::kNumFoldersInOtherBookmarkFolder, 0);
   local_state->RegisterIntegerPref(prefs::kNumKeywords, 0);
-  local_state->RegisterListPref(prefs::kMetricsInitialLogs);
-  local_state->RegisterListPref(prefs::kMetricsOngoingLogs);
+  local_state->RegisterListPref(prefs::kMetricsInitialLogsXml);
+  local_state->RegisterListPref(prefs::kMetricsOngoingLogsXml);
+  local_state->RegisterListPref(prefs::kMetricsInitialLogsProto);
+  local_state->RegisterListPref(prefs::kMetricsOngoingLogsProto);
 
   local_state->RegisterInt64Pref(prefs::kUninstallMetricsPageLoadCount, 0);
   local_state->RegisterInt64Pref(prefs::kUninstallLaunchCount, 0);
   local_state->RegisterInt64Pref(prefs::kUninstallMetricsInstallDate, 0);
   local_state->RegisterInt64Pref(prefs::kUninstallMetricsUptimeSec, 0);
   local_state->RegisterInt64Pref(prefs::kUninstallLastLaunchTimeSec, 0);
   local_state->RegisterInt64Pref(prefs::kUninstallLastObservedRunTimeSec, 0);
 }
 
 // static
@@ skipping 12 matching lines @@
 
   local_state->SetInteger(prefs::kStabilityPageLoadCount, 0);
   local_state->SetInteger(prefs::kStabilityRendererCrashCount, 0);
   local_state->SetInteger(prefs::kStabilityRendererHangCount, 0);
 
   local_state->SetInt64(prefs::kStabilityLaunchTimeSec, 0);
   local_state->SetInt64(prefs::kStabilityLastTimestampSec, 0);
 
   local_state->ClearPref(prefs::kStabilityPluginStats);
 
-  local_state->ClearPref(prefs::kMetricsInitialLogs);
-  local_state->ClearPref(prefs::kMetricsOngoingLogs);
+  local_state->ClearPref(prefs::kMetricsInitialLogsXml);
+  local_state->ClearPref(prefs::kMetricsOngoingLogsXml);
+  local_state->ClearPref(prefs::kMetricsInitialLogsProto);
+  local_state->ClearPref(prefs::kMetricsOngoingLogsProto);
 }
 
 MetricsService::MetricsService()
     : recording_active_(false),
       reporting_active_(false),
       state_(INITIALIZED),
-      current_fetch_(NULL),
       io_thread_(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)),
       waiting_for_asynchronus_reporting_step_(false) {
   DCHECK(IsSingleThreaded());
   InitializeMetricsState();
 
   base::Closure callback = base::Bind(&MetricsService::StartScheduledUpload,
@@ skipping 238 matching lines @@
 //------------------------------------------------------------------------------
 // private methods
 //------------------------------------------------------------------------------
 
 
 //------------------------------------------------------------------------------
 // Initialization methods
 
 void MetricsService::InitializeMetricsState() {
 #if defined(OS_POSIX)
-  server_url_ = L"https://clients4.google.com/firefox/metrics/collect";
+  server_url_xml_ = ASCIIToUTF16(kServerUrlXml);
+  server_url_proto_ = ASCIIToUTF16(kServerUrlProto);
   network_stats_server_ = "chrome.googleechotest.com";
 #else
   BrowserDistribution* dist = BrowserDistribution::GetDistribution();
-  server_url_ = dist->GetStatsServerURL();
+  server_url_xml_ = dist->GetStatsServerURL();
+  // TODO(isherman): Hmm, do distribution channels sometimes specify other
+  // servers?

[Ilya Sherman, 2012/01/28 08:17:20]

Jim, Ian, do you know how this works and/or whether it's ever used to change the
upload location?  Do we need to add a new URL to the browser distribution info
for protobuf uploads?

+  server_url_proto_ = ASCIIToUTF16(kServerUrlProto);
   network_stats_server_ = dist->GetNetworkStatsServer();
 #endif
 
   PrefService* pref = g_browser_process->local_state();
   DCHECK(pref);
 
   if ((pref->GetInt64(prefs::kStabilityStatsBuildTime)
        != MetricsLog::GetBuildTime()) ||
       (pref->GetString(prefs::kStabilityStatsVersion)
        != MetricsLog::GetVersionString())) {
@@ skipping 186 matching lines @@
   // Adds to ongoing logs.
   log_manager_.current_log()->set_hardware_class(hardware_class_);
 
   // Put incremental data (histogram deltas, and realtime stats deltas) at the
   // end of all log transmissions (initial log handles this separately).
   // RecordIncrementalStabilityElements only exists on the derived
   // MetricsLog class.
   MetricsLog* current_log =
       static_cast<MetricsLog*>(log_manager_.current_log());
   DCHECK(current_log);
-  current_log->RecordIncrementalStabilityElements();
+  current_log->RecordIncrementalStabilityElements(plugins_);
   RecordCurrentHistograms();
 
   log_manager_.StageCurrentLogForUpload();
 }
 
 void MetricsService::PushPendingLogsToPersistentStorage() {
   if (state_ < INITIAL_LOG_READY)
     return;  // We didn't and still don't have time to get plugin list etc.
 
   if (log_manager_.has_staged_log()) {
@@ skipping 74 matching lines @@
       MessageLoop::current(), callback,
       kMaxHistogramGatheringWaitDuration);
 }
 
 void MetricsService::OnHistogramSynchronizationDone() {
   DCHECK(IsSingleThreaded());
 
   // If somehow there is a fetch in progress, we return 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())
+  DCHECK(!current_fetch_xml_.get());
+  DCHECK(!current_fetch_proto_.get());
+  if (current_fetch_xml_.get() || current_fetch_proto_.get())
     return;
 
   // 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;
 
   // 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();
     scheduler_->UploadCancelled();
     return;
   }
 
   MakeStagedLog();
 
   // MakeStagedLog should have prepared log text; if it didn't, skip this
   // upload and hope things work out next time.
-  if (log_manager_.staged_log_text().empty()) {
+  if (log_manager_.staged_log_text_xml().empty()) {
     scheduler_->UploadCancelled();
     return;
   }
 
   PrepareFetchWithStagedLog();
 
-  if (!current_fetch_.get()) {
+  if (!current_fetch_xml_.get()) {
+    DCHECK(!current_fetch_proto_.get());
     // Compression failed, and log discarded :-/.
     log_manager_.DiscardStagedLog();
     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(current_fetch_proto_.get());
 
   DCHECK(!waiting_for_asynchronus_reporting_step_);
 
   waiting_for_asynchronus_reporting_step_ = true;
-  current_fetch_->Start();
+  current_fetch_xml_->Start();
+  current_fetch_proto_->Start();
 
   HandleIdleSinceLastTransmission(true);
 }
 
 
 void MetricsService::MakeStagedLog() {
   if (log_manager_.has_staged_log())
     return;
 
   switch (state_) {
@@ skipping 52 matching lines @@
 }
 
 void MetricsService::StoreUnsentLogs() {
   if (state_ < INITIAL_LOG_READY)
     return;  // We never Recalled the prior unsent logs.
 
   log_manager_.PersistUnsentLogs();
 }
 
 void MetricsService::PrepareFetchWithStagedLog() {
-  DCHECK(!log_manager_.staged_log_text().empty());
-  DCHECK(!current_fetch_.get());
+  // Prepare the XML version.
+  DCHECK(!log_manager_.staged_log_text_xml().empty());
+  DCHECK(!current_fetch_xml_.get());
+  current_fetch_xml_.reset(content::URLFetcher::Create(
+      GURL(server_url_xml_), content::URLFetcher::POST, this));
+  current_fetch_xml_->SetRequestContext(
+      g_browser_process->system_request_context());
+  current_fetch_xml_->SetUploadData(kMetricsTypeXml,
+                                log_manager_.staged_log_text_xml());
 
-  current_fetch_.reset(content::URLFetcher::Create(
-      GURL(WideToUTF16(server_url_)), content::URLFetcher::POST, this));
-  current_fetch_->SetRequestContext(
+  // Prepare the protobuf version.
+  DCHECK(!log_manager_.staged_log_text_proto().empty());
+  DCHECK(!current_fetch_proto_.get());
+  current_fetch_proto_.reset(content::URLFetcher::Create(
+      GURL(server_url_proto_), content::URLFetcher::POST, this));
+  current_fetch_proto_->SetRequestContext(
       g_browser_process->system_request_context());
-  current_fetch_->SetUploadData(kMetricsType, log_manager_.staged_log_text());
+  current_fetch_proto_->SetUploadData(kMetricsTypeProto,
+                                      log_manager_.staged_log_text_proto());
 }
 
 static const char* StatusToString(const net::URLRequestStatus& status) {
   switch (status.status()) {
     case net::URLRequestStatus::SUCCESS:
       return "SUCCESS";
 
     case net::URLRequestStatus::IO_PENDING:
       return "IO_PENDING";
 
     case net::URLRequestStatus::HANDLED_EXTERNALLY:
       return "HANDLED_EXTERNALLY";
 
     case net::URLRequestStatus::CANCELED:
       return "CANCELED";
 
     case net::URLRequestStatus::FAILED:
       return "FAILED";
 
     default:
       NOTREACHED();
       return "Unknown";
   }
 }
 
+// We need to wait for two responses: the response to the XML upload, and the
+// response to the protobuf upload.  For now, only the XML upload's response
+// affects decisions like whether to retry the upload, whether to abandon the
+// upload because it is too large, etc.  However, we still need to wait for the
+// protobuf upload, as we cannot reset |current_fetch_proto_| until we have
+// confirmation that the network request was sent; and the easiest way to do
+// that is to wait for the response.  In case the XML upload's response arrives
+// first, we cache that response until the protobuf upload's response also
+// arrives.

[Ilya Sherman, 2012/01/28 08:17:20]

Reviewers: Does this approach (i.e. waiting for both responses, but only
considering the XML response for error handling) sound o.k. while we have both
the XML and protobuf versions of the pipeline running in parallel?

 void MetricsService::OnURLFetchComplete(const content::URLFetcher* source) {
   DCHECK(waiting_for_asynchronus_reporting_step_);
+
+  // We're not allowed to re-use the existing |URLFetcher|s, so free them here.
+  scoped_ptr<content::URLFetcher> s;
+  if (source == current_fetch_xml_.get()) {
+    s.reset(current_fetch_xml_.release());
+
+    // Cache the XML responses, in case we still need to wait for the protobuf
+    // response.
+    response_code_ = source->GetResponseCode();
+    response_status_ = StatusToString(source->GetStatus());
+    source->GetResponseAsString(&response_data_);
+  } else if (source == current_fetch_proto_.get()) {
+    s.reset(current_fetch_proto_.release());
+  } else {
+    NOTREACHED();
+    return;
+  }
+
+  // If we're still waiting for one of the responses, keep waiting...
+  if (current_fetch_xml_.get() || current_fetch_proto_.get())
+    return;
+
+  // We should only be able to reach here once we've received responses to both
+  // the XML and the protobuf requests.  We should always have the response code
+  // available.
+  DCHECK_NE(response_code_, content::URLFetcher::RESPONSE_CODE_INVALID);
   waiting_for_asynchronus_reporting_step_ = false;
-  DCHECK(current_fetch_.get());
-  // We're not allowed to re-use it. Delete it on function exit since we use it.
-  scoped_ptr<content::URLFetcher> s(current_fetch_.release());
+
 
   // Confirm send so that we can move on.
-  VLOG(1) << "METRICS RESPONSE CODE: " << source->GetResponseCode()
-          << " status=" << StatusToString(source->GetStatus());
+  VLOG(1) << "METRICS RESPONSE CODE: " << response_code_
+          << " status=" << response_status_;
 
-  bool upload_succeeded = source->GetResponseCode() == 200;
+  bool upload_succeeded = response_code_ == 200;
 
   // Provide boolean for error recovery (allow us to ignore response_code).
   bool discard_log = false;
 
   if (!upload_succeeded &&
-      (log_manager_.staged_log_text().length() >
-          static_cast<size_t>(kUploadLogAvoidRetransmitSize))) {
-    UMA_HISTOGRAM_COUNTS(
-        "UMA.Large Rejected Log was Discarded",
-        static_cast<int>(log_manager_.staged_log_text().length()));
-    discard_log = true;
-  } else if (source->GetResponseCode() == 400) {
+      log_manager_.staged_log_text_xml().length() >
+          kUploadLogAvoidRetransmitSize) {
+      UMA_HISTOGRAM_COUNTS(
+          "UMA.Large Rejected Log was Discarded",
+          static_cast<int>(log_manager_.staged_log_text_xml().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 (!upload_succeeded && !discard_log) {
     VLOG(1) << "METRICS: transmission attempt returned a failure code: "
-            << source->GetResponseCode() << ". Verify network connectivity";
+            << response_code_ << ". Verify network connectivity";
     LogBadResponseCode();
   } else {  // Successful receipt (or we are discarding log).
-    std::string data;
-    source->GetResponseAsString(&data);
-    VLOG(1) << "METRICS RESPONSE DATA: " << data;
+    VLOG(1) << "METRICS RESPONSE DATA: " << response_data_;
     switch (state_) {
       case INITIAL_LOG_READY:
         state_ = SENDING_OLD_LOGS;
         break;
 
       case SENDING_OLD_LOGS:
         // Store the updated list to disk now that the removed log is uploaded.
         StoreUnsentLogs();
         break;
 
       case SENDING_CURRENT_LOGS:
         break;
 
       default:
         NOTREACHED();
         break;
     }
 
     log_manager_.DiscardStagedLog();
 
     if (log_manager_.has_unsent_logs())
       DCHECK(state_ < SENDING_CURRENT_LOGS);
   }
 
   // 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 || source->GetResponseCode() == 400;
+  bool server_is_healthy = upload_succeeded || response_code_ == 400;
 
   scheduler_->UploadFinished(server_is_healthy,
                              log_manager_.has_unsent_logs());
 
   // Collect network stats if UMA upload succeeded.
   if (server_is_healthy && io_thread_)
     chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread_);
+
+  // Reset the cached response data.
+  response_code_ = content::URLFetcher::RESPONSE_CODE_INVALID;
+  response_data_ = std::string();
+  response_status_ = std::string();
 }
 
 void MetricsService::LogBadResponseCode() {
   VLOG(1) << "Verify your metrics logs are formatted correctly.  Verify server "
-             "is active at " << server_url_;
+             "is active at " << server_url_xml_;
   if (!log_manager_.has_staged_log()) {
     VLOG(1) << "METRICS: Recorder shutdown during log transmission.";
   } else {
     VLOG(1) << "METRICS: transmission retry being scheduled for "
-            << log_manager_.staged_log_text();
+            << log_manager_.staged_log_text_xml();
   }
 }
 
 void MetricsService::LogWindowChange(
     int type,
     const content::NotificationSource& source,
     const content::NotificationDetails& details) {
   int controller_id = -1;
   uintptr_t window_or_tab = source.map_key();
   MetricsLog::WindowEventType window_type;
@@ skipping 351 matching lines @@
 
   RecordPluginChanges(pref);
 }
 
 // static
 bool MetricsService::IsPluginProcess(content::ProcessType type) {
   return (type == content::PROCESS_TYPE_PLUGIN||
           type == content::PROCESS_TYPE_PPAPI_PLUGIN);
 }
 
-static bool IsSingleThreaded() {
-  static base::PlatformThreadId thread_id = 0;
-  if (!thread_id)
-    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
 
 // static
 bool MetricsServiceHelper::IsMetricsReportingEnabled() {
   bool result = false;
   const PrefService* local_state = g_browser_process->local_state();
   if (local_state) {
     const PrefService::Preference* uma_pref =
         local_state->FindPreference(prefs::kMetricsReportingEnabled);
     if (uma_pref) {
       bool success = uma_pref->GetValue()->GetAsBoolean(&result);
       DCHECK(success);
     }
   }
   return result;
 }