Log the freshness of the Variations seed in a histogram.

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 197 matching lines @@
 
 void VariationsService::SetCreateTrialsFromSeedCalledForTesting(bool called) {
   create_trials_from_seed_called_ = called;
 }
 
 // static
 void VariationsService::RegisterPrefs(PrefRegistrySimple* registry) {
   registry->RegisterStringPref(prefs::kVariationsSeed, std::string());
   registry->RegisterInt64Pref(prefs::kVariationsSeedDate,
                               base::Time().ToInternalValue());
+  registry->RegisterInt64Pref(prefs::kVariationsLastFetchTime, 0);
 }
 
 // static
 VariationsService* VariationsService::Create(PrefService* local_state) {
 // This is temporarily disabled for Android. See http://crbug.com/168224
 #if !defined(GOOGLE_CHROME_BUILD) || defined(OS_ANDROID)
   // Unless the URL was provided, unsupported builds should return NULL to
   // indicate that the service should not be used.
   if (!CommandLine::ForCurrentProcess()->HasSwitch(
           switches::kVariationsServerURL))
@@ skipping 53 matching lines @@
       response_code == net::HTTP_NOT_MODIFIED) {
     bool success = request->GetResponseHeaders()->GetDateValue(&response_date);
     DCHECK(success || response_date.is_null());
 
     if (!response_date.is_null()) {
       network_time_tracker_.UpdateNetworkTime(
           response_date,
           base::TimeDelta::FromMilliseconds(kServerTimeResolutionMs),
           latency);
     }
+
+    // If this is not the first successful fetch, record the delta between now
+    // and the last successful fetch.
+    int64 internal_now = base::Time::Now().ToInternalValue();

[Ilya Sherman, 2013/02/22 02:05:05]

nit: I'd recommend writing this as

base::Time now = base::Time::Now();

and converting to the internal representation down on line 309.

[SteveT, 2013/02/22 16:14:36]

Done.

+    int64 last_fetch_time =
+        local_state_->GetInt64(prefs::kVariationsLastFetchTime);
+    if (last_fetch_time) {
+      int64 internal_delta = internal_now - last_fetch_time;
+      DCHECK_GE(internal_delta, 0);
+      base::TimeDelta delta =
+          base::TimeDelta::FromInternalValue(internal_delta);

[Ilya Sherman, 2013/02/22 02:05:05]

nit: I'd write this as

base::TimeDelta delta =
    now - base::Time::FromInternalValue(last_fetch_time_internal);

In general, it's preferable to perform calculations with base::Time and
base::TimeDelta objects than with their internal values.

[SteveT, 2013/02/22 16:14:36]

Done.

+      // Log the value in number of minutes.
+      UMA_HISTOGRAM_CUSTOM_COUNTS("Variations.SeedFreshness", delta.InMinutes(),

[Alexei Svitkine (slow), 2013/02/22 14:13:10]

Doing this here will not give us as much info as doing it in the way we
discussed - where we log it at startup when we create field trials.

It's not really relevant if in a given 16 hour Chrome session, the browser
downloaded the seed 4 time without using it. In fact, we can already derive such
info from Variations.SeedFetchResponseCode.

For example, consider the hypothetical scenario where we modify the code to ping
every 10 minutes after startup for the first 5 hours, and then every 5 hours
otherwise.

Suppose that 99% of users restart Chrome only after 6 hours has passed.

In the current CL's implementation, the metric would indicate a very much
improved freshness of the seed (since all the successful attempts during the
first 5 hours would record the seed is only 10 minutes old). Except this would
be misleading because it won't actually improve freshness in practice if all
users are only restarting after 6 hours.

We really need to record the freshness at startup, when the seed is being
applied to paint an accurate picture here.

[SteveT, 2013/02/22 15:17:55]

I see, so what we're measuring here is "how recently was the seed successfully
updated" where as what you're suggesting we measure is "how recently was the
seed APPLIED"?

But since the seed is applied on every startup, we end up just getting a measure
of how long a Chrome session is, right? Unless you mean to measure how often a
*new* seed is applied (after a 200), in which case we're sort of just measuring
how often developers update configurations. That doesn't seem useful, either.

Could you clarify what you mean by logging at startup? Are we still comparing it
to the time recorded here?

+          1, base::TimeDelta::FromDays(7).InMinutes(), 50);
+    }
+
+    // Record the time of the most recent successful fetch.
+    local_state_->SetInt64(prefs::kVariationsLastFetchTime,
+                           internal_now);
   }
 
   if (response_code != net::HTTP_OK) {
     DVLOG(1) << "Variations server request returned non-HTTP_OK response code: "
              << response_code;
     if (response_code == net::HTTP_NOT_MODIFIED)
       UMA_HISTOGRAM_MEDIUM_TIMES("Variations.FetchNotModifiedLatency", latency);
     else
       UMA_HISTOGRAM_MEDIUM_TIMES("Variations.FetchOtherLatency", latency);
     return;
@@ skipping 294 matching lines @@
                                       variation_id);
     }
   }
 
   trial->SetForced();
   if (IsStudyExpired(study, reference_date))
     trial->Disable();
 }
 
 }  // namespace chrome_variations