Measure and log the latency of VariationsService requests.

chrome/browser/metrics/variations/variations_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.
 
 #include "chrome/browser/metrics/variations/variations_service.h"
 
 #include <set>
 
 #include "base/base64.h"
 #include "base/build_time.h"
@@ skipping 78 matching lines @@
 GURL GetVariationsServerURL() {
   std::string server_url(CommandLine::ForCurrentProcess()->GetSwitchValueASCII(
       switches::kVariationsServerURL));
   if (server_url.empty())
     server_url = kDefaultVariationsServerURL;
   GURL url_as_gurl = GURL(server_url);
   DCHECK(url_as_gurl.is_valid());
   return url_as_gurl;
 }
 
+// Logs |latency| in the time histogram named |name|.
+void LogRequestLatency(const char* name, base::TimeDelta latency) {
+  UMA_HISTOGRAM_CUSTOM_TIMES(name,

[Ilya Sherman, 2012/10/02 21:09:33]

This won't work.  The name passed to any of the UMA_HISTOGRAM macros needs to be
a fixed string during the entire run of Chrome, as the macro internally caches
the histogram in a static variable.

[Ilya Sherman, 2012/10/02 21:09:33]

nit: Why do we need custom times for this histogram, rather than using one of
MEDIUM_ or LONG_TIMES?

[SteveT, 2012/10/03 19:51:34]

Darn, okay. It was odd that my testing seemed to work.

I've reverted to calling UMA_HISTOGRAMS_... three times.

[SteveT, 2012/10/03 19:51:34]

I was following what how some Net code was measuring some Http request
latencies... But it looked like that code was just for the handshake.

3 minutes seems like a reasonable upper bound on this histogram, so I'll use
MEDIUM_TIMES unless you think otherwise.

+      latency,
+      base::TimeDelta::FromMilliseconds(1),
+      base::TimeDelta::FromMinutes(10),
+      100);
+}
+
 }  // namespace
 
 VariationsService::VariationsService()
     : variations_server_url_(GetVariationsServerURL()),
       create_trials_from_seed_called_(false),
       resource_request_allowed_notifier_(
           new ResourceRequestAllowedNotifier) {
   resource_request_allowed_notifier_->Init(this);
 }
 
@@ skipping 67 matching lines @@
   pending_seed_request_->SetLoadFlags(net::LOAD_DO_NOT_SEND_COOKIES |
                                       net::LOAD_DO_NOT_SAVE_COOKIES);
   pending_seed_request_->SetRequestContext(
       g_browser_process->system_request_context());
   pending_seed_request_->SetMaxRetries(kMaxRetrySeedFetch);
   if (!variations_serial_number_.empty()) {
     pending_seed_request_->AddExtraRequestHeader("If-Match:" +
                                                  variations_serial_number_);
   }
   pending_seed_request_->Start();
+
+  last_request_started_time_ = base::TimeTicks::Now();
 }
 
 void VariationsService::FetchVariationsSeed() {
   DCHECK(content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
 
   if (!resource_request_allowed_notifier_->ResourceRequestsAllowed()) {
     DVLOG(1) << "Resource requests were not allowed. Waiting for notification.";
     return;
   }
 
   DoActualFetch();
 }
 
 void VariationsService::OnURLFetchComplete(const net::URLFetcher* source) {
   DCHECK_EQ(pending_seed_request_.get(), source);
   // The fetcher will be deleted when the request is handled.
   scoped_ptr<const net::URLFetcher> request(
       pending_seed_request_.release());
   if (request->GetStatus().status() != net::URLRequestStatus::SUCCESS) {
     DVLOG(1) << "Variations server request failed.";
     return;
   }
 
   // Log the response code.
   UMA_HISTOGRAM_CUSTOM_ENUMERATION("Variations.SeedFetchResponseCode",
       net::HttpUtil::MapStatusCodeForHistogram(request->GetResponseCode()),
       net::HttpUtil::GetStatusCodesForHistogram());
 
+  const base::TimeDelta latency =
+      base::TimeTicks::Now() - last_request_started_time_;
+
   if (request->GetResponseCode() != 200) {
     DVLOG(1) << "Variations server request returned non-200 response code: "
              << request->GetResponseCode();
+    if (request->GetResponseCode() == 304)
+      LogRequestLatency("Variations.FetchNotModifiedLatency", latency);
+    else
+      LogRequestLatency("Variations.FetchOtherLatency", latency);
     return;
   }
+  LogRequestLatency("Variations.FetchSuccessLatency", latency);
 
   std::string seed_data;
   bool success = request->GetResponseAsString(&seed_data);
   DCHECK(success);
 
   base::Time response_date;
   success = request->GetResponseHeaders()->GetDateValue(&response_date);
   DCHECK(success || response_date.is_null());
 
   StoreSeedData(seed_data, response_date, g_browser_process->local_state());
@@ skipping 271 matching lines @@
                                       variation_id);
     }
   }
 
   trial->SetForced();
   if (IsStudyExpired(study, reference_date))
     trial->Disable();
 }
 
 }  // namespace chrome_variations