bug 1133177 - network logging and cleanups (part 1) r=hurley
authorPatrick McManus <mcmanus@ducksong.com>
Thu, 19 Feb 2015 12:21:03 -0500
changeset 258769 f34ddbf1e4908fea90f4109875bfe9cddf3f4391
parent 258768 39354f436e2b7d5ecde0b7fbbdfbc1fe797c12be
child 258770 b465cd661b6beb01fc6e76d35ad5b80b66747082
push id721
push userjlund@mozilla.com
push dateTue, 21 Apr 2015 23:03:33 +0000
treeherdermozilla-release@d27c9211ebb3 [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewershurley
bugs1133177
milestone38.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 1133177 - network logging and cleanups (part 1) r=hurley
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
@@ -786,23 +786,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
@@ -1729,20 +1729,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;
 
@@ -1787,17 +1789,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();
@@ -1805,33 +1808,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;
@@ -1858,65 +1862,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
@@ -1753,64 +1753,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()
     {