Record the number of freshness periods since a stale HttpCache entry was last used

net/http/http_cache_transaction.cc

Index: net/http/http_cache_transaction.cc
diff --git a/net/http/http_cache_transaction.cc b/net/http/http_cache_transaction.cc
index 420092620705381184e2bce0a6638342ede00d65..860fee6b97d9a7394b43a983cf72f9d80d8f58e7 100644
--- a/net/http/http_cache_transaction.cc
+++ b/net/http/http_cache_transaction.cc
@@ -970,6 +970,7 @@ int HttpCache::Transaction::DoOpenEntryComplete(int result) {
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, result);
   cache_pending_ = false;
   if (result == OK) {
+    open_entry_last_used_ = new_entry_->disk_entry->GetLastUsed();
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
@@ -2190,11 +2191,14 @@ ValidationType HttpCache::Transaction::RequiresValidation() {
                                             cache_->clock_->Now());
 
   if (validation_required_by_headers != VALIDATION_NONE) {
-    validation_cause_ =
-        response_.headers->GetFreshnessLifetimes(response_.response_time)
-                    .freshness == base::TimeDelta()
-            ? VALIDATION_CAUSE_ZERO_FRESHNESS
-            : VALIDATION_CAUSE_STALE;
+    HttpResponseHeaders::FreshnessLifetimes lifetimes =
+        response_.headers->GetFreshnessLifetimes(response_.response_time);
+    if (lifetimes.freshness == base::TimeDelta()) {
+      validation_cause_ = VALIDATION_CAUSE_ZERO_FRESHNESS;
+    } else {
+      validation_cause_ = VALIDATION_CAUSE_STALE;
+      stale_entry_freshness_ = lifetimes.freshness;
+    }
   }
 
   if (validation_required_by_headers == VALIDATION_ASYNCHRONOUS) {
@@ -2790,6 +2794,17 @@ void HttpCache::Transaction::RecordHistograms() {
     }
   }
 
+  if ((validation_request ||
+       transaction_pattern_ == PATTERN_ENTRY_CANT_CONDITIONALIZE) &&
+      validation_cause_ == VALIDATION_CAUSE_STALE) {
+    DCHECK(!open_entry_last_used_.is_null());
+    DCHECK(!stale_entry_freshness_.is_zero());
+
+    base::TimeDelta time_since_use = base::Time::Now() - open_entry_last_used_;
+    UMA_HISTOGRAM_COUNTS("HttpCache.StaleEntry.FreshnessPeriodsSinceLastUsed",
+                         (time_since_use * 1000) / stale_entry_freshness_);

[rkaplow, 2016/05/24 17:43:25]

instead of doing this, I think you want milliseconds, right? Why not use
inmilliseconds?

https://code.google.com/p/chromium/codesearch#chromium/src/base/time/time.h&q...

[jkarlin, 2016/05/24 17:57:40]

I see why the 1000 is making you think of milliseconds. But the metric is
recording a ratio, not a time. The * 1000 is just to make sure the integer
division has enough precision.

[jkarlin, 2016/05/24 18:38:30]

I've added a comment to clarify what's being recorded here.

+  }
+
   UMA_HISTOGRAM_ENUMERATION(
       "HttpCache.Pattern", transaction_pattern_, PATTERN_MAX);