bug 868441 Bypass Cache when lock held too long r=novotny

modules/libpref/src/init/all.js

@@ -999,6 +999,10 @@ pref("network.http.rendering-critical-requests-prioritization", true);
 // IPv6 connectivity.
 pref("network.http.fast-fallback-to-IPv4", true);
 
+// The maximum amount of time the cache session lock can be held
+// before a new transaction bypasses the cache. In milliseconds.
+pref("network.http.bypass-cachelock-threshold", 250);
+
 // Try and use SPDY when using SSL
 pref("network.http.spdy.enabled", true);
 pref("network.http.spdy.enabled.v2", true);

netwerk/cache/nsCacheService.cpp

@@ -1071,12 +1071,13 @@ private:
  *****************************************************************************/
 nsCacheService *   nsCacheService::gService = nullptr;
 
-NS_IMPL_THREADSAFE_ISUPPORTS1(nsCacheService, nsICacheService)
+NS_IMPL_THREADSAFE_ISUPPORTS2(nsCacheService, nsICacheService, nsICacheServiceInternal)
 
 nsCacheService::nsCacheService()
     : mObserver(nullptr),
       mLock("nsCacheService.mLock"),
       mCondVar(mLock, "nsCacheService.mCondVar"),
+      mTimeStampLock("nsCacheService.mTimeStampLock"),
       mInitialized(false),
       mClearingEntries(false),
       mEnableMemoryDevice(true),
@@ -1528,6 +1529,24 @@ NS_IMETHODIMP nsCacheService::GetCacheIOTarget(nsIEventTarget * *aCacheIOTarget)
     return rv;
 }
 
+/* nsICacheServiceInternal
+ * readonly attribute double lockHeldTime;
+*/
+NS_IMETHODIMP nsCacheService::GetLockHeldTime(double *aLockHeldTime)
+{
+    MutexAutoLock lock(mTimeStampLock);
+
+    if (mLockAcquiredTimeStamp.IsNull()) {
+        *aLockHeldTime = 0.0;
+    }
+    else {
+        *aLockHeldTime = 
+            (TimeStamp::Now() - mLockAcquiredTimeStamp).ToMilliseconds();
+    }
+
+    return NS_OK;
+}
+
 /**
  * Internal Methods
  */
@@ -2597,6 +2616,20 @@ nsCacheService::OnDataSizeChange(nsCacheEntry * entry, int32_t deltaSize)
     return device->OnDataSizeChange(entry, deltaSize);
 }
 
