Bug 1312057 - Fix prefetch telmetry r=mayhemer,necko-reviewers,dragana

Differential Revision: https://phabricator.services.mozilla.com/D11518

netwerk/base/Predictor.cpp

@@ -2186,6 +2186,8 @@ Predictor::PrefetchListener::OnStopRequest(nsIRequest* aRequest,
                    static_cast<uint32_t>(rv)));
   } else {
     rv = cachingChannel->ForceCacheEntryValidFor(0);
+    Telemetry::AccumulateCategorical(
+        Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::Not200);
     PREDICTOR_LOG(("    removing any forced validity rv=%" PRIX32,
                    static_cast<uint32_t>(rv)));
   }

netwerk/cache2/CacheEntry.cpp

@@ -1130,6 +1130,19 @@ nsresult CacheEntry::ForceValidFor(uint32_t aSecondsToTheFuture) {
   return NS_OK;
 }
 
+nsresult CacheEntry::MarkForcedValidUse() {
+  LOG(("CacheEntry::MarkForcedValidUse [this=%p, ]", this));
+
+  nsAutoCString key;
+  nsresult rv = HashingKey(key);
+  if (NS_FAILED(rv)) {
+    return rv;
+  }
+
+  CacheStorageService::Self()->MarkForcedValidEntryUse(mStorageID, key);
+  return NS_OK;
+}
+
 nsresult CacheEntry::SetExpirationTime(uint32_t aExpirationTime) {
   NS_ENSURE_SUCCESS(mFileStatus, NS_ERROR_NOT_AVAILABLE);
 

netwerk/cache2/CacheEntry.h

@@ -74,6 +74,7 @@ class CacheEntry final : public nsIRunnable, public CacheFileListener {
   nsresult SetContentType(uint8_t aContentType);
   nsresult ForceValidFor(uint32_t aSecondsToTheFuture);
   nsresult GetIsForcedValid(bool* aIsForcedValid);
+  nsresult MarkForcedValidUse();
   nsresult OpenInputStream(int64_t offset, nsIInputStream** _retval);
   nsresult OpenOutputStream(int64_t offset, int64_t predictedSize,
                             nsIOutputStream** _retval);
@@ -473,6 +474,9 @@ class CacheEntryHandle final : public nsICacheEntry {
   NS_IMETHOD GetIsForcedValid(bool* aIsForcedValid) override {
     return mEntry->GetIsForcedValid(aIsForcedValid);
   }
+  NS_IMETHOD MarkForcedValidUse() override {
+    return mEntry->MarkForcedValidUse();
+  }
   NS_IMETHOD OpenInputStream(int64_t offset,
                              nsIInputStream** _retval) override {
     return mEntry->OpenInputStream(offset, _retval);

netwerk/cache2/CacheStorageService.cpp

@@ -18,6 +18,7 @@
 #include "nsIObserverService.h"
 #include "nsIFile.h"
 #include "nsIURI.h"
+#include "nsINetworkPredictor.h"
 #include "nsCOMPtr.h"
 #include "nsContentUtils.h"
 #include "nsNetCID.h"
@@ -1159,26 +1160,46 @@ bool CacheStorageService::IsForcedValidEntry(
     nsACString const& aContextEntryKey) {
   mozilla::MutexAutoLock lock(mForcedValidEntriesLock);
 
-  TimeStamp validUntil;
+  ForcedValidData data;
 
-  if (!mForcedValidEntries.Get(aContextEntryKey, &validUntil)) {
+  if (!mForcedValidEntries.Get(aContextEntryKey, &data)) {
     return false;
   }
 
-  if (validUntil.IsNull()) {
+  if (data.validUntil.IsNull()) {
+    MOZ_ASSERT_UNREACHABLE("the timeStamp should never be null");
     return false;
   }
 
   // Entry timeout not reached yet
-  if (TimeStamp::NowLoRes() <= validUntil) {
+  if (TimeStamp::NowLoRes() <= data.validUntil) {
     return true;
   }
 
   // Entry timeout has been reached
   mForcedValidEntries.Remove(aContextEntryKey);
+
+  if (!data.viewed) {
+    Telemetry::AccumulateCategorical(
+        Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::WaitedTooLong);
+  }
   return false;
 }
 
+void CacheStorageService::MarkForcedValidEntryUse(nsACString const& aContextKey,
+                                                  nsACString const& aEntryKey) {
+  mozilla::MutexAutoLock lock(mForcedValidEntriesLock);
+
+  ForcedValidData data;
+
+  if (!mForcedValidEntries.Get(aContextKey + aEntryKey, &data)) {
+    return;
+  }
+
+  data.viewed = true;
+  mForcedValidEntries.InsertOrUpdate(aContextKey + aEntryKey, data);
+}
+
 // Allows a cache entry to be loaded directly from cache without further
 // validation - see nsICacheEntry.idl for further details
 void CacheStorageService::ForceEntryValidFor(nsACString const& aContextKey,
@@ -1189,10 +1210,11 @@ void CacheStorageService::ForceEntryValidFor(nsACString const& aContextKey,
   TimeStamp now = TimeStamp::NowLoRes();
   ForcedValidEntriesPrune(now);
 
-  // This will be the timeout
-  TimeStamp validUntil = now + TimeDuration::FromSeconds(aSecondsToTheFuture);
+  ForcedValidData data;
+  data.validUntil = now + TimeDuration::FromSeconds(aSecondsToTheFuture);
+  data.viewed = false;
 
-  mForcedValidEntries.InsertOrUpdate(aContextKey + aEntryKey, validUntil);
+  mForcedValidEntries.InsertOrUpdate(aContextKey + aEntryKey, data);
 }
 
 void CacheStorageService::RemoveEntryForceValid(nsACString const& aContextKey,
@@ -1201,6 +1223,12 @@ void CacheStorageService::RemoveEntryForceValid(nsACString const& aContextKey,
 
   LOG(("CacheStorageService::RemoveEntryForceValid context='%s' entryKey=%s",
        aContextKey.BeginReading(), aEntryKey.BeginReading()));
+  ForcedValidData data;
+  bool ok = mForcedValidEntries.Get(aContextKey + aEntryKey, &data);
+  if (ok && !data.viewed) {
+    Telemetry::AccumulateCategorical(
+        Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::WaitedTooLong);
+  }
   mForcedValidEntries.Remove(aContextKey + aEntryKey);
 }
 
@@ -1211,7 +1239,11 @@ void CacheStorageService::ForcedValidEntriesPrune(TimeStamp& now) {
   if (now < dontPruneUntil) return;
 
   for (auto iter = mForcedValidEntries.Iter(); !iter.Done(); iter.Next()) {
-    if (iter.Data() < now) {
+    if (iter.Data().validUntil < now) {
+      if (!iter.Data().viewed) {
+        Telemetry::AccumulateCategorical(
+            Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::WaitedTooLong);
+      }
       iter.Remove();
     }
   }

netwerk/cache2/CacheStorageService.h

@@ -101,7 +101,14 @@ class CacheStorageService final : public nsICacheStorageService,
   mozilla::Mutex& Lock() { return mLock; }
 
   // Tracks entries that may be forced valid in a pruned hashtable.
-  nsTHashMap<nsCStringHashKey, TimeStamp> mForcedValidEntries;
+  struct ForcedValidData {
+    // The timestamp is computed when the entry gets inserted into the map.
+    // It should never be null for an entry in the map.
+    TimeStamp validUntil;
+    // viewed gets set to true by a call to MarkForcedValidEntryUse()
+    bool viewed = false;
+  };
+  nsTHashMap<nsCStringHashKey, ForcedValidData> mForcedValidEntries;
   void ForcedValidEntriesPrune(TimeStamp& now);
 
   // Helper thread-safe interface to pass entry info, only difference from
@@ -190,6 +197,11 @@ class CacheStorageService final : public nsICacheStorageService,
   bool IsForcedValidEntry(nsACString const& aContextKey,
                           nsACString const& aEntryKey);
 
+  // Marks the entry as used, so we may properly report when it gets evicted
+  // if the prefetched resource was used or not.
+  void MarkForcedValidEntryUse(nsACString const& aContextKey,
+                               nsACString const& aEntryKey);
+
  private:
   friend class CacheIndex;
 

netwerk/cache2/nsICacheEntry.idl

@@ -125,6 +125,14 @@ interface nsICacheEntry : nsISupports
    */
   readonly attribute boolean isForcedValid;
 
+  /**
+   * This method gets called to mark the actual use of the forced-valid entry.
+   * This is necessary for telemetry, so when the entry eventually gets
+   * evicted we can report whether it was ever used or not.
+   * If the entry was not forced-valid, then this operation has no effect.
+   */
+  void markForcedValidUse();
+
   /**
    * Open blocking input stream to cache data.  Use the stream transport
    * service to asynchronously read this stream on a background thread.

netwerk/protocol/http/nsHttpChannel.cpp

@@ -3785,6 +3785,7 @@ nsHttpChannel::OnCacheEntryCheck(nsICacheEntry* entry, uint32_t* aResult) {
 
   bool isForcedValid = false;
   entry->GetIsForcedValid(&isForcedValid);
+  auto prefetchStatus = Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::Used;
 
   bool weaklyFramed, isImmutable;
   nsHttp::DetermineFramingAndImmutability(entry, mCachedResponseHead.get(),
@@ -3795,7 +3796,12 @@ nsHttpChannel::OnCacheEntryCheck(nsICacheEntry* entry, uint32_t* aResult) {
     LOG(("Validating based on Vary headers returning TRUE\n"));
     canAddImsHeader = false;
     doValidation = true;
+    prefetchStatus = Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::WouldVary;
   } else {
+    if (mCachedResponseHead->ExpiresInPast() ||
+        mCachedResponseHead->MustValidateIfExpired()) {
+      prefetchStatus = Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::Expired;
+    }
     doValidation = nsHttp::ValidationRequired(
         isForcedValid, mCachedResponseHead.get(), mLoadFlags,
         LoadAllowStaleCacheContent(), isImmutable,
@@ -3837,6 +3843,9 @@ nsHttpChannel::OnCacheEntryCheck(nsICacheEntry* entry, uint32_t* aResult) {
     doValidation =
         (fromPreviousSession && !buf.IsEmpty()) ||
         (buf.IsEmpty() && mRequestHead.HasHeader(nsHttp::Authorization));
+    if (doValidation) {
+      prefetchStatus = Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::Auth;
+    }
   }
 
   // Bug #561276: We maintain a chain of cache-keys which returns cached
@@ -3860,11 +3869,28 @@ nsHttpChannel::OnCacheEntryCheck(nsICacheEntry* entry, uint32_t* aResult) {
          doValidation ? "contains" : "does not contain", cacheKey.get()));
 
     // Append cacheKey if not in the chain already
-    if (!doValidation) mRedirectedCachekeys->AppendElement(cacheKey);
+    if (!doValidation) {
+      mRedirectedCachekeys->AppendElement(cacheKey);
+    } else {
+      prefetchStatus =
+          Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::Redirect;
+    }
   }
 
   mCachedContentIsValid = !doValidation;
 
+  if (isForcedValid) {
+    // Telemetry value is only useful if this was a prefetched item
+    if (!doValidation) {
+      // Could have gotten to a funky state with some of the if chain above
+      // and in nsHttp::ValidationRequired. Make sure we get it right here.
+      prefetchStatus = Telemetry::LABELS_PREDICTOR_PREFETCH_USE_STATUS::Used;
+
+      entry->MarkForcedValidUse();
+    }
+    Telemetry::AccumulateCategorical(prefetchStatus);
+  }
+
   if (doValidation) {
     //
     // now, we are definitely going to issue a HTTP request to the server.

toolkit/components/telemetry/Histograms.json

@@ -4944,16 +4944,15 @@
     "n_buckets": 50,
     "description": "How many actual prefetches happen"
   },
-  "PREDICTOR_TOTAL_PREFETCHES_USED": {
+  "PREDICTOR_PREFETCH_USE_STATUS": {
     "record_in_processes": ["main"],
     "products": ["firefox", "fennec"],
     "expires_in_version": "never",
     "alert_emails": ["necko@mozilla.com"],
-    "bug_numbers": [1016628],
-    "kind": "exponential",
-    "high": 1000000,
-    "n_buckets": 50,
-    "description": "How many prefetches are actually used by a channel"
+    "bug_numbers": [1016628, 1312057],
+    "kind": "categorical",
+    "labels": ["Used", "Not200", "Expired", "WouldVary", "WaitedTooLong", "Etag", "Auth", "Redirect"],
+    "description": "If and why prefetches are used/unused."
   },
   "PREDICTOR_PREFETCH_TIME": {
     "record_in_processes": ["main"],
@@ -5101,21 +5100,21 @@
   "PREDICTOR_PREFETCH_DECISION_REASON": {
     "record_in_processes": ["main"],
     "products": ["firefox", "fennec"],
-    "expires_in_version": "65",
+    "expires_in_version": "never",
     "kind": "enumerated",
     "n_values": 15,
     "alert_emails": ["necko@mozilla.com"],
-    "bug_numbers": [1409542, 1430322],
+    "bug_numbers": [1409542, 1430322, 1312057],
     "description": "Why the predictor determined a particular resource was eligible for future prefetch (or not). See PrefetchDecisionReason in Predictor.cpp for value meanings"
   },
   "PREDICTOR_PREFETCH_IGNORE_REASON": {
     "record_in_processes": ["main"],
     "products": ["firefox", "fennec"],
-    "expires_in_version": "65",
+    "expires_in_version": "never",
     "kind": "enumerated",
     "n_values": 15,
     "alert_emails": ["necko@mozilla.com"],
-    "bug_numbers": [1409542, 1430322],
+    "bug_numbers": [1409542, 1430322, 1312057],
     "description": "Why the predictor determined a particular resource that was marked eligible for prefetch should not be prefetched. See PrefetchIgnoreReason in Predictor.cpp for value meanings"
   },
   "HTTPCONNMGR_TOTAL_SPECULATIVE_CONN": {