Bug 1371700 - Some added network logs for better tracking, r=mcmanus
authorHonza Bambas <honzab.moz@firemni.cz>
Wed, 12 Jul 2017 08:44:00 +0200
changeset 608365 a20b3deaa51dd6bb82842e93341a6c966bab98cf
parent 608364 13a9e2bbb96ac089ee2fabd2f02c9f7e1fcbc5a0
child 608366 ff324c369c9cbaf010b7e8bd6b93348e5d378a03
push id68249
push userbmo:rail@mozilla.com
push dateThu, 13 Jul 2017 14:21:35 +0000
reviewersmcmanus
bugs1371700
milestone56.0a1
Bug 1371700 - Some added network logs for better tracking, r=mcmanus
netwerk/base/RequestContextService.cpp
netwerk/protocol/http/Http2Stream.cpp
netwerk/protocol/http/nsHttpConnectionMgr.cpp
netwerk/protocol/http/nsHttpTransaction.cpp
--- a/netwerk/base/RequestContextService.cpp
+++ b/netwerk/base/RequestContextService.cpp
@@ -7,23 +7,28 @@
 #include "nsAutoPtr.h"
 #include "nsIObserverService.h"
 #include "nsIXULRuntime.h"
 #include "nsServiceManagerUtils.h"
 #include "nsThreadUtils.h"
 #include "RequestContextService.h"
 
 #include "mozilla/Atomics.h"
+#include "mozilla/Logging.h"
 #include "mozilla/Services.h"
 
 #include "mozilla/net/PSpdyPush.h"
 
 namespace mozilla {
 namespace net {
 
+LazyLogModule gRequestContextLog("RequestContext");
+#undef LOG
+#define LOG(args) MOZ_LOG(gRequestContextLog, LogLevel::Info, args)
+
 // nsIRequestContext
 class RequestContext final : public nsIRequestContext
 {
 public:
   NS_DECL_THREADSAFE_ISUPPORTS
   NS_DECL_NSIREQUESTCONTEXT
 
   explicit RequestContext(const uint64_t id);
@@ -37,42 +42,49 @@ private:
 };
 
 NS_IMPL_ISUPPORTS(RequestContext, nsIRequestContext)
 
 RequestContext::RequestContext(const uint64_t aID)
   : mID(aID)
   , mBlockingTransactionCount(0)
 {
+  LOG(("RequestContext::RequestContext this=%p id=%" PRIx64, this, mID));
 }
 
 RequestContext::~RequestContext()
 {
+  LOG(("RequestContext::~RequestContext this=%p blockers=%u",
+       this, static_cast<uint32_t>(mBlockingTransactionCount)));
 }
 
 NS_IMETHODIMP
 RequestContext::GetBlockingTransactionCount(uint32_t *aBlockingTransactionCount)
 {
   NS_ENSURE_ARG_POINTER(aBlockingTransactionCount);
   *aBlockingTransactionCount = mBlockingTransactionCount;
   return NS_OK;
 }
 
 NS_IMETHODIMP
 RequestContext::AddBlockingTransaction()
 {
   mBlockingTransactionCount++;
+  LOG(("RequestContext::AddBlockingTransaction this=%p blockers=%u",
+       this, static_cast<uint32_t>(mBlockingTransactionCount)));
   return NS_OK;
 }
 
 NS_IMETHODIMP
 RequestContext::RemoveBlockingTransaction(uint32_t *outval)
 {
   NS_ENSURE_ARG_POINTER(outval);
   mBlockingTransactionCount--;
+  LOG(("RequestContext::RemoveBlockingTransaction this=%p blockers=%u",
+       this, static_cast<uint32_t>(mBlockingTransactionCount)));
   *outval = mBlockingTransactionCount;
   return NS_OK;
 }
 
 NS_IMETHODIMP
 RequestContext::GetSpdyPushCache(mozilla::net::SpdyPushCache **aSpdyPushCache)
 {
   *aSpdyPushCache = mSpdyCache.get();
@@ -215,8 +227,10 @@ RequestContextService::Observe(nsISuppor
     Shutdown();
   }
 
   return NS_OK;
 }
 
 } // ::mozilla::net
 } // ::mozilla