+void
+nsCacheService::LockAcquired()
+{
+    MutexAutoLock lock(mTimeStampLock);
+    mLockAcquiredTimeStamp = TimeStamp::Now();
+}
+
+void
+nsCacheService::LockReleased()
+{
+    MutexAutoLock lock(mTimeStampLock);
+    mLockAcquiredTimeStamp = TimeStamp();
+}
+
 void
 nsCacheService::Lock(mozilla::Telemetry::ID mainThreadLockerID)
 {
@@ -2615,6 +2648,7 @@ nsCacheService::Lock(mozilla::Telemetry::ID mainThreadLockerID)
     MOZ_EVENT_TRACER_WAIT(nsCacheService::gService, "net::cache::lock");
 
     gService->mLock.Lock();
+    gService->LockAcquired();
 
     TimeStamp stop(TimeStamp::Now());
     MOZ_EVENT_TRACER_EXEC(nsCacheService::gService, "net::cache::lock");
@@ -2635,6 +2669,7 @@ nsCacheService::Unlock()
     nsTArray<nsISupports*> doomed;
     doomed.SwapElements(gService->mDoomedObjects);
 
+    gService->LockReleased();
     gService->mLock.Unlock();
 
     MOZ_EVENT_TRACER_DONE(nsCacheService::gService, "net::cache::lock");

netwerk/cache/nsCacheService.h

@@ -61,11 +61,12 @@ private:
  *  nsCacheService
  ******************************************************************************/
 
-class nsCacheService : public nsICacheService
+class nsCacheService : public nsICacheServiceInternal
 {
 public:
     NS_DECL_ISUPPORTS
     NS_DECL_NSICACHESERVICE
+    NS_DECL_NSICACHESERVICEINTERNAL
 
     nsCacheService();
     virtual ~nsCacheService();
@@ -239,6 +240,8 @@ private:
 
     static void      Lock(::mozilla::Telemetry::ID mainThreadLockerID);
     static void      Unlock();
+    void             LockAcquired();
+    void             LockReleased();
 
     nsresult         CreateDiskDevice();
     nsresult         CreateOfflineDevice();
@@ -324,6 +327,9 @@ private:
     mozilla::Mutex                  mLock;
     mozilla::CondVar                mCondVar;
 
+    mozilla::Mutex                  mTimeStampLock;
+    mozilla::TimeStamp              mLockAcquiredTimeStamp;
+
     nsCOMPtr<nsIThread>             mCacheIOThread;
 
     nsTArray<nsISupports*>          mDoomedObjects;

netwerk/cache/nsICacheService.idl

@@ -67,3 +67,19 @@ interface nsICacheService : nsISupports
  */
 #define NS_CACHESERVICE_EMPTYCACHE_TOPIC_ID "cacheservice:empty-cache"
 %}
+
+[scriptable, builtinclass, uuid(d0fc8d38-db80-4928-bf1c-b0085ddfa9dc)]
+interface nsICacheServiceInternal : nsICacheService
+{
+    /**
+     * This is an internal interface. It changes so frequently that it probably
+     * went away while you were reading this.
+     */
+
+    /**
+     * Milliseconds for which the service lock has been held. 0 if unlocked.
+     */
+    readonly attribute double lockHeldTime;
+};
+
+

netwerk/protocol/http/nsHttpChannel.cpp

@@ -407,7 +407,7 @@ nsHttpChannel::Connect()
         return NS_ERROR_DOCUMENT_NOT_CACHED;
     }
 
-    if (!gHttpHandler->UseCache())
+    if (ShouldSkipCache())
         return ContinueConnect();
 
     // open a cache entry for this channel...
@@ -5998,6 +5998,52 @@ nsHttpChannel::UpdateAggregateCallbacks()
     mTransaction->SetSecurityCallbacks(callbacks);
 }
 
+bool
+nsHttpChannel::ShouldSkipCache()
+{
+    if (!gHttpHandler->UseCache())
+        return true;
+
+    if (mLoadFlags & LOAD_ONLY_FROM_CACHE)
+        return false;
+    
+    if (mChooseApplicationCache || (mLoadFlags & LOAD_CHECK_OFFLINE_CACHE))
+        return false;
+
+    TimeStamp cacheSkippedUntil = gHttpHandler->GetCacheSkippedUntil();
+    if (!cacheSkippedUntil.IsNull()) {
+        TimeStamp now = TimeStamp::Now();
+        if (now < cacheSkippedUntil) {
+            LOG(("channel=%p Cache bypassed because of dampener\n", this));
+            return true;
+        }
+        LOG(("channel=%p Cache dampener released\n", this));
+        gHttpHandler->ClearCacheSkippedUntil();
+    }
+
+    // If the cache lock has been held for a long time then just
+    // bypass the cache instead of getting in that queue.
+    nsCOMPtr<nsICacheService> cacheService =
+        do_GetService(NS_CACHESERVICE_CONTRACTID);
+    nsCOMPtr<nsICacheServiceInternal> internalCacheService =
+        do_QueryInterface(cacheService);
+    if (!internalCacheService)
+        return false;
+    
+    double timeLocked;
+    if (NS_FAILED(internalCacheService->GetLockHeldTime(&timeLocked)))
+        return false;
+    
+    if (timeLocked <= gHttpHandler->BypassCacheLockThreshold())
+        return false;
+
+    LOG(("Cache dampener installed because service lock held too long [%fms]\n",
+         timeLocked));
+    cacheSkippedUntil = TimeStamp::Now() + TimeDuration::FromSeconds(60);
+    gHttpHandler->SetCacheSkippedUntil(cacheSkippedUntil);
+    return true;
+}
+
 NS_IMETHODIMP
 nsHttpChannel::SetLoadGroup(nsILoadGroup *aLoadGroup)
 {

netwerk/protocol/http/nsHttpChannel.h

@@ -280,6 +280,9 @@ private:
     // and ensure the transaction is updated to use it.
     void UpdateAggregateCallbacks();
 
+    // Disk cache is skipped for some requests when it is behaving slowly
+    bool ShouldSkipCache();
+
 private:
     nsCOMPtr<nsISupports>             mSecurityInfo;
     nsCOMPtr<nsICancelable>           mProxyRequest;

netwerk/protocol/http/nsHttpHandler.cpp

@@ -188,6 +188,7 @@ nsHttpHandler::nsHttpHandler()
     , mSpdyPingThreshold(PR_SecondsToInterval(58))
     , mSpdyPingTimeout(PR_SecondsToInterval(8))
     , mConnectTimeout(90000)
+    , mBypassCacheLockThreshold(250.0)
     , mParallelSpeculativeConnectLimit(6)
     , mRequestTokenBucketEnabled(true)
     , mRequestTokenBucketMinParallelism(6)
@@ -1175,6 +1176,16 @@ nsHttpHandler::PrefsChanged(nsIPrefBranch *prefs, const char *pref)
             mConnectTimeout = clamped(val, 1, 0xffff) * PR_MSEC_PER_SEC;
     }
 
