Bug 1133177 - Network logging and cleanups (part 1). r=hurley, a=lmandel
authorPatrick McManus <mcmanus@ducksong.com>
Thu, 19 Feb 2015 12:21:03 -0500
changeset 250105 f321e120f8e1
parent 250104 dd1511c04aad
child 250106 1c270f40087a
push id4502
push userryanvm@gmail.com
push date2015-02-27 21:16 +0000
treeherdermozilla-beta@9fb3cc1f7ff6 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewershurley, lmandel
bugs1133177
milestone37.0
Bug 1133177 - Network logging and cleanups (part 1). r=hurley, a=lmandel
netwerk/protocol/http/nsHttpChannel.cpp
netwerk/protocol/http/nsHttpConnectionMgr.cpp
netwerk/protocol/http/nsHttpTransaction.cpp
netwerk/protocol/http/nsHttpTransaction.h
--- a/netwerk/protocol/http/nsHttpChannel.cpp
+++ b/netwerk/protocol/http/nsHttpChannel.cpp
@@ -781,23 +781,20 @@ nsHttpChannel::SetupTransaction()
             }
         }
     }
 
     // create wrapper for this channel's notification callbacks
     nsCOMPtr<nsIInterfaceRequestor> callbacks;
     NS_NewNotificationCallbacksAggregation(mCallbacks, mLoadGroup,
                                            getter_AddRefs(callbacks));
-    if (!callbacks)
-        return NS_ERROR_OUT_OF_MEMORY;
 
     // create the transaction object
     mTransaction = new nsHttpTransaction();
-    if (!mTransaction)
-        return NS_ERROR_OUT_OF_MEMORY;
+    LOG(("nsHttpChannel %p created nsHttpTransaction %p\n", this, mTransaction.get()));
 
     // See bug #466080. Transfer LOAD_ANONYMOUS flag to socket-layer.
     if (mLoadFlags & LOAD_ANONYMOUS)
         mCaps |= NS_HTTP_LOAD_ANONYMOUS;
 
     if (mTimingEnabled)
         mCaps |= NS_HTTP_TIMING_ENABLED;
 
--- a/netwerk/protocol/http/nsHttpConnectionMgr.cpp
+++ b/netwerk/protocol/http/nsHttpConnectionMgr.cpp
@@ -1685,20 +1685,22 @@ nsHttpConnectionMgr::IsUnderPressure(nsC
 //   not remain in the pending queue
 nsresult
 nsHttpConnectionMgr::TryDispatchTransaction(nsConnectionEntry *ent,
                                             bool onlyReusedConnection,
                                             nsHttpTransaction *trans)
 {
     MOZ_ASSERT(PR_GetCurrentThread() == gSocketThread);
     LOG(("nsHttpConnectionMgr::TryDispatchTransaction without conn "
-         "[trans=%p ci=%s caps=%x wildcardok=%d onlyreused=%d]\n",
-         trans, ent->mConnInfo->HashKey().get(),
+         "[trans=%p ci=%p ci=%s caps=%x wildcardok=%d onlyreused=%d "
+         "active=%d idle=%d]\n", trans,
+         ent->mConnInfo.get(), ent->mConnInfo->HashKey().get(),
          uint32_t(trans->Caps()), !trans->DontRouteViaWildCard(),
-         onlyReusedConnection));
+         onlyReusedConnection, ent->mActiveConns.Length(),
+         ent->mIdleConns.Length()));
 
     nsHttpTransaction::Classifier classification = trans->Classification();
     uint32_t caps = trans->Caps();
 
     // no keep-alive means no pipelines either
     if (!(caps & NS_HTTP_ALLOW_KEEPALIVE))
         caps = caps & ~NS_HTTP_ALLOW_PIPELINING;
 
