Bug 1325336 - Generate statistics for cache performance on the given HW, r=valentin, r=honzab
authorMichal Novotny <michal.novotny@gmail.com>
Fri, 23 Jun 2017 10:24:45 +0200
changeset 417101 4da7ff4c92bf47c1ceb8383da4cc459e84a95e08
parent 417100 aa1693a26a15eb5cba24102222687dc81eeddd7b
child 417102 ea3fb9e7622e2f890d45cc2f45cd472c6cf45935
push id1517
push userjlorenzo@mozilla.com
push dateThu, 14 Sep 2017 16:50:54 +0000
treeherdermozilla-release@3b41fd564418 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvalentin, honzab
bugs1325336
milestone56.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1325336 - Generate statistics for cache performance on the given HW, r=valentin, r=honzab CachePerfStats gathers performance data for single open, read and write operations as well as the whole cache entry opening. It maintains long term and short term average. The long term average filters out excessive values and it represents and average time for a given operation when the cache is not busy. The short term average represents the current cache speed. By comparing these two stats we know pretty quickly that the cache is getting slower and then we race the cache with network immediately without a delay. Otherwise the delay is based on the average cache entry open time.
netwerk/cache2/CacheFileIOManager.cpp
netwerk/cache2/CacheFileUtils.cpp
netwerk/cache2/CacheFileUtils.h
netwerk/cache2/CacheIOThread.cpp
netwerk/cache2/CacheIOThread.h
netwerk/protocol/http/nsHttpChannel.cpp
--- a/netwerk/cache2/CacheFileIOManager.cpp
+++ b/netwerk/cache2/CacheFileIOManager.cpp
@@ -589,25 +589,70 @@ public:
     }
   }
 
 protected:
   mozilla::Monitor mMonitor;
   bool             mNotified;
 };
 
-class OpenFileEvent : public Runnable {
+// Class responsible for reporting IO performance stats
+class IOPerfReportEvent {
+public:
+  explicit IOPerfReportEvent(CacheFileUtils::CachePerfStats::EDataType aType)
+    : mType(aType)
+    , mEventCounter(0)
+  {
+  }
+
+  void Start(CacheIOThread *aIOThread)
+  {
+    mStartTime = TimeStamp::Now();
+    mEventCounter = aIOThread->EventCounter();
+  }
+
+  void Report(CacheIOThread *aIOThread)
+  {
+    if (mStartTime.IsNull()) {
+      return;
+    }
+
+    // Single IO operations can take less than 1ms. So we use microseconds to
+    // keep a good resolution of data.
+    uint32_t duration = (TimeStamp::Now() - mStartTime).ToMicroseconds();
+
+    // This is a simple prefiltering of values that might differ a lot from the
+    // average value. Do not add the value to the filtered stats when the event
+    // had to wait in a long queue.
+    uint32_t eventCounter = aIOThread->EventCounter();
+    bool shortOnly = eventCounter - mEventCounter < 5 ? false : true;
+
+    CacheFileUtils::CachePerfStats::AddValue(mType, duration, shortOnly);
+  }
+
+protected:
+  CacheFileUtils::CachePerfStats::EDataType mType;
+  TimeStamp                             mStartTime;
+  uint32_t                              mEventCounter;
+};
+
+class OpenFileEvent : public Runnable
+                    , public IOPerfReportEvent {
 public:
   OpenFileEvent(const nsACString &aKey, uint32_t aFlags,
                 CacheFileIOListener *aCallback)
-    : mFlags(aFlags)
+    : IOPerfReportEvent(CacheFileUtils::CachePerfStats::IO_OPEN)
+    , mFlags(aFlags)
     , mCallback(aCallback)
     , mKey(aKey)
   {
     mIOMan = CacheFileIOManager::gInstance;
+    if (!(mFlags & CacheFileIOManager::SPECIAL_FILE)) {
+      Start(mIOMan->mIOThread);
+    }
   }
 
 protected:
   ~OpenFileEvent()
   {
   }
 
 public:
@@ -625,16 +670,19 @@ public:
       rv = NS_ERROR_NOT_INITIALIZED;
     } else {
       if (mFlags & CacheFileIOManager::SPECIAL_FILE) {
         rv = mIOMan->OpenSpecialFileInternal(mKey, mFlags,
                                              getter_AddRefs(mHandle));
       } else {
         rv = mIOMan->OpenFileInternal(&mHash, mKey, mFlags,
                                       getter_AddRefs(mHandle));
+        if (NS_SUCCEEDED(rv)) {
+          Report(mIOMan->mIOThread);
+        }
       }
       mIOMan = nullptr;
       if (mHandle) {
         if (mHandle->Key().IsEmpty()) {
           mHandle->Key() = mKey;
         }
       }
     }
@@ -647,26 +695,31 @@ protected:
   SHA1Sum::Hash                 mHash;
   uint32_t                      mFlags;
   nsCOMPtr<CacheFileIOListener> mCallback;
   RefPtr<CacheFileIOManager>    mIOMan;
   RefPtr<CacheFileHandle>       mHandle;
   nsCString                     mKey;
 };
 