+    // The maximum amount of time the cache session lock can be held
+    // before a new transaction bypasses the cache. In milliseconds.
+    if (PREF_CHANGED(HTTP_PREF("bypass-cachelock-threshold"))) {
+        rv = prefs->GetIntPref(HTTP_PREF("bypass-cachelock-threshold"), &val);
+        if (NS_SUCCEEDED(rv))
+            // the pref and variable are both in milliseconds
+            mBypassCacheLockThreshold =
+                static_cast<double>(clamped(val, 0, 0x7ffffff));
+    }
+
     // The maximum number of current global half open sockets allowable
     // for starting a new speculative connection.
     if (PREF_CHANGED(HTTP_PREF("speculative-parallel-limit"))) {

netwerk/protocol/http/nsHttpHandler.h

@@ -106,6 +106,7 @@ public:
     uint32_t       ConnectTimeout()  { return mConnectTimeout; }
     uint32_t       ParallelSpeculativeConnectLimit() { return mParallelSpeculativeConnectLimit; }
     bool           CritialRequestPrioritization() { return mCritialRequestPrioritization; }
+    double         BypassCacheLockThreshold() { return mBypassCacheLockThreshold; }
 
     bool           UseRequestTokenBucket() { return mRequestTokenBucketEnabled; }
     uint16_t       RequestTokenBucketMinParallelism() { return mRequestTokenBucketMinParallelism; }
@@ -271,6 +272,13 @@ public:
             uint32_t appId,
             bool inBrowser,
             nsACString& sessionName);
+
+    // When the disk cache is responding slowly its use is suppressed
+    // for 1 minute for most requests. Callable from main thread only.
+    mozilla::TimeStamp GetCacheSkippedUntil() { return mCacheSkippedUntil; }
+    void SetCacheSkippedUntil(mozilla::TimeStamp arg) { mCacheSkippedUntil = arg; }
+    void ClearCacheSkippedUntil() { mCacheSkippedUntil = mozilla::TimeStamp(); }
+
 private:
 
     //
@@ -417,6 +425,10 @@ private:
     // established. In milliseconds.
     uint32_t       mConnectTimeout;
 
+    // The maximum amount of time the nsICacheSession lock can be held
+    // before a new transaction bypasses the cache. In milliseconds.
+    double         mBypassCacheLockThreshold;
+
     // The maximum number of current global half open sockets allowable
     // when starting a new speculative connection.
     uint32_t       mParallelSpeculativeConnectLimit;
@@ -432,6 +444,10 @@ private:
     // while those elements load.
     bool           mCritialRequestPrioritization;
 
+    // When the disk cache is responding slowly its use is suppressed
+    // for 1 minute for most requests.
+    mozilla::TimeStamp                mCacheSkippedUntil;
+
 private:
     // For Rate Pacing Certain Network Events. Only assign this pointer on
     // socket thread.