Bug 913813 - HTTP cache v1/v2 miss/hit time compare telemetry, r=michal

netwerk/cache2/CacheEntry.cpp

@@ -21,6 +21,7 @@
 #include "nsProxyRelease.h"
 #include "nsSerializationHelper.h"
 #include "nsThreadUtils.h"
+#include "mozilla/Telemetry.h"
 #include <math.h>
 #include <algorithm>
 
@@ -215,6 +216,7 @@ bool CacheEntry::Load(bool aTruncate, bool aPriority)
   }
   else {
     mState = LOADING;
+    mLoadStart = TimeStamp::Now();
   }
 
   mFile = new CacheFile();
@@ -252,6 +254,21 @@ NS_IMETHODIMP CacheEntry::OnFileReady(nsresult aResult, bool aIsNew)
   LOG(("CacheEntry::OnFileReady [this=%p, rv=0x%08x, new=%d]",
       this, aResult, aIsNew));
 
+  MOZ_ASSERT(!mLoadStart.IsNull());
+
+  if (NS_SUCCEEDED(aResult)) {
+    if (aIsNew) {
+      mozilla::Telemetry::AccumulateTimeDelta(
+        mozilla::Telemetry::NETWORK_CACHE_V2_MISS_TIME_MS,
+        mLoadStart);
+    }
+    else {
+      mozilla::Telemetry::AccumulateTimeDelta(
+        mozilla::Telemetry::NETWORK_CACHE_V2_HIT_TIME_MS,
+        mLoadStart);
+    }
+  }
+
   // OnFileReady, that is the only code that can transit from LOADING
   // to any follow-on state, can only be invoked ones on an entry,
   // thus no need to lock.  Until this moment there is no consumer that

netwerk/cache2/CacheEntry.h

@@ -21,6 +21,7 @@
 #include "nsCOMArray.h"
 #include "nsThreadUtils.h"
 #include "mozilla/Mutex.h"
+#include "mozilla/TimeStamp.h"
 
 static inline uint32_t
 PRTimeToSeconds(PRTime t_usec)
@@ -293,6 +294,8 @@ private:
 
   int64_t mPredictedDataSize;
   uint32_t mDataSize; // ???
+
+  mozilla::TimeStamp mLoadStart;
 };
 
 } // net

netwerk/cache2/OldWrappers.cpp

@@ -20,6 +20,7 @@
 #include "nsServiceManagerUtils.h"
 #include "nsNetCID.h"
 #include "nsProxyRelease.h"
+#include "mozilla/Telemetry.h"
 
 static NS_DEFINE_CID(kStreamTransportServiceCID,
                      NS_STREAMTRANSPORTSERVICE_CID);
@@ -485,6 +486,8 @@ nsresult _OldCacheLoad::Start()
   LOG(("_OldCacheLoad::Start [this=%p, key=%s]", this, mCacheKey.get()));
   MOZ_ASSERT(NS_IsMainThread());
 
+  mLoadStart = mozilla::TimeStamp::Now();
+
   bool mainThreadOnly;
   if (mCallback && (
       NS_SUCCEEDED(mCallback->GetMainThreadOnly(&mainThreadOnly)) &&
@@ -558,6 +561,24 @@ _OldCacheLoad::Run()
       return NS_OK;
     }
 
+    if (NS_SUCCEEDED(mStatus)) {
+      if (mFlags & nsICacheStorage::OPEN_TRUNCATE) {
+        mozilla::Telemetry::AccumulateTimeDelta(
+          mozilla::Telemetry::NETWORK_CACHE_V1_TRUNCATE_TIME_MS,
+          mLoadStart);
+      }
+      else if (mNew) {
+        mozilla::Telemetry::AccumulateTimeDelta(
+          mozilla::Telemetry::NETWORK_CACHE_V1_MISS_TIME_MS,
+          mLoadStart);
+      }
+      else {
+        mozilla::Telemetry::AccumulateTimeDelta(
+          mozilla::Telemetry::NETWORK_CACHE_V1_HIT_TIME_MS,
+          mLoadStart);
+      }
+    }
+
     if (mMainThreadOnly)
       Check();
 

netwerk/cache2/OldWrappers.h

@@ -11,6 +11,7 @@
 #include "nsICacheEntryOpenCallback.h"
 #include "nsICacheEntryDescriptor.h"
 #include "nsThreadUtils.h"
+#include "mozilla/TimeStamp.h"
 
 class nsIURI;
 class nsICacheEntryOpenCallback;
@@ -88,6 +89,8 @@ private:
   nsresult mStatus;
   uint32_t mRunCount;
   nsCOMPtr<nsIApplicationCache> mAppCache;
+
+  mozilla::TimeStamp mLoadStart;
 };
 
 

toolkit/components/telemetry/Histograms.json

@@ -4014,5 +4014,40 @@
     "n_buckets": 15,
     "extended_statistics_ok": true,
     "description": "BACKGROUND THUMBNAILS: Time it took to draw the capture's window to canvas (ms)"
+  },
+  "NETWORK_CACHE_V2_MISS_TIME_MS": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time spent to find out a cache entry file is missing"
+  },
+  "NETWORK_CACHE_V2_HIT_TIME_MS": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time spent to open an existing file"
+  },
+  "NETWORK_CACHE_V1_TRUNCATE_TIME_MS": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time spent to reopen an entry with OPEN_TRUNCATE"
+  },
+  "NETWORK_CACHE_V1_MISS_TIME_MS": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time spent to find out a cache entry is missing"
+  },
+  "NETWORK_CACHE_V1_HIT_TIME_MS": {
+    "kind": "exponential",
+    "high": "10000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time spent to open an existing cache entry"
   }
 }