@@ -1743,17 +1745,18 @@ nsHttpConnectionMgr::TryDispatchTransact
     if (!(caps & NS_HTTP_LOAD_AS_BLOCKING)) {
         if (!(caps & NS_HTTP_LOAD_UNBLOCKED)) {
             nsILoadGroupConnectionInfo *loadGroupCI = trans->LoadGroupConnectionInfo();
             if (loadGroupCI) {
                 uint32_t blockers = 0;
                 if (NS_SUCCEEDED(loadGroupCI->GetBlockingTransactionCount(&blockers)) &&
                     blockers) {
                     // need to wait for blockers to clear
-                    LOG(("   blocked by load group: [blockers=%d]\n", blockers));
+                    LOG(("   blocked by load group: [lgci=%p trans=%p blockers=%d]\n",
+                         loadGroupCI, trans, blockers));
                     return NS_ERROR_NOT_AVAILABLE;
                 }
             }
         }
     } else {
         // Mark the transaction and its load group as blocking right now to prevent
         // other transactions from being reordered in the queue due to slow syns.
         trans->DispatchedAsBlocking();
@@ -1761,33 +1764,34 @@ nsHttpConnectionMgr::TryDispatchTransact
 
     // step 1
     // If connection pressure, then we want to favor pipelining of any kind
     if (IsUnderPressure(ent, classification) && !attemptedOptimisticPipeline) {
         attemptedOptimisticPipeline = true;
         if (AddToShortestPipeline(ent, trans,
                                   classification,
                                   mMaxOptimisticPipelinedRequests)) {
+            LOG(("   dispatched step 1 trans=%p\n", trans));
             return NS_OK;
         }
     }
 
     // Subject most transactions at high parallelism to rate pacing.
     // It will only be actually submitted to the
     // token bucket once, and if possible it is granted admission synchronously.
     // It is important to leave a transaction in the pending queue when blocked by
     // pacing so it can be found on cancel if necessary.
     // Transactions that cause blocking or bypass it (e.g. js/css) are not rate
     // limited.
     if (gHttpHandler->UseRequestTokenBucket() &&
         (mNumActiveConns >= mNumSpdyActiveConns) && // just check for robustness sake
         ((mNumActiveConns - mNumSpdyActiveConns) >= gHttpHandler->RequestTokenBucketMinParallelism()) &&
         !(caps & (NS_HTTP_LOAD_AS_BLOCKING | NS_HTTP_LOAD_UNBLOCKED))) {
         if (!trans->TryToRunPacedRequest()) {
-            LOG(("   blocked due to rate pacing\n"));
+            LOG(("   blocked due to rate pacing trans=%p\n", trans));
             return NS_ERROR_NOT_AVAILABLE;
         }
     }
 
     // step 2
     // consider an idle persistent connection
     if (caps & NS_HTTP_ALLOW_KEEPALIVE) {
         nsRefPtr<nsHttpConnection> conn;
@@ -1814,65 +1818,71 @@ nsHttpConnectionMgr::TryDispatchTransact
             // sure that we are not pruning dead connections anymore.
             ConditionallyStopPruneDeadConnectionsTimer();
         }
         if (conn) {
             // This will update the class of the connection to be the class of
             // the transaction dispatched on it.
             AddActiveConn(conn, ent);
             DispatchTransaction(ent, trans, conn);
+            LOG(("   dispatched step 2 (idle) trans=%p\n", trans));
             return NS_OK;
         }
     }
 
     // step 3
     // consider pipelining scripts and revalidations
     if (!attemptedOptimisticPipeline &&
         (classification == nsHttpTransaction::CLASS_REVALIDATION ||
          classification == nsHttpTransaction::CLASS_SCRIPT)) {
         attemptedOptimisticPipeline = true;
         if (AddToShortestPipeline(ent, trans,
                                   classification,
                                   mMaxOptimisticPipelinedRequests)) {
+            LOG(("   dispatched step 3 (pipeline) trans=%p\n", trans));
             return NS_OK;
         }
     }
 
     // step 4
     if (!onlyReusedConnection) {
         nsresult rv = MakeNewConnection(ent, trans);
         if (NS_SUCCEEDED(rv)) {
             // this function returns NOT_AVAILABLE for asynchronous connects
+            LOG(("   dispatched step 4 (async new conn) trans=%p\n", trans));
             return NS_ERROR_NOT_AVAILABLE;
         }
 
         if (rv != NS_ERROR_NOT_AVAILABLE) {
             // not available return codes should try next step as they are
             // not hard errors. Other codes should stop now
+            LOG(("   failed step 4 (%x) trans=%p\n", rv, trans));
             return rv;
         }
     }
 
     // step 5
     if (caps & NS_HTTP_ALLOW_PIPELINING) {
         if (AddToShortestPipeline(ent, trans,
                                   classification,
                                   mMaxPipelinedRequests)) {
+            LOG(("   dispatched step 5 trans=%p\n", trans));
             return NS_OK;
         }
     }
 
     // step 6
     if (unusedSpdyPersistentConnection) {
         // to avoid deadlocks, we need to throw away this perfectly valid SPDY
         // connection to make room for a new one that can service a no KEEPALIVE
         // request
         unusedSpdyPersistentConnection->DontReuse();
     }
 
