bug 603514 - http stalled read detection r=honzab
authorPatrick McManus <mcmanus@ducksong.com>
Tue, 20 Mar 2012 13:11:32 -0400
changeset 89855 57c69b1e9dcf9d4f837458a0e48bc08a39739ba2
parent 89854 89ff973f27e6ec45894615261130f8a08d446aa1
child 89856 8dbf8965bac9082a120ae56e2229765528355259
push id22293
push usermlamouri@mozilla.com
push dateWed, 21 Mar 2012 10:30:54 +0000
treeherdermozilla-central@f10862ac3217 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewershonzab
bugs603514
milestone14.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 603514 - http stalled read detection r=honzab When a connection that involves a pipelined transaction has been stalled (i.e. idle with an open transaction, not an idle persistent connection) for a second move any transactions that are pipelined after the current one onto different connections (and implicitly close this connection when done with the current transaction). when it has been stalled for 10 seconds (pref configurable), cancel the current transaction itself too - depending on its state it can hopefully be restarted on a clean connection.
modules/libpref/src/init/all.js
netwerk/protocol/http/SpdySession.h
netwerk/protocol/http/nsAHttpTransaction.h
netwerk/protocol/http/nsHttpConnection.cpp
netwerk/protocol/http/nsHttpConnection.h
netwerk/protocol/http/nsHttpConnectionMgr.cpp
netwerk/protocol/http/nsHttpHandler.cpp
netwerk/protocol/http/nsHttpHandler.h
netwerk/protocol/http/nsHttpPipeline.cpp
netwerk/protocol/http/nsHttpPipeline.h
--- a/modules/libpref/src/init/all.js
+++ b/modules/libpref/src/init/all.js
@@ -809,16 +809,17 @@ pref("network.http.proxy.pipelining", fa
 pref("network.http.pipelining.maxrequests" , 32);
 
 // An optimistic request is one pipelined when policy might allow a new
 // connection instead
 pref("network.http.pipelining.max-optimistic-requests" , 4);
 
 pref("network.http.pipelining.aggressive", false);
 pref("network.http.pipelining.maxsize" , 300000);
+pref("network.http.pipelining.read-timeout", 10000);
 
 // Prompt for 307 redirects
 pref("network.http.prompt-temp-redirect", true);
 
 // If true generate CORRUPTED_CONTENT errors for entities that
 // contain an invalid Assoc-Req response header
 pref("network.http.assoc-req.enforce", false);
 
--- a/netwerk/protocol/http/SpdySession.h
+++ b/netwerk/protocol/http/SpdySession.h
@@ -72,17 +72,17 @@ public:
 
   SpdySession(nsAHttpTransaction *, nsISocketTransport *, PRInt32);
   ~SpdySession();
 
   bool AddStream(nsAHttpTransaction *, PRInt32);
   bool CanReuse() { return !mShouldGoAway && !mClosed; }
   bool RoomForMoreStreams();
 
-  // When the connection is active this is called every 15 seconds
+  // When the connection is active this is called every 1 second
   void ReadTimeoutTick(PRIntervalTime now);
   
   // Idle time represents time since "goodput".. e.g. a data or header frame
   PRIntervalTime IdleTime();
 
   PRUint32 RegisterStreamID(SpdyStream *);
 
   const static PRUint8 kFlag_Control   = 0x80;
--- a/netwerk/protocol/http/nsAHttpTransaction.h
+++ b/netwerk/protocol/http/nsAHttpTransaction.h
@@ -43,16 +43,17 @@
 
 class nsAHttpConnection;
 class nsAHttpSegmentReader;
 class nsAHttpSegmentWriter;
 class nsIInterfaceRequestor;
 class nsIEventTarget;
 class nsITransport;
 class nsHttpRequestHead;
+class nsHttpPipeline;
 
 //----------------------------------------------------------------------------
 // Abstract base class for a HTTP transaction:
 //
 // A transaction is a "sink" for the response data.  The connection pushes
 // data to the transaction by writing to it.  The transaction supports
 // WriteSegments and may refuse to accept data if its buffers are full (its
 // write function returns NS_BASE_STREAM_WOULD_BLOCK in this case).
@@ -128,16 +129,21 @@ public:
     virtual PRUint32 PipelineDepth() = 0;
 
     // Used to inform the connection that it is being used in a pipelined
     // context. That may influence the handling of some errors.
     // The value is the pipeline position (> 1).
     virtual nsresult SetPipelinePosition(PRInt32) = 0;
     virtual PRInt32  PipelinePosition() = 0;
 
+    // If we used rtti this would be the result of doing
+    // dynamic_cast<nsHttpPipeline *>(this).. i.e. it can be nsnull for
+    // non pipeline implementations of nsAHttpTransaction
+    virtual nsHttpPipeline *QueryPipeline() { return nsnull; }
+    
     // Every transaction is classified into one of the types below. When using
     // HTTP pipelines, only transactions with the same type appear on the same
     // pipeline.
     enum Classifier  {
         // Transactions that expect a short 304 (no-content) response
         CLASS_REVALIDATION,
 
         // Transactions for content expected to be CSS or JS
--- a/netwerk/protocol/http/nsHttpConnection.cpp
+++ b/netwerk/protocol/http/nsHttpConnection.cpp
@@ -954,18 +954,66 @@ nsHttpConnection::ReadTimeoutTick(PRInte
 
     // Spdy in the future actually should implement some timeout handling
     // using the SPDY ping frame.
     if (mSpdySession) {
         mSpdySession->ReadTimeoutTick(now);
         return;
     }
     
-    // Pending patches places pipeline rescheduling code will go here
+    PRIntervalTime delta = PR_IntervalNow() - mLastReadTime;
+
+    // we replicate some of the checks both here and in OnSocketReadable() as
+    // they will be discovered under different conditions. The ones here
+    // will generally be discovered if we are totally hung and OSR does
+    // not get called at all, however OSR discovers them with lower latency
+    // if the issue is just very slow (but not stalled) reading.
+    //
+    // Right now we only take action if pipelining is involved, but this would
+    // be the place to add general read timeout handling if it is desired.
+
+    const PRIntervalTime k1000ms = PR_MillisecondsToInterval(1000);
+
+    if (delta < k1000ms)
+        return;
+
+    PRUint32 pipelineDepth = mTransaction->PipelineDepth();
+
+    // this just reschedules blocked transactions. no transaction
+    // is aborted completely.
+    LOG(("cancelling pipeline due to a %ums stall - depth %d\n",
+         PR_IntervalToMilliseconds(delta), pipelineDepth));
 
+    if (pipelineDepth > 1) {
+        nsHttpPipeline *pipeline = mTransaction->QueryPipeline();
+        NS_ABORT_IF_FALSE(pipeline, "pipelinedepth > 1 without pipeline");
+        // code this defensively for the moment and check for null in opt build
+        if (pipeline)
+            pipeline->CancelPipeline(NS_ERROR_NET_TIMEOUT);
+    }
+    
+    if (delta < gHttpHandler->GetPipelineTimeout())
+        return;
+
+    if (pipelineDepth <= 1 && !mTransaction->PipelinePosition())
+        return;
+    
+    // nothing has transpired on this pipelined socket for many
+    // seconds. Call that a total stall and close the transaction.
+    // There is a chance the transaction will be restarted again
+    // depending on its state.. that will come back araound
+    // without pipelining on, so this won't loop.
+
+    LOG(("canceling transaction stalled for %ums on a pipeline"
+         "of depth %d and scheduled originally at pos %d\n",
+         PR_IntervalToMilliseconds(delta),
+         pipelineDepth, mTransaction->PipelinePosition()));
+
+    // This will also close the connection
+    CloseTransaction(mTransaction, NS_ERROR_NET_TIMEOUT);
 }
 
 void
 nsHttpConnection::GetSecurityInfo(nsISupports **secinfo)
 {
     NS_ASSERTION(PR_GetCurrentThread() == gSocketThread, "wrong thread");
 
     if (mSocketTransport) {
@@ -1281,18 +1329,30 @@ nsHttpConnection::OnSocketReadable()
         delta -= mRtt;
     else
         delta = 0;
 
     const PRIntervalTime k400ms  = PR_MillisecondsToInterval(400);
     const PRIntervalTime k1200ms = PR_MillisecondsToInterval(1200);
 
     if (delta > k1200ms) {
+        LOG(("Read delta ms of %u causing slow read major "
+             "event and pipeline cancellation",
+             PR_IntervalToMilliseconds(delta)));
+
         gHttpHandler->ConnMgr()->PipelineFeedbackInfo(
             mConnInfo, nsHttpConnectionMgr::BadSlowReadMajor, this, 0);
+
+        if (mTransaction->PipelineDepth() > 1) {
+            nsHttpPipeline *pipeline = mTransaction->QueryPipeline();
+            NS_ABORT_IF_FALSE(pipeline, "pipelinedepth > 1 without pipeline");
+            // code this defensively for the moment and check for null
+            if (pipeline)
+                pipeline->CancelPipeline(NS_ERROR_NET_TIMEOUT);
+        }
     }
     else if (delta > k400ms) {
         gHttpHandler->ConnMgr()->PipelineFeedbackInfo(
             mConnInfo, nsHttpConnectionMgr::BadSlowReadMinor, this, 0);
     }
 
     mLastReadTime = now;
 
--- a/netwerk/protocol/http/nsHttpConnection.h
+++ b/netwerk/protocol/http/nsHttpConnection.h
@@ -162,25 +162,28 @@ public:
     // connection pool, the nsHttpConnection still reads errors and hangups
     // on the socket so that it can be proactively released if the server
     // initiates a termination. Only call on socket thread.
     void BeginIdleMonitoring();
     void EndIdleMonitoring();
 
     bool UsingSpdy() { return mUsingSpdy; }
 
-    // When the connection is active this is called every 15 seconds
+    // When the connection is active this is called every 1 second
     void  ReadTimeoutTick(PRIntervalTime now);
 
     nsAHttpTransaction::Classifier Classification() { return mClassification; }
     void Classify(nsAHttpTransaction::Classifier newclass)
     {
         mClassification = newclass;
     }
 
+    // When the connection is active this is called every second
+    void  ReadTimeoutTick();
+
 private:
     // called to cause the underlying socket to start speaking SSL
     nsresult ProxyStartSSL();
 
     nsresult OnTransactionDone(nsresult reason);
     nsresult OnSocketWritable();
     nsresult OnSocketReadable();
 
--- a/netwerk/protocol/http/nsHttpConnectionMgr.cpp
+++ b/netwerk/protocol/http/nsHttpConnectionMgr.cpp
@@ -1933,22 +1933,16 @@ nsHttpConnectionMgr::OnMsgProcessFeedbac
 
 void
 nsHttpConnectionMgr::ActivateTimeoutTick()
 {
     NS_ABORT_IF_FALSE(PR_GetCurrentThread() == gSocketThread, "wrong thread");
     LOG(("nsHttpConnectionMgr::ActivateTimeoutTick() "
          "this=%p mReadTimeoutTick=%p\n"));
 
-    // right now the spdy timeout code is the only thing hooked to the timeout
-    // tick, so disable it if spdy is not being used. However pipelining code
-    // will also want this functionality soon.
-    if (!gHttpHandler->IsSpdyEnabled())
-        return;
-
     // The timer tick should be enabled if it is not already pending.
     // Upon running the tick will rearm itself if there are active
     // connections available.
 
     if (mReadTimeoutTick && mReadTimeoutTickArmed)
         return;
 
     if (!mReadTimeoutTick) {
@@ -1956,18 +1950,17 @@ nsHttpConnectionMgr::ActivateTimeoutTick
         if (!mReadTimeoutTick) {
             NS_WARNING("failed to create timer for http timeout management");
             return;
         }
     }
 
     NS_ABORT_IF_FALSE(!mReadTimeoutTickArmed, "timer tick armed");
     mReadTimeoutTickArmed = true;
-    // pipeline will expect a 1000ms granuality
-    mReadTimeoutTick->Init(this, 15000, nsITimer::TYPE_REPEATING_SLACK);
+    mReadTimeoutTick->Init(this, 1000, nsITimer::TYPE_REPEATING_SLACK);
 }
 
 void
 nsHttpConnectionMgr::ReadTimeoutTick()
 {
     NS_ABORT_IF_FALSE(PR_GetCurrentThread() == gSocketThread, "wrong thread");
     NS_ABORT_IF_FALSE(mReadTimeoutTick, "no readtimeout tick");
 
--- a/netwerk/protocol/http/nsHttpHandler.cpp
+++ b/netwerk/protocol/http/nsHttpHandler.cpp
@@ -184,16 +184,17 @@ nsHttpHandler::nsHttpHandler()
     , mMaxConnections(24)
     , mMaxConnectionsPerServer(8)
     , mMaxPersistentConnectionsPerServer(2)
     , mMaxPersistentConnectionsPerProxy(4)
     , mMaxPipelinedRequests(32)
     , mMaxOptimisticPipelinedRequests(4)
     , mPipelineAggressive(false)
     , mMaxPipelineObjectSize(300000)
+    , mPipelineReadTimeout(PR_MillisecondsToInterval(10000))
     , mRedirectionLimit(10)
     , mPhishyUserPassLength(1)
     , mQoSBits(0x00)
     , mPipeliningOverSSL(false)
     , mEnforceAssocReq(false)
     , mInPrivateBrowsingMode(PRIVATE_BROWSING_UNKNOWN)
     , mLastUniqueID(NowInSeconds())
     , mSessionStartTime(0)
@@ -1048,16 +1049,24 @@ nsHttpHandler::PrefsChanged(nsIPrefBranc
     if (PREF_CHANGED(HTTP_PREF("pipelining.maxsize"))) {
         rv = prefs->GetIntPref(HTTP_PREF("pipelining.maxsize"), &val);
         if (NS_SUCCEEDED(rv)) {
             mMaxPipelineObjectSize =
                 static_cast<PRInt64>(clamped(val, 1000, 100000000));
         }
     }
 
+    if (PREF_CHANGED(HTTP_PREF("pipelining.read-timeout"))) {
+        rv = prefs->GetIntPref(HTTP_PREF("pipelining.read-timeout"), &val);
+        if (NS_SUCCEEDED(rv)) {
+            mPipelineReadTimeout =
+                PR_MillisecondsToInterval(clamped(val, 500, 0xffff));
+        }
+    }
+
     if (PREF_CHANGED(HTTP_PREF("pipelining.ssl"))) {
         rv = prefs->GetBoolPref(HTTP_PREF("pipelining.ssl"), &cVar);
         if (NS_SUCCEEDED(rv))
             mPipeliningOverSSL = cVar;
     }
 
     if (PREF_CHANGED(HTTP_PREF("proxy.pipelining"))) {
         rv = prefs->GetBoolPref(HTTP_PREF("proxy.pipelining"), &cVar);
--- a/netwerk/protocol/http/nsHttpHandler.h
+++ b/netwerk/protocol/http/nsHttpHandler.h
@@ -232,16 +232,17 @@ public:
     static nsresult GenerateHostPort(const nsCString& host, PRInt32 port,
                                      nsCString& hostLine);
 
     bool GetPipelineAggressive()     { return mPipelineAggressive; }
     void GetMaxPipelineObjectSize(PRInt64 &outVal)
     {
         outVal = mMaxPipelineObjectSize;
     }
+    PRIntervalTime GetPipelineTimeout()   { return mPipelineReadTimeout; }
 
 private:
 
     //
     // Useragent/prefs helper methods
     //
     void     BuildUserAgent();
     void     InitUserAgentComponents();
@@ -294,16 +295,18 @@ private:
     PRUint8  mMaxConnectionsPerServer;
     PRUint8  mMaxPersistentConnectionsPerServer;
     PRUint8  mMaxPersistentConnectionsPerProxy;
     PRUint16 mMaxPipelinedRequests;
     PRUint16 mMaxOptimisticPipelinedRequests;
     bool     mPipelineAggressive;
     PRInt64  mMaxPipelineObjectSize;
 
+    PRIntervalTime mPipelineReadTimeout;
+
     PRUint8  mRedirectionLimit;
 
     // we'll warn the user if we load an URL containing a userpass field
     // unless its length is less than this threshold.  this warning is
     // intended to protect the user against spoofing attempts that use
     // the userpass field of the URL to obscure the actual origin server.
     PRUint8  mPhishyUserPassLength;
 
--- a/netwerk/protocol/http/nsHttpPipeline.cpp
+++ b/netwerk/protocol/http/nsHttpPipeline.cpp
@@ -170,16 +170,22 @@ PRInt32
 nsHttpPipeline::PipelinePosition()
 {
     nsAHttpTransaction *trans = Response(0);
     if (trans)
         return trans->PipelinePosition();
     return 2;
 }
 
+nsHttpPipeline *
+nsHttpPipeline::QueryPipeline()
+{
+    return this;
+}
+
 //-----------------------------------------------------------------------------
 // nsHttpPipeline::nsISupports
 //-----------------------------------------------------------------------------
 
 NS_IMPL_THREADSAFE_ADDREF(nsHttpPipeline)
 NS_IMPL_THREADSAFE_RELEASE(nsHttpPipeline)
 
 // multiple inheritance fun :-)
--- a/netwerk/protocol/http/nsHttpPipeline.h
+++ b/netwerk/protocol/http/nsHttpPipeline.h
@@ -77,16 +77,19 @@ private:
     nsAHttpTransaction *Response(PRInt32 i)
     {
         if (mResponseQ.Length() == 0)
             return nsnull;
 
         return mResponseQ[i];
     }
 
+    // overload of nsAHttpTransaction::QueryPipeline()
+    nsHttpPipeline *QueryPipeline();
+
     nsAHttpConnection            *mConnection;
     nsTArray<nsAHttpTransaction*> mRequestQ;  // array of transactions
     nsTArray<nsAHttpTransaction*> mResponseQ; // array of transactions
     nsresult                      mStatus;
 
     // these flags indicate whether or not the first request or response
     // is partial.  a partial request means that Request(0) has been 
     // partially written out to the socket.  a partial response means