-class ReadEvent : public Runnable {
+class ReadEvent : public Runnable
+                , public IOPerfReportEvent {
 public:
   ReadEvent(CacheFileHandle *aHandle, int64_t aOffset, char *aBuf,
             int32_t aCount, CacheFileIOListener *aCallback)
-    : mHandle(aHandle)
+    : IOPerfReportEvent(CacheFileUtils::CachePerfStats::IO_READ)
+    , mHandle(aHandle)
     , mOffset(aOffset)
     , mBuf(aBuf)
     , mCount(aCount)
     , mCallback(aCallback)
   {
+    if (!mHandle->IsSpecialFile()) {
+      Start(CacheFileIOManager::gInstance->mIOThread);
+    }
   }
 
 protected:
   ~ReadEvent()
   {
   }
 
 public:
@@ -674,43 +727,51 @@ public:
   {
     nsresult rv;
 
     if (mHandle->IsClosed() || (mCallback && mCallback->IsKilled())) {
       rv = NS_ERROR_NOT_INITIALIZED;
     } else {
       rv = CacheFileIOManager::gInstance->ReadInternal(
         mHandle, mOffset, mBuf, mCount);
+      if (NS_SUCCEEDED(rv)) {
+        Report(CacheFileIOManager::gInstance->mIOThread);
+      }
     }
 
     mCallback->OnDataRead(mHandle, mBuf, rv);
     return NS_OK;
   }
 
 protected:
   RefPtr<CacheFileHandle>       mHandle;
   int64_t                       mOffset;
   char                         *mBuf;
   int32_t                       mCount;
   nsCOMPtr<CacheFileIOListener> mCallback;
 };
 
-class WriteEvent : public Runnable {
+class WriteEvent : public Runnable
+                 , public IOPerfReportEvent {
 public:
   WriteEvent(CacheFileHandle *aHandle, int64_t aOffset, const char *aBuf,
              int32_t aCount, bool aValidate, bool aTruncate,
              CacheFileIOListener *aCallback)
-    : mHandle(aHandle)
+    : IOPerfReportEvent(CacheFileUtils::CachePerfStats::IO_WRITE)
+    , mHandle(aHandle)
     , mOffset(aOffset)
     , mBuf(aBuf)
     , mCount(aCount)
     , mValidate(aValidate)
     , mTruncate(aTruncate)
     , mCallback(aCallback)
   {
+    if (!mHandle->IsSpecialFile()) {
+      Start(CacheFileIOManager::gInstance->mIOThread);
+    }
   }
 
 protected:
   ~WriteEvent()
   {
     if (!mCallback && mBuf) {
       free(const_cast<char *>(mBuf));
     }
@@ -727,16 +788,19 @@ public:
       // to avoid any past-shutdown file dooming.
       rv = (CacheObserver::IsPastShutdownIOLag() ||
             CacheFileIOManager::gInstance->mShuttingDown)
         ? NS_OK
         : NS_ERROR_NOT_INITIALIZED;
     } else {
       rv = CacheFileIOManager::gInstance->WriteInternal(
           mHandle, mOffset, mBuf, mCount, mValidate, mTruncate);
+      if (NS_SUCCEEDED(rv)) {
+        Report(CacheFileIOManager::gInstance->mIOThread);
+      }
       if (NS_FAILED(rv) && !mCallback) {
         // No listener is going to handle the error, doom the file
         CacheFileIOManager::gInstance->DoomFileInternal(mHandle);
       }
     }
     if (mCallback) {
       mCallback->OnDataWritten(mHandle, mBuf, rv);
     } else {
--- a/netwerk/cache2/CacheFileUtils.cpp
+++ b/netwerk/cache2/CacheFileUtils.cpp
@@ -506,16 +506,166 @@ DetailedCacheHitTelemetry::AddRecord(ERe
 
       Telemetry::Accumulate(Telemetry::NETWORK_CACHE_HIT_RATE_PER_CACHE_SIZE,
                             bucketOffset + i);
       sHRStats[i].Reset();
     }
   }
 }
 
+StaticMutex CachePerfStats::sLock;
+CachePerfStats::PerfData CachePerfStats::sData[CachePerfStats::LAST];
+
+CachePerfStats::MMA::MMA(uint32_t aTotalWeight, bool aFilter)
+  : mSum(0)
+  , mSumSq(0)
+  , mCnt(0)
+  , mWeight(aTotalWeight)
+  , mFilter(aFilter)
+{
+}
+
+void
+CachePerfStats::MMA::AddValue(uint32_t aValue)
+{
+  if (mFilter) {
+    // Filter high spikes
+    uint32_t avg = GetAverage();
+    uint32_t stddev = GetStdDev();
+    uint32_t maxdiff = (avg / 4) + (2 * stddev);
+    if (avg && aValue > avg + maxdiff) {
+      return;
+    }
+  }
+
+  if (mCnt < mWeight) {
+    // Compute arithmetic average until we have at least mWeight values
+    CheckedInt<uint64_t> newSumSq = CheckedInt<uint64_t>(aValue) * aValue;
+    newSumSq += mSumSq;
+    if (!newSumSq.isValid()) {
+      return; // ignore this value
+    }
+    mSumSq = newSumSq.value();
+    mSum += aValue;
+    ++mCnt;
+  } else {
+    CheckedInt<uint64_t> newSumSq = mSumSq - mSumSq / mCnt;
+    newSumSq += static_cast<uint64_t>(aValue) * aValue;
+    if (!newSumSq.isValid()) {
+      return; // ignore this value
+    }
+    mSumSq = newSumSq.value();
+
+    // Compute modified moving average for more values:
+    // newAvg = ((weight - 1) * oldAvg + newValue) / weight
+    mSum -= GetAverage();
+    mSum += aValue;
+  }
+}
+
+uint32_t
+CachePerfStats::MMA::GetAverage()
+{
+  if (mCnt == 0) {
+    return 0;
+  }
+
+  return mSum / mCnt;
+}
+
+uint32_t
+CachePerfStats::MMA::GetStdDev()
+{
+  if (mCnt == 0) {
+    return 0;
+  }
+
+  uint32_t avg = GetAverage();
+  uint64_t avgSq = static_cast<uint64_t>(avg) * avg;
+  uint64_t variance = mSumSq / mCnt;
+  if (variance < avgSq) {
+    // Due to rounding error when using integer data type, it can happen that
+    // average of squares of the values is smaller than square of the average
+    // of the values. In this case fix mSumSq.
+    variance = avgSq;
+    mSumSq = variance * mCnt;
+  }
+
+  variance -= avgSq;
+  return sqrt(variance);
+}
+
+CachePerfStats::PerfData::PerfData()
+  : mFilteredAvg(50, true)
+  , mShortAvg(3, false)
+{
+}
+
+void
+CachePerfStats::PerfData::AddValue(uint32_t aValue, bool aShortOnly)
+{
+  if (!aShortOnly) {
+    mFilteredAvg.AddValue(aValue);
+  }
+  mShortAvg.AddValue(aValue);
+}
+
+uint32_t
+CachePerfStats::PerfData::GetAverage(bool aFiltered)
+{
+  return aFiltered ? mFilteredAvg.GetAverage() : mShortAvg.GetAverage();
+}
+
+uint32_t
+CachePerfStats::PerfData::GetStdDev(bool aFiltered)
+{
+  return aFiltered ? mFilteredAvg.GetStdDev() : mShortAvg.GetStdDev();
+}
+
+// static
+void
+CachePerfStats::AddValue(EDataType aType, uint32_t aValue, bool aShortOnly)
+{
+  StaticMutexAutoLock lock(sLock);
+  sData[aType].AddValue(aValue, aShortOnly);
+}
+
+// static
+uint32_t
+CachePerfStats::GetAverage(EDataType aType, bool aFiltered)
+{
+  StaticMutexAutoLock lock(sLock);
+  return sData[aType].GetAverage(aFiltered);
+}
+
+//static
+bool
+CachePerfStats::IsCacheSlow()
+{
+  // Compare mShortAvg with mFilteredAvg to find out whether cache is getting
+  // slower. Use only data about single IO operations because ENTRY_OPEN can be
+  // affected by more factors than a slow disk.
+  for (uint32_t i = 0; i < ENTRY_OPEN; ++i) {
+    uint32_t avgLong = sData[i].GetAverage(true);
+    if (avgLong == 0) {
+      // We have no perf data yet, skip this data type.
+      continue;
+    }
+    uint32_t avgShort = sData[i].GetAverage(false);
+    uint32_t stddevLong = sData[i].GetStdDev(true);
+    uint32_t maxdiff = (avgLong / 4) + (2 * stddevLong);
+
+    if (avgShort > avgLong + maxdiff) {
+      return true;
+    }
+  }
+
+  return false;
+}
+
 void
 FreeBuffer(void *aBuf) {
 #ifndef NS_FREE_PERMANENT_DATA
   if (CacheObserver::ShuttingDown()) {
     return;
   }
 #endif
 
--- a/netwerk/cache2/CacheFileUtils.h
+++ b/netwerk/cache2/CacheFileUtils.h
@@ -143,16 +143,81 @@ private:
 
   // Counter of samples that is compared against kTotalSamplesReportLimit.
   static uint32_t sRecordCnt;
  
   // Hit rate statistics for every cache size range.
   static HitRate sHRStats[kNumOfRanges];
 };
 
+class CachePerfStats {
+public:
+  enum EDataType {
+    IO_OPEN    = 0,
+    IO_READ    = 1,
+    IO_WRITE   = 2,
+    ENTRY_OPEN = 3,
+    LAST       = 4
+  };
+
+  static void     AddValue(EDataType aType, uint32_t aValue, bool aShortOnly);
+  static uint32_t GetAverage(EDataType aType, bool aFiltered);
+  static bool     IsCacheSlow();
+
+private:
+
+  // This class computes average and standard deviation, it returns an
+  // arithmetic avg and stddev until total number of values reaches mWeight.
+  // Then it returns modified moving average computed as follows:
+  //
+  //   avg = (1-a)*avg + a*value
+  //   avgsq = (1-a)*avgsq + a*value^2
+  //   stddev = sqrt(avgsq - avg^2)
+  //
+  //   where
+  //       avgsq is an average of the square of the values
+  //       a = 1 / weight
+  class MMA {
+  public:
+    MMA(uint32_t aTotalWeight, bool aFilter);
+
+    void     AddValue(uint32_t aValue);
+    uint32_t GetAverage();
+    uint32_t GetStdDev();
+
+  private:
+    uint64_t mSum;
+    uint64_t mSumSq;
+    uint32_t mCnt;
+    uint32_t mWeight;
+    bool     mFilter;
+  };
+
+  class PerfData {
+  public:
+    PerfData();
+
+    void     AddValue(uint32_t aValue, bool aShortOnly);
+    uint32_t GetAverage(bool aFiltered);
+    uint32_t GetStdDev(bool aFiltered);
+
+  private:
+    // Contains filtered data (i.e. times when we think the cache and disk was
+    // not busy) for a longer time.
+    MMA mFilteredAvg;
+
+    // Contains unfiltered average of few recent values.
+    MMA mShortAvg;
+  };
+
+  static StaticMutex sLock;
+
+  static PerfData sData[LAST];
+};
+
 void
 FreeBuffer(void *aBuf);
 
 nsresult
 ParseAlternativeDataInfo(const char *aInfo, int64_t *_offset, nsACString *_type);
 
 void
 BuildAlternativeDataInfo(const char *aInfo, int64_t aOffset, nsACString &_retval);
--- a/netwerk/cache2/CacheIOThread.cpp
+++ b/netwerk/cache2/CacheIOThread.cpp
@@ -229,16 +229,17 @@ CacheIOThread::CacheIOThread()
 , mThread(nullptr)
 , mXPCOMThread(nullptr)
 , mLowestLevelWaiting(LAST_LEVEL)
 , mCurrentlyExecutingLevel(0)
 , mHasXPCOMEvents(false)
 , mRerunCurrentEvent(false)
 , mShutdown(false)
 , mIOCancelableEvents(0)
+, mEventCounter(0)
 #ifdef DEBUG
 , mInsideLoop(true)
 #endif
 {
   for (uint32_t i = 0; i < LAST_LEVEL; ++i) {
     mQueueLength[i] = 0;
   }
 
@@ -486,16 +487,17 @@ loopStart:
         MonitorAutoUnlock unlock(mMonitor);
 
         bool processedEvent;
         nsresult rv;
         do {
           nsIThread *thread = mXPCOMThread;
           rv = thread->ProcessNextEvent(false, &processedEvent);
 
+          ++mEventCounter;
           MOZ_ASSERT(mBlockingIOWatcher);
           mBlockingIOWatcher->NotifyOperationDone();
         } while (NS_SUCCEEDED(rv) && processedEvent);
       }
 
       uint32_t level;
       for (level = 0; level < LAST_LEVEL; ++level) {
         if (!mEventQueue[level].Length()) {
@@ -571,16 +573,17 @@ void CacheIOThread::LoopOneLevel(uint32_
       mBlockingIOWatcher->NotifyOperationDone();
 
       if (mRerunCurrentEvent) {
         // The event handler yields to higher priority events and wants to rerun.
         returnEvents = true;
         break;
       }
 
+      ++mEventCounter;
       --mQueueLength[aLevel];
 
       // Release outside the lock.
       events[index] = nullptr;
     }
   }
 
   if (returnEvents)
--- a/netwerk/cache2/CacheIOThread.h
+++ b/netwerk/cache2/CacheIOThread.h
@@ -64,16 +64,18 @@ public:
   // Makes sure that any previously posted event to OPEN or OPEN_PRIORITY
   // levels (such as file opennings and dooms) are executed before aRunnable
   // that is intended to evict stuff from the cache.
   nsresult DispatchAfterPendingOpens(nsIRunnable* aRunnable);
   bool IsCurrentThread();
 
   uint32_t QueueSize(bool highPriority);
 
+  uint32_t EventCounter() const { return mEventCounter; }
+
   /**
    * Callable only on this thread, checks if there is an event waiting in
    * the event queue with a higher execution priority.  If so, the result
    * is true and the current event handler should break it's work and return
    * from Run() method immediately.  The event handler will be rerun again
    * when all more priority events are processed.  Events pending after this
    * handler (i.e. the one that called YieldAndRerun()) will not execute sooner
    * then this handler is executed w/o a call to YieldAndRerun().
@@ -131,16 +133,18 @@ private:
   bool mRerunCurrentEvent;
   // Signal to process all pending events and then shutdown
   // Synchronized by mMonitor
   bool mShutdown;
   // If > 0 there is currently an I/O operation on the thread that
   // can be canceled when after shutdown, see the Shutdown() method
   // for usage. Made a counter to allow nesting of the Cancelable class.
   Atomic<uint32_t, Relaxed> mIOCancelableEvents;
+  // Event counter that increases with every event processed.
+  Atomic<uint32_t, Relaxed> mEventCounter;
 #ifdef DEBUG
   bool mInsideLoop;
 #endif
 };
 
 } // namespace net
 } // namespace mozilla
 
--- a/netwerk/protocol/http/nsHttpChannel.cpp
+++ b/netwerk/protocol/http/nsHttpChannel.cpp
@@ -107,16 +107,17 @@
 #include "nsMixedContentBlocker.h"
 #include "HSTSPrimerListener.h"
 #include "CacheStorageService.h"
 #include "HttpChannelParent.h"
 #include "nsIBufferedStreams.h"
 #include "nsIFileStreams.h"
 #include "nsIMIMEInputStream.h"
 #include "nsIMultiplexInputStream.h"
+#include "../../cache2/CacheFileUtils.h"
 
 #ifdef MOZ_TASK_TRACER
 #include "GeckoTaskTracer.h"
 #endif
 
 namespace mozilla { namespace net {
 
 namespace {
@@ -4482,16 +4483,29 @@ nsHttpChannel::OnNormalCacheEntryAvailab
             return NS_ERROR_DOCUMENT_NOT_CACHED;
         }
     }
 
     if (NS_SUCCEEDED(aEntryStatus)) {
         mCacheEntry = aEntry;
         mCacheEntryIsWriteOnly = aNew;
 
+        if (!aNew && !mAsyncOpenTime.IsNull()) {
+            // We use microseconds for IO operations. For consistency let's use
+            // microseconds here too.
+            uint32_t duration = (TimeStamp::Now() - mAsyncOpenTime).ToMicroseconds();
+            bool isSlow = false;
+            if ((mCacheOpenWithPriority && mCacheQueueSizeWhenOpen >= sRCWNQueueSizePriority) ||
+                (!mCacheOpenWithPriority && mCacheQueueSizeWhenOpen >= sRCWNQueueSizeNormal)) {
+                isSlow = true;
+            }
+            CacheFileUtils::CachePerfStats::AddValue(
+                CacheFileUtils::CachePerfStats::ENTRY_OPEN, duration, isSlow);
+        }
+
         if (mLoadFlags & LOAD_INITIAL_DOCUMENT_URI) {
             Telemetry::Accumulate(Telemetry::HTTP_OFFLINE_CACHE_DOCUMENT_LOAD,
                                   false);
         }
     }
 
     return NS_OK;
 }
@@ -9184,34 +9198,40 @@ nsHttpChannel::MaybeRaceCacheWithNetwork
         return NS_OK;
     }
 
     // If a CORS Preflight is required we must not race.
     if (mRequireCORSPreflight && !mIsCorsPreflightDone) {
         return NS_OK;
     }
 
-    uint32_t threshold = mCacheOpenWithPriority ? sRCWNQueueSizePriority
-                                                : sRCWNQueueSizeNormal;
-    // No need to trigger to trigger the racing, since most likely the cache
-    // will be faster.
-    if (mCacheQueueSizeWhenOpen < threshold) {
-        return NS_OK;
+    uint32_t delay;
+    if (CacheFileUtils::CachePerfStats::IsCacheSlow()) {
+        // If the cache is slow, trigger the network request immediately.
+        delay = 0;
+    } else {
+        // Give cache a headstart of 3 times the average cache entry open time.
+        delay = CacheFileUtils::CachePerfStats::GetAverage(
+                CacheFileUtils::CachePerfStats::ENTRY_OPEN, true) * 3;
+        // We use microseconds in CachePerfStats but we need milliseconds
+        // for TriggerNetwork.
+        delay /= 1000;
     }
 
     MOZ_ASSERT(sRCWNEnabled, "The pref must be truned on.");
-    LOG(("nsHttpChannel::MaybeRaceCacheWithNetwork [this=%p]\n", this));
+    LOG(("nsHttpChannel::MaybeRaceCacheWithNetwork [this=%p, delay=%u]\n",
+         this, delay));
 
     if (!mOnCacheAvailableCalled) {
         // If the network was triggered before onCacheEntryAvailable was
         // called, it means we are racing the network with the cache.
         mRaceCacheWithNetwork = true;
     }
 
-    return TriggerNetwork(0);
+    return TriggerNetwork(delay);
 }
 
 NS_IMETHODIMP
 nsHttpChannel::Test_triggerNetwork(int32_t aTimeout)
 {
     MOZ_ASSERT(NS_IsMainThread(), "Must be called on the main thread");
     if (!mOnCacheAvailableCalled) {
         // If the network was triggered before onCacheEntryAvailable was