Bug 920606 - HTTP cache v2: add telemetry for the intermediate memory cache purging, r=michal

netwerk/cache2/CacheEntry.cpp

@@ -175,6 +175,7 @@ CacheEntry::CacheEntry(const nsACString& aStorageID,
 , mRegistration(NEVERREGISTERED)
 , mWriter(nullptr)
 , mPredictedDataSize(0)
+, mUseCount(0)
 , mReleaseThread(NS_GetCurrentThread())
 {
   MOZ_COUNT_CTOR(CacheEntry);
@@ -211,12 +212,12 @@ char const * CacheEntry::StateString(uint32_t aState)
 
 #endif
 
-nsresult CacheEntry::HashingKeyWithStorage(nsACString &aResult)
+nsresult CacheEntry::HashingKeyWithStorage(nsACString &aResult) const
 {
   return HashingKey(mStorageID, mEnhanceID, mURI, aResult);
 }
 
-nsresult CacheEntry::HashingKey(nsACString &aResult)
+nsresult CacheEntry::HashingKey(nsACString &aResult) const
 {
   return HashingKey(EmptyCString(), mEnhanceID, mURI, aResult);
 }
@@ -362,10 +363,14 @@ bool CacheEntry::Load(bool aTruncate, bool aPriority)
   BackgroundOp(Ops::REGISTER);
 
   bool directLoad = aTruncate || !mUseDisk;
-  if (directLoad)
+  if (directLoad) {
     mFileStatus = NS_OK;
-  else
+    // mLoadStart will be used to calculate telemetry of life-time of this entry.
+    // Low resulution is then enough.
+    mLoadStart = TimeStamp::NowLoRes();
+  } else {
     mLoadStart = TimeStamp::Now();
+  }
 
   {
     mozilla::MutexAutoUnlock unlock(mLock);
@@ -1514,6 +1519,8 @@ void CacheEntry::BackgroundOp(uint32_t aOperations, bool aForceAsync)
     MOZ_ASSERT(CacheStorageService::IsOnManagementThread());
 
     if (aOperations & Ops::FRECENCYUPDATE) {
+      ++mUseCount;
+
       #ifndef M_LN2
       #define M_LN2 0.69314718055994530942
       #endif

netwerk/cache2/CacheEntry.h

@@ -69,9 +69,9 @@ public:
   nsIURI* GetURI() const { return mURI; }
   // Accessible at any time
   bool IsUsingDisk() const { return mUseDisk; }
-  bool SetUsingDisk(bool aUsingDisk);
   bool IsReferenced() const;
   bool IsFileDoomed();
+  bool IsDoomed() const { return mIsDoomed; }
 
   // Methods for entry management (eviction from memory),
   // called only on the management thread.
@@ -79,11 +79,14 @@ public:
   // TODO make these inline
   double GetFrecency() const;
   uint32_t GetExpirationTime() const;
+  uint32_t UseCount() const { return mUseCount; }
 
   bool IsRegistered() const;
   bool CanRegister() const;
   void SetRegistered(bool aRegistered);
 
+  TimeStamp const& LoadStart() const { return mLoadStart; }
+
   enum EPurge {
     PURGE_DATA_ONLY_DISK_BACKED,
     PURGE_WHOLE_ONLY_DISK_BACKED,
@@ -94,8 +97,8 @@ public:
   void PurgeAndDoom();
   void DoomAlreadyRemoved();
 
-  nsresult HashingKeyWithStorage(nsACString &aResult);
-  nsresult HashingKey(nsACString &aResult);
+  nsresult HashingKeyWithStorage(nsACString &aResult) const;
+  nsresult HashingKey(nsACString &aResult) const;
 
   static nsresult HashingKey(nsCSubstring const& aStorageID,
                              nsCSubstring const& aEnhanceID,
@@ -342,6 +345,7 @@ private:
   nsCOMPtr<nsISupports> mSecurityInfo;
   int64_t mPredictedDataSize;
   mozilla::TimeStamp mLoadStart;
+  uint32_t mUseCount;
   nsCOMPtr<nsIThread> mReleaseThread;
 };
 

netwerk/cache2/CacheStorageService.cpp

@@ -865,6 +865,8 @@ CacheStorageService::RegisterEntry(CacheEntry* aEntry)
   if (mShutdown || !aEntry->CanRegister())
     return;
 
+  TelemetryRecordEntryCreation(aEntry);
+
   LOG(("CacheStorageService::RegisterEntry [entry=%p]", aEntry));
 
   MemoryPool& pool = Pool(aEntry->IsUsingDisk());
@@ -882,6 +884,8 @@ CacheStorageService::UnregisterEntry(CacheEntry* aEntry)
   if (!aEntry->IsRegistered())
     return;
 
+  TelemetryRecordEntryRemoval(aEntry);
+
   LOG(("CacheStorageService::UnregisterEntry [entry=%p]", aEntry));
 
   MemoryPool& pool = Pool(aEntry->IsUsingDisk());
@@ -1742,6 +1746,113 @@ CacheStorageService::GetCacheEntryInfo(CacheEntry* aEntry,
                          fetchCount, lastModified, expirationTime);
 }
 
+// Telementry collection
+
+namespace { // anon
+
+bool TelemetryEntryKey(CacheEntry const* entry, nsAutoCString& key)
+{
+  nsAutoCString entryKey;
+  nsresult rv = entry->HashingKey(entryKey);
+  if (NS_FAILED(rv))
+    return false;
+
+  if (entry->GetStorageID().IsEmpty()) {
+    // Hopefully this will be const-copied, saves some memory
+    key = entryKey;
+  } else {
+    key.Assign(entry->GetStorageID());
+    key.Append(':');
+    key.Append(entryKey);
+  }
+
+  return true;
+}
+
+PLDHashOperator PrunePurgeTimeStamps(
+  const nsACString& aKey, TimeStamp& aTimeStamp, void* aClosure)
+{
+  TimeStamp* now = static_cast<TimeStamp*>(aClosure);
+  static TimeDuration const fifteenMinutes = TimeDuration::FromSeconds(900);
+
+  if (*now - aTimeStamp > fifteenMinutes) {
+    // We are not interested in resurrection of entries after 15 minutes
+    // of time.  This is also the limit for the telemetry.
+    return PL_DHASH_REMOVE;
+  }
+
+  return PL_DHASH_NEXT;
+}
+
+} // anon
+
+void
+CacheStorageService::TelemetryPrune(TimeStamp &now)
+{
+  static TimeDuration const oneMinute = TimeDuration::FromSeconds(60);
+  static TimeStamp dontPruneUntil = now + oneMinute;
+  if (now < dontPruneUntil)
+    return;
+
+  mPurgeTimeStamps.Enumerate(PrunePurgeTimeStamps, &now);
+  dontPruneUntil = now + oneMinute;
+}
+
+void
+CacheStorageService::TelemetryRecordEntryCreation(CacheEntry const* entry)
+{
+  MOZ_ASSERT(CacheStorageService::IsOnManagementThread());
+
+  nsAutoCString key;
+  if (!TelemetryEntryKey(entry, key))
+    return;
+
+  TimeStamp now = TimeStamp::NowLoRes();
+  TelemetryPrune(now);
+
+  // When an entry is craeted (registered actually) we check if there is
+  // a timestamp marked when this very same cache entry has been removed
+  // (deregistered) because of over-memory-limit purging.  If there is such
+  // a timestamp found accumulate telemetry on how long the entry was away.
+  TimeStamp timeStamp;
+  if (!mPurgeTimeStamps.Get(key, &timeStamp))
+    return;
+
+  mPurgeTimeStamps.Remove(key);
+
+  Telemetry::AccumulateTimeDelta(Telemetry::HTTP_CACHE_ENTRY_RELOAD_TIME,
+                                 timeStamp, TimeStamp::NowLoRes());
+}
+
+void
+CacheStorageService::TelemetryRecordEntryRemoval(CacheEntry const* entry)
+{
+  MOZ_ASSERT(CacheStorageService::IsOnManagementThread());
+
+  // Doomed entries must not be considered, we are only interested in purged
+  // entries.  Note that the mIsDoomed flag is always set before deregistration
+  // happens.
+  if (entry->IsDoomed())
+    return;
+
+  nsAutoCString key;
+  if (!TelemetryEntryKey(entry, key))
+    return;
+
+  // When an entry is removed (deregistered actually) we put a timestamp for this
+  // entry to the hashtable so that when the entry is created (registered) again
+  // we know how long it was away.  Also accumulate number of AsyncOpen calls on
+  // the entry, this tells us how efficiently the pool actually works.
+
+  TimeStamp now = TimeStamp::NowLoRes();
+  TelemetryPrune(now);
+  mPurgeTimeStamps.Put(key, now);
+
+  Telemetry::Accumulate(Telemetry::HTTP_CACHE_ENTRY_REUSE_COUNT, entry->UseCount());
+  Telemetry::AccumulateTimeDelta(Telemetry::HTTP_CACHE_ENTRY_ALIVE_TIME,
+                                 entry->LoadStart(), TimeStamp::NowLoRes());
+}
+
 // nsIMemoryReporter
 
 size_t

netwerk/cache2/CacheStorageService.h

@@ -10,11 +10,13 @@
 
 #include "nsITimer.h"
 #include "nsClassHashtable.h"
+#include "nsDataHashtable.h"
 #include "nsString.h"
 #include "nsThreadUtils.h"
 #include "nsProxyRelease.h"
 #include "mozilla/Mutex.h"
 #include "mozilla/Atomics.h"
+#include "mozilla/TimeStamp.h"
 #include "nsTArray.h"
 
 class nsIURI;
@@ -144,6 +146,12 @@ private:
                              bool aOnlyInMemory,
                              bool aOverwrite);
 
+private:
+  // These are helpers for telemetry monitorying of the memory pools.
+  void TelemetryPrune(TimeStamp &now);
+  void TelemetryRecordEntryCreation(CacheEntry const* entry);
+  void TelemetryRecordEntryRemoval(CacheEntry const* entry);
+
 private:
   // Following methods are thread safe to call.
   friend class CacheStorage;
@@ -323,6 +331,12 @@ private:
     nsRefPtr<CacheStorageService> mService;
     uint32_t mWhat;
   };
+
+  // Used just for telemetry purposes, accessed only on the management thread.
+  // Note: not included in the memory reporter, this is not expected to be huge
+  // and also would be complicated to report since reporting happens on the main
+  // thread but this table is manipulated on the management thread.
+  nsDataHashtable<nsCStringHashKey, mozilla::TimeStamp> mPurgeTimeStamps;
 };
 
 template<class T>

toolkit/components/telemetry/Histograms.json

@@ -1459,6 +1459,29 @@
     "n_values": 4,
     "description": "HTTP Cache v2 Miss by half-life value (6h, 1d, 7d, 50d)"
   },
+  "HTTP_CACHE_ENTRY_RELOAD_TIME": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "900000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time before we reload an HTTP cache entry again to memory"
+  },
+  "HTTP_CACHE_ENTRY_ALIVE_TIME": {
+    "expires_in_version": "never",
+    "kind": "exponential",
+    "high": "7200000",
+    "n_buckets": 50,
+    "extended_statistics_ok": true,
+    "description": "Time for which an HTTP cache entry is kept warmed in memory"
+  },
+  "HTTP_CACHE_ENTRY_REUSE_COUNT": {
+    "expires_in_version": "never",
+    "kind": "linear",
+    "high": "20",
+    "n_buckets": 19,
+    "description": "Reuse count of an HTTP cache entry warmed in memory"
+  },
   "HTTP_MEMORY_CACHE_DISPOSITION_2": {
     "expires_in_version": "never",
     "kind": "enumerated",