+    LOG(("   not dispatched (queued) trans=%p\n", trans));
     return NS_ERROR_NOT_AVAILABLE;                /* queue it */
 }
 
 nsresult
 nsHttpConnectionMgr::DispatchTransaction(nsConnectionEntry *ent,
                                          nsHttpTransaction *trans,
                                          nsHttpConnection *conn)
 {
--- a/netwerk/protocol/http/nsHttpTransaction.cpp
+++ b/netwerk/protocol/http/nsHttpTransaction.cpp
@@ -1751,64 +1751,74 @@ nsHttpTransaction::CancelPipeline(uint32
     mConnection->CancelPipeline(NS_ERROR_ABORT);
 
     // Avoid pipelining this transaction on restart by classifying it as solo.
     // This also prevents BadUnexpectedLarge from being reported more
     // than one time per transaction.
     mClassification = CLASS_SOLO;
 }
 
+
+void
+nsHttpTransaction::SetLoadGroupConnectionInfo(nsILoadGroupConnectionInfo *aLoadGroupCI)
+{
+    LOG(("nsHttpTransaction %p SetLoadGroupConnectionInfo %p\n", this, aLoadGroupCI));
+    mLoadGroupCI = aLoadGroupCI;
+}
+
 // Called when the transaction marked for blocking is associated with a connection
 // (i.e. added to a new h1 conn, an idle http connection, or placed into
 // a http pipeline). It is safe to call this multiple times with it only
 // having an effect once.
 void
 nsHttpTransaction::DispatchedAsBlocking()
 {
     if (mDispatchedAsBlocking)
         return;
 
     LOG(("nsHttpTransaction %p dispatched as blocking\n", this));
 
     if (!mLoadGroupCI)
         return;
 
-    LOG(("nsHttpTransaction adding blocking channel %p from "
+    LOG(("nsHttpTransaction adding blocking transaction %p from "
          "loadgroup %p\n", this, mLoadGroupCI.get()));
 
     mLoadGroupCI->AddBlockingTransaction();
     mDispatchedAsBlocking = true;
 }
 
 void
 nsHttpTransaction::RemoveDispatchedAsBlocking()
 {
     if (!mLoadGroupCI || !mDispatchedAsBlocking)
         return;
 
     uint32_t blockers = 0;
     nsresult rv = mLoadGroupCI->RemoveBlockingTransaction(&blockers);
 
-    LOG(("nsHttpTransaction removing blocking channel %p from "
+    LOG(("nsHttpTransaction removing blocking transaction %p from "
          "loadgroup %p. %d blockers remain.\n", this,
          mLoadGroupCI.get(), blockers));
 
     if (NS_SUCCEEDED(rv) && !blockers) {
-        LOG(("nsHttpTransaction %p triggering release of blocked channels.\n",
-             this));
+        LOG(("nsHttpTransaction %p triggering release of blocked channels "
+             " with loadgroupci=%p\n", this, mLoadGroupCI.get()));
         gHttpHandler->ConnMgr()->ProcessPendingQ();
     }
 
     mDispatchedAsBlocking = false;
 }
 
 void
 nsHttpTransaction::ReleaseBlockingTransaction()
 {
     RemoveDispatchedAsBlocking();
+    LOG(("nsHttpTransaction %p loadgroupci set to null "
+         "in ReleaseBlockingTransaction() - was %p\n", this, mLoadGroupCI.get()));
     mLoadGroupCI = nullptr;
 }
 
 void
 nsHttpTransaction::DisableSpdy()
 {
     mCaps |= NS_HTTP_DISALLOW_SPDY;
     if (mConnInfo) {
--- a/netwerk/protocol/http/nsHttpTransaction.h
+++ b/netwerk/protocol/http/nsHttpTransaction.h
@@ -128,17 +128,17 @@ public:
 
     // Sets mPendingTime to the current time stamp or to a null time stamp (if now is false)
     void SetPendingTime(bool now = true) { mPendingTime = now ? TimeStamp::Now() : TimeStamp(); }
     const TimeStamp GetPendingTime() { return mPendingTime; }
     bool UsesPipelining() const { return mCaps & NS_HTTP_ALLOW_PIPELINING; }
 
     // overload of nsAHttpTransaction::LoadGroupConnectionInfo()
     nsILoadGroupConnectionInfo *LoadGroupConnectionInfo() MOZ_OVERRIDE { return mLoadGroupCI.get(); }
-    void SetLoadGroupConnectionInfo(nsILoadGroupConnectionInfo *aLoadGroupCI) { mLoadGroupCI = aLoadGroupCI; }
+    void SetLoadGroupConnectionInfo(nsILoadGroupConnectionInfo *aLoadGroupCI);
     void DispatchedAsBlocking();
     void RemoveDispatchedAsBlocking();
 
     nsHttpTransaction *QueryHttpTransaction() MOZ_OVERRIDE { return this; }
 
     Http2PushedStream *GetPushedStream() { return mPushedStream; }
     Http2PushedStream *TakePushedStream()
     {