From 5f33b8eb1d7b70f9c2f1f97bad99a3d5491b4692 Mon Sep 17 00:00:00 2001
From: Honza Bambas <honzab.moz@firemni.cz>
Date: Thu, 26 Sep 2013 21:37:03 +0200
Subject: [PATCH] Bug 913813 - HTTP cache v1/v2 miss/hit time compare
 telemetry, r=michal

---
 netwerk/cache2/CacheEntry.cpp                | 17 ++++++++++
 netwerk/cache2/CacheEntry.h                  |  3 ++
 netwerk/cache2/OldWrappers.cpp               | 21 ++++++++++++
 netwerk/cache2/OldWrappers.h                 |  3 ++
 toolkit/components/telemetry/Histograms.json | 35 ++++++++++++++++++++
 5 files changed, 79 insertions(+)

diff --git a/netwerk/cache2/CacheEntry.cpp b/netwerk/cache2/CacheEntry.cpp
index 32082d60d9a..3a5685cc56d 100644
--- a/netwerk/cache2/CacheEntry.cpp
+++ b/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
diff --git a/netwerk/cache2/CacheEntry.h b/netwerk/cache2/CacheEntry.h
index 7f4ea3e81f9..ea294b2ece7 100644
--- a/netwerk/cache2/CacheEntry.h
+++ b/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
diff --git a/netwerk/cache2/OldWrappers.cpp b/netwerk/cache2/OldWrappers.cpp
index 8ff43c3fd27..cd52199b2a0 100644
--- a/netwerk/cache2/OldWrappers.cpp
+++ b/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();
 
diff --git a/netwerk/cache2/OldWrappers.h b/netwerk/cache2/OldWrappers.h
index 3946bcb51d0..8b1eb4416bf 100644
--- a/netwerk/cache2/OldWrappers.h
+++ b/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;
 };
 
 
diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json
index ddf2a0fec4c..17a597d1fee 100644
--- a/toolkit/components/telemetry/Histograms.json
+++ b/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"
   }
 }