+
+#undef LOG
--- a/netwerk/protocol/http/Http2Stream.cpp
+++ b/netwerk/protocol/http/Http2Stream.cpp
@@ -101,16 +101,18 @@ Http2Stream::Http2Stream(nsAHttpTransact
   MOZ_ASSERT(httpPriority >= 0);
   SetPriority(static_cast<uint32_t>(httpPriority));
 }
 
 Http2Stream::~Http2Stream()
 {
   ClearTransactionsBlockedOnTunnel();
   mStreamID = Http2Session::kDeadStreamID;
+
+  LOG3(("Http2Stream::~Http2Stream %p", this));
 }
 
 // ReadSegments() is used to write data down the socket. Generally, HTTP
 // request data is pulled from the approriate transaction and
 // converted to HTTP/2 data. Sometimes control data like a window-update is
 // generated instead.
 
 nsresult
--- a/netwerk/protocol/http/nsHttpConnectionMgr.cpp
+++ b/netwerk/protocol/http/nsHttpConnectionMgr.cpp
@@ -911,46 +911,46 @@ nsHttpConnectionMgr::DispatchPendingQ(ns
     nsresult rv;
     bool dispatchedSuccessfully = false;
 
     // if !considerAll iterate the pending list until one is dispatched successfully.
     // Keep iterating afterwards only until a transaction fails to dispatch.
     // if considerAll == true then try and dispatch all items.
     for (uint32_t i = 0; i < pendingQ.Length(); ) {
         pendingTransInfo = pendingQ[i];
-        LOG(("nsHttpConnectionMgr::ProcessPendingQForEntry "
+        LOG(("nsHttpConnectionMgr::DispatchPendingQ "
              "[trans=%p, halfOpen=%p, activeConn=%p]\n",
              pendingTransInfo->mTransaction.get(),
              pendingTransInfo->mHalfOpen.get(),
              pendingTransInfo->mActiveConn.get()));
 
         // When this transaction has already established a half-open
         // connection, we want to prevent any duplicate half-open
         // connections from being established and bound to this
         // transaction. Allow only use of an idle persistent connection
         // (if found) for transactions referred by a half-open connection.
         bool alreadyHalfOpenOrWaitingForTLS = false;
         if (pendingTransInfo->mHalfOpen) {
             MOZ_ASSERT(!pendingTransInfo->mActiveConn);
             RefPtr<nsHalfOpenSocket> halfOpen =
                 do_QueryReferent(pendingTransInfo->mHalfOpen);
-            LOG(("nsHttpConnectionMgr::ProcessPendingQForEntry "
+            LOG(("nsHttpConnectionMgr::DispatchPendingQ "
                  "[trans=%p, halfOpen=%p]\n",
                  pendingTransInfo->mTransaction.get(), halfOpen.get()));
             if (halfOpen) {
                 alreadyHalfOpenOrWaitingForTLS = true;
             } else {
                 // If we have not found the halfOpen socket, remove the pointer.
                 pendingTransInfo->mHalfOpen = nullptr;
             }
         }  else if (pendingTransInfo->mActiveConn) {
             MOZ_ASSERT(!pendingTransInfo->mHalfOpen);
             RefPtr<nsHttpConnection> activeConn =
                 do_QueryReferent(pendingTransInfo->mActiveConn);
-            LOG(("nsHttpConnectionMgr::ProcessPendingQForEntry "
+            LOG(("nsHttpConnectionMgr::DispatchPendingQ "
                  "[trans=%p, activeConn=%p]\n",
                  pendingTransInfo->mTransaction.get(), activeConn.get()));
             // Check if this transaction claimed a connection that is still
             // performing tls handshake with a NullHttpTransaction or it is between
             // finishing tls and reclaiming (When nullTrans finishes tls handshake,
             // httpConnection does not have a transaction any more and a
             // ReclaimConnection is dispatched). But if an error occurred the
             // connection will be closed, it will exist but CanReused will be
@@ -1024,16 +1024,30 @@ nsHttpConnectionMgr::ProcessPendingQForE
 
     LOG(("nsHttpConnectionMgr::ProcessPendingQForEntry "
          "[ci=%s ent=%p active=%" PRIuSIZE " idle=%" PRIuSIZE " urgent-start-queue=%" PRIuSIZE
          " queued=%" PRIuSIZE "]\n",
          ent->mConnInfo->HashKey().get(), ent, ent->mActiveConns.Length(),
          ent->mIdleConns.Length(), ent->mUrgentStartQ.Length(),
          ent->PendingQLength()));
 
+    if (LOG_ENABLED()) {
+      LOG(("urgent queue ["));
+      for (auto info : ent->mUrgentStartQ) {
+        LOG(("  %p", info->mTransaction.get()));
+      }
+      for (auto it = ent->mPendingTransactionTable.Iter(); !it.Done(); it.Next()) {
+        LOG(("] window id = %" PRIx64 " queue [", it.Key()));
+        for (auto info : *it.UserData()) {
+          LOG(("  %p", info->mTransaction.get()));
+        }
+      }
+      LOG(("]"));
+    }
+
     if (!ent->mUrgentStartQ.Length() && !ent->PendingQLength()) {
         return false;
     }
     ProcessSpdyPendingQ(ent);
 
     bool dispatchedSuccessfully = false;
 
     if (!ent->mUrgentStartQ.IsEmpty()) {
@@ -2619,17 +2633,16 @@ nsHttpConnectionMgr::OnMsgDoShiftReloadC
     if (ci)
         ResetIPFamilyPreference(ci);
 }
 
 void
 nsHttpConnectionMgr::OnMsgReclaimConnection(int32_t, ARefBase *param)
 {
     MOZ_ASSERT(OnSocketThread(), "not on socket thread");
-    LOG(("nsHttpConnectionMgr::OnMsgReclaimConnection [conn=%p]\n", param));
 
     nsHttpConnection *conn = static_cast<nsHttpConnection *>(param);
 
     //
     // 1) remove the connection from the active list
     // 2) if keep-alive, add connection to idle list
     // 3) post event to process the pending transaction queue
     //
@@ -2645,16 +2658,18 @@ nsHttpConnectionMgr::OnMsgReclaimConnect
         LOG(("nsHttpConnectionMgr::OnMsgReclaimConnection conn %p "
              "forced new hash entry %s\n",
              conn, conn->ConnectionInfo()->HashKey().get()));
     }
 
     MOZ_ASSERT(ent);
     RefPtr<nsHttpConnectionInfo> ci(ent->mConnInfo);
 
+    LOG(("nsHttpConnectionMgr::OnMsgReclaimConnection [ent=%p conn=%p]\n", ent, conn));
+
     // If the connection is in the active list, remove that entry
     // and the reference held by the mActiveConns list.
     // This is never the final reference on conn as the event context
     // is also holding one that is released at the end of this function.
 
     if (conn->EverUsedSpdy()) {
         // Spdy connections aren't reused in the traditional HTTP way in
         // the idleconns list, they are actively multplexed as active
@@ -2779,16 +2794,18 @@ nsHttpConnectionMgr::OnMsgUpdateParam(in
     default:
         NS_NOTREACHED("unexpected parameter name");
     }
 }
 
 // nsHttpConnectionMgr::nsConnectionEntry
 nsHttpConnectionMgr::nsConnectionEntry::~nsConnectionEntry()
 {
+    LOG(("nsConnectionEntry::~nsConnectionEntry this=%p", this));
+
     MOZ_DIAGNOSTIC_ASSERT(!mIdleConns.Length());
     MOZ_DIAGNOSTIC_ASSERT(!mActiveConns.Length());
     MOZ_DIAGNOSTIC_ASSERT(!mHalfOpens.Length());
     MOZ_DIAGNOSTIC_ASSERT(!mUrgentStartQ.Length());
     MOZ_DIAGNOSTIC_ASSERT(!PendingQLength());
     MOZ_DIAGNOSTIC_ASSERT(!mHalfOpenFastOpenBackups.Length());
     MOZ_DIAGNOSTIC_ASSERT(!mDoNotDestroy);
 
@@ -4726,16 +4743,19 @@ nsConnectionEntry::nsConnectionEntry(nsH
     , mUsingSpdy(false)
     , mPreferIPv4(false)
     , mPreferIPv6(false)
     , mUsedForConnection(false)
     , mDoNotDestroy(false)
 {
     MOZ_COUNT_CTOR(nsConnectionEntry);
     mUseFastOpen = gHttpHandler->UseFastOpen();
+
+    LOG(("nsConnectionEntry::nsConnectionEntry this=%p key=%s",
+         this, ci->HashKey().get()));
 }
 
 bool
 nsHttpConnectionMgr::nsConnectionEntry::AvailableForDispatchNow()
 {
     if (mIdleConns.Length() && mIdleConns[0]->CanReuse()) {
         return true;
     }
@@ -4922,18 +4942,18 @@ nsConnectionEntry::AppendPendingQForFocu
             countToAppend;
 
     result.InsertElementsAt(result.Length(),
                             infoArray->Elements(),
                             countToAppend);
     infoArray->RemoveElementsAt(0, countToAppend);
 
     LOG(("nsConnectionEntry::AppendPendingQForFocusedWindow [ci=%s], "
-         "pendingQ count=%" PRIuSIZE " for focused window (id=%" PRIu64 ")\n",
-         mConnInfo->HashKey().get(), result.Length(),
+         "pendingQ count=%" PRIuSIZE " window.count=%" PRIuSIZE " for focused window (id=%" PRIu64 ")\n",
+         mConnInfo->HashKey().get(), result.Length(), infoArray->Length(),
          windowId));
 }
 
 void
 nsHttpConnectionMgr::
 nsConnectionEntry::AppendPendingQForNonFocusedWindows(
     uint64_t windowId,
     nsTArray<RefPtr<PendingTransactionInfo>> &result,
--- a/netwerk/protocol/http/nsHttpTransaction.cpp
+++ b/netwerk/protocol/http/nsHttpTransaction.cpp
@@ -237,16 +237,17 @@ nsHttpTransaction::Init(uint32_t caps,
     LOG(("nsHttpTransaction::Init [this=%p caps=%x]\n", this, caps));
 
     MOZ_ASSERT(cinfo);
     MOZ_ASSERT(requestHead);
     MOZ_ASSERT(target);
     MOZ_ASSERT(NS_IsMainThread());
 
     mTopLevelOuterContentWindowId = topLevelOuterContentWindowId;
+    LOG(("  window-id = %" PRIx64, mTopLevelOuterContentWindowId));
 
     mActivityDistributor = services::GetActivityDistributor();
     if (!mActivityDistributor) {
         return NS_ERROR_NOT_AVAILABLE;
     }
 
     bool activityDistributorActive;
     rv = mActivityDistributor->GetIsActive(&activityDistributorActive);
@@ -1832,18 +1833,21 @@ nsHttpTransaction::DispatchedAsBlocking(
 
     mRequestContext->AddBlockingTransaction();
     mDispatchedAsBlocking = true;
 }
 
 void
 nsHttpTransaction::RemoveDispatchedAsBlocking()
 {
-    if (!mRequestContext || !mDispatchedAsBlocking)
+    if (!mRequestContext || !mDispatchedAsBlocking) {
+        LOG(("nsHttpTransaction::RemoveDispatchedAsBlocking this=%p not blocking",
+             this));
         return;
+    }
 
     uint32_t blockers = 0;
     nsresult rv = mRequestContext->RemoveBlockingTransaction(&blockers);
 
     LOG(("nsHttpTransaction removing blocking transaction %p from "
          "request context %p. %d blockers remain.\n", this,
          mRequestContext.get(), blockers));