Bug 938803 - Improve DNS debugs to show which path is taken in nsHostResolver::ResolveHost r=mcmanus
authorSteve Workman <sworkman@mozilla.com>
Thu, 21 Nov 2013 13:35:44 -0800
changeset 156958 5c5453914a2078cd5a155f1926ede5ed2af5ea1b
parent 156957 ce06d56e593f5408987c44e3811784fbec1878fd
child 156959 53c776c1b69198f9dfcdcfff315e991b55ad8de2
push id25694
push usercbook@mozilla.com
push dateFri, 22 Nov 2013 13:45:11 +0000
treeherdermozilla-central@9a179f9b33ca [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersmcmanus
bugs938803
milestone28.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 938803 - Improve DNS debugs to show which path is taken in nsHostResolver::ResolveHost r=mcmanus
netwerk/base/src/nsSocketTransport2.cpp
netwerk/dns/nsHostResolver.cpp
netwerk/protocol/http/nsHttpChannel.cpp
--- a/netwerk/base/src/nsSocketTransport2.cpp
+++ b/netwerk/base/src/nsSocketTransport2.cpp
@@ -967,17 +967,20 @@ nsSocketTransport::SendStatus(nsresult s
     }
     if (sink)
         sink->OnTransportStatus(this, status, progress, UINT64_MAX);
 }
 
 nsresult
 nsSocketTransport::ResolveHost()
 {
-    SOCKET_LOG(("nsSocketTransport::ResolveHost [this=%p]\n", this));
+    SOCKET_LOG(("nsSocketTransport::ResolveHost [this=%p %s:%d%s]\n",
+                this, SocketHost().get(), SocketPort(),
+                mConnectionFlags & nsSocketTransport::BYPASS_CACHE ?
+                " bypass cache" : ""));
 
     nsresult rv;
 
     if (!mProxyHost.IsEmpty()) {
         if (!mProxyTransparent || mProxyTransparentResolvesHost) {
 #if defined(XP_UNIX) || defined(XP_OS2)
             NS_ABORT_IF_FALSE(!mNetAddrIsSet || mNetAddr.raw.family != AF_LOCAL,
                               "Unix domain sockets can't be used with proxies");
--- a/netwerk/dns/nsHostResolver.cpp
+++ b/netwerk/dns/nsHostResolver.cpp
@@ -512,17 +512,18 @@ nsHostResolver::MoveQueue(nsHostRecord *
 nsresult
 nsHostResolver::ResolveHost(const char            *host,
                             uint16_t               flags,
                             uint16_t               af,
                             nsResolveHostCallback *callback)
 {
     NS_ENSURE_TRUE(host && *host, NS_ERROR_UNEXPECTED);
 
-    LOG(("Resolving host [%s].\n", host));
+    LOG(("Resolving host [%s]%s.\n",
+         host, flags & RES_BYPASS_CACHE ? " - bypassing cache" : ""));
 
     // ensure that we are working with a valid hostname before proceeding.  see
     // bug 304904 for details.
     if (!net_IsValidHostName(nsDependentCString(host)))
         return NS_ERROR_UNKNOWN_HOST;
 
     // if result is set inside the lock, then we need to issue the
     // callback before returning.
@@ -547,67 +548,76 @@ nsHostResolver::ResolveHost(const char  
             // and return.  otherwise, add ourselves as first pending
             // callback, and proceed to do the lookup.
 
             nsHostKey key = { host, flags, af };
             nsHostDBEnt *he = static_cast<nsHostDBEnt *>
                                          (PL_DHashTableOperate(&mDB, &key, PL_DHASH_ADD));
 
             // if the record is null, then HostDB_InitEntry failed.
-            if (!he || !he->rec)
+            if (!he || !he->rec) {
+                LOG(("  Out of memory: no cache entry for [%s].\n", host));
                 rv = NS_ERROR_OUT_OF_MEMORY;
+            }
             // do we have a cached result that we can reuse?
             else if (!(flags & RES_BYPASS_CACHE) &&
                      he->rec->HasUsableResult(flags) &&
                      TimeStamp::NowLoRes() <= (he->rec->expiration + TimeDuration::FromSeconds(mGracePeriod * 60))) {
-                LOG(("Using cached record for host [%s].\n", host));
+                LOG(("  Using cached record for host [%s].\n", host));
                 // put reference to host record on stack...
                 result = he->rec;
                 Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2, METHOD_HIT);
 
                 // For entries that are in the grace period with a failed connect,
                 // or all cached negative entries, use the cache but start a new
                 // lookup in the background
                 ConditionallyRefreshRecord(he->rec, host);
                 
                 if (he->rec->negative) {
+                    LOG(("  Negative cache entry for[%s].\n", host));
                     Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                           METHOD_NEGATIVE_HIT);
                     status = NS_ERROR_UNKNOWN_HOST;
                 }
             }
             // if the host name is an IP address literal and has been parsed,
             // go ahead and use it.
             else if (he->rec->addr) {
+                LOG(("  Using cached address for IP Literal [%s].\n", host));
                 Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                       METHOD_LITERAL);
                 result = he->rec;
             }
             // try parsing the host name as an IP address literal to short
             // circuit full host resolution.  (this is necessary on some
             // platforms like Win9x.  see bug 219376 for more details.)
             else if (PR_StringToNetAddr(host, &tempAddr) == PR_SUCCESS) {
+                LOG(("  Host is IP Literal [%s].\n", host));
                 // ok, just copy the result into the host record, and be done
                 // with it! ;-)
                 he->rec->addr = new NetAddr();
                 PRNetAddrToNetAddr(&tempAddr, he->rec->addr);
                 // put reference to host record on stack...
                 Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                       METHOD_LITERAL);
                 result = he->rec;
             }
             else if (mPendingCount >= MAX_NON_PRIORITY_REQUESTS &&
                      !IsHighPriority(flags) &&
                      !he->rec->resolving) {
+                LOG(("  Lookup queue full: dropping %s priority request for "
+                     "[%s].\n",
+                     IsMediumPriority(flags) ? "medium" : "low", host));
                 Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                       METHOD_OVERFLOW);
                 // This is a lower priority request and we are swamped, so refuse it.
                 rv = NS_ERROR_DNS_LOOKUP_QUEUE_FULL;
             }
             else if (flags & RES_OFFLINE) {
+                LOG(("  Offline request for [%s]; ignoring.\n", host));
                 rv = NS_ERROR_OFFLINE;
             }
 
             // If this is an IPV4 or IPV6 specific request, check if there is
             // an AF_UNSPEC entry we can use. Otherwise, hit the resolver...
             else if (!he->rec->resolving) {
                 if (!(flags & RES_BYPASS_CACHE) &&
                     ((af == PR_AF_INET) || (af == PR_AF_INET6))) {
@@ -619,19 +629,18 @@ nsHostResolver::ResolveHost(const char  
                                  (PL_DHASH_ENTRY_IS_BUSY(unspecHe) &&
                                   unspecHe->rec),
                                 "Valid host entries should contain a record");
                     if (PL_DHASH_ENTRY_IS_BUSY(unspecHe) &&
                         unspecHe->rec &&
                         unspecHe->rec->HasUsableResult(flags) &&
                         TimeStamp::NowLoRes() <= (he->rec->expiration +
                             TimeDuration::FromSeconds(mGracePeriod * 60))) {
-                        LOG(("Specific DNS request (%s) for an unspecified "
-                             "cached record",
-                            (af == PR_AF_INET) ? "AF_INET" : "AF_INET6"));
+                        LOG(("  Trying AF_UNSPEC entry for [%s] af: %s.\n",
+                            host, (af == PR_AF_INET) ? "AF_INET" : "AF_INET6"));
 
                         // Search for any valid address in the AF_UNSPEC entry
                         // in the cache (not blacklisted and from the right
                         // family).
                         NetAddrElement *addrIter =
                             unspecHe->rec->addr_info->mAddresses.getFirst();
                         he->rec->addr_info = nullptr;
                         while (addrIter) {
@@ -653,46 +662,49 @@ nsHostResolver::ResolveHost(const char  
                                                   METHOD_HIT);
                             ConditionallyRefreshRecord(he->rec, host);
                         }
                         // For AF_INET6, a new lookup means another AF_UNSPEC
                         // lookup. We have already iterated through the
                         // AF_UNSPEC addresses, so we mark this record as
                         // negative.
                         else if (af == PR_AF_INET6) {
+                            LOG(("  No AF_INET6 in AF_UNSPEC entry: "
+                                 "[%s] unknown host", host));
                             result = he->rec;
                             he->rec->negative = true;
                             status = NS_ERROR_UNKNOWN_HOST;
                             Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                                   METHOD_NEGATIVE_HIT);
                         }
                     }
                 }
                 // If no valid address was found in the cache or this is an
                 // AF_UNSPEC request, then start a new lookup.
                 if (!result) {
-                    LOG(("No valid address was found in the cache for the "
-                         "requested IP family"));
+                    LOG(("  No usable address in cache for [%s]", host));
                     // Add callback to the list of pending callbacks.
                     PR_APPEND_LINK(callback, &he->rec->callbacks);
                     he->rec->flags = flags;
-                    IssueLookup(he->rec);
+                    rv = IssueLookup(he->rec);
                     Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                           METHOD_NETWORK_FIRST);
                     if (NS_FAILED(rv)) {
                         PR_REMOVE_AND_INIT_LINK(callback);
                     }
                     else {
-                        LOG(("DNS lookup for host [%s] blocking pending "
-                             "'getaddrinfo' query.", host));
+                        LOG(("  DNS lookup for host [%s] blocking pending "
+                             "'getaddrinfo' query: callback [%p]",
+                             host, callback));
                     }
                 }
             }
             else {
-                // The record is being resolved. Append our callback.
+                LOG(("  Host [%s] is being resolved. Appending callback [%p].",
+                     host, callback));
                 PR_APPEND_LINK(callback, &he->rec->callbacks);
                 if (he->rec->onQueue) {
                     Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                                           METHOD_NETWORK_SHARED);
 
                     // Consider the case where we are on a pending queue of
                     // lower priority than the request is being made at.
                     // In that case we should upgrade to the higher queue.
@@ -777,17 +789,17 @@ nsHostResolver::ConditionallyCreateThrea
         if (!thr) {
             mThreadCount--;
             NS_RELEASE_THIS();
             return NS_ERROR_OUT_OF_MEMORY;
         }
     }
 #if defined(PR_LOGGING)
     else
-      LOG(("Unable to find a thread for looking up host [%s].\n", rec->host));
+      LOG(("  Unable to find a thread for looking up host [%s].\n", rec->host));
 #endif
     return NS_OK;
 }
 
 nsresult
 nsHostResolver::IssueLookup(nsHostRecord *rec)
 {
     MOZ_EVENT_TRACER_WAIT(rec, "net::dns::resolve");
@@ -813,32 +825,32 @@ nsHostResolver::IssueLookup(nsHostRecord
         PR_APPEND_LINK(rec, &mLowQ);
     mPendingCount++;
     
     rec->resolving = true;
     rec->onQueue = true;
 
     rv = ConditionallyCreateThread(rec);
     
-    LOG (("DNS thread counters: total=%d any-live=%d idle=%d pending=%d\n",
+    LOG (("  DNS thread counters: total=%d any-live=%d idle=%d pending=%d\n",
           mThreadCount,
           mActiveAnyThreadCount,
           mNumIdleThreads,
           mPendingCount));
 
     return rv;
 }
 
 nsresult
 nsHostResolver::ConditionallyRefreshRecord(nsHostRecord *rec, const char *host)
 {
     if ((((TimeStamp::NowLoRes() > rec->expiration) &&
         rec->mBlacklistedItems.Length()) ||
         rec->negative) && !rec->resolving) {
-        LOG(("Using %s cache entry for host [%s] but starting async renewal.",
+        LOG(("  Using %s cache entry for host [%s] but starting async renewal.",
             rec->negative ? "negative" :"positive", host));
         IssueLookup(rec);
 
         if (!rec->negative) {
             // negative entries are constantly being refreshed, only
             // track positive grace period induced renewals
             Telemetry::Accumulate(Telemetry::DNS_LOOKUP_METHOD2,
                 METHOD_RENEWAL);
@@ -1048,29 +1060,30 @@ nsHostResolver::CancelAsyncRequest(const
             }
         }
     }
 }
 
 void
 nsHostResolver::ThreadFunc(void *arg)
 {
-    LOG(("DNS lookup thread starting execution.\n"));
+    LOG(("DNS lookup thread - starting execution.\n"));
 
     static nsThreadPoolNaming naming;
     naming.SetThreadPoolName(NS_LITERAL_CSTRING("DNS Resolver"));
 
 #if defined(RES_RETRY_ON_FAILURE)
     nsResState rs;
 #endif
     nsHostResolver *resolver = (nsHostResolver *)arg;
     nsHostRecord *rec;
     PRAddrInfo *prai = nullptr;
     while (resolver->GetHostToLookup(&rec)) {
-        LOG(("Calling getaddrinfo for host [%s].\n", rec->host));
+        LOG(("DNS lookup thread - Calling getaddrinfo for host [%s].\n",
+             rec->host));
 
         int flags = PR_AI_ADDRCONFIG;
         if (!(rec->flags & RES_CANON_NAME))
             flags |= PR_AI_NOCANONNAME;
 
         TimeStamp startTime = TimeStamp::Now();
         MOZ_EVENT_TRACER_EXEC(rec, "net::dns::resolve");
 
@@ -1110,21 +1123,22 @@ nsHostResolver::ThreadFunc(void *arg)
                                   millis);
         }
         else {
             status = NS_ERROR_UNKNOWN_HOST;
             Telemetry::Accumulate(Telemetry::DNS_FAILED_LOOKUP_TIME, millis);
         }
 
         // OnLookupComplete may release "rec", log before we lose it.
-        LOG(("Lookup completed for host [%s].\n", rec->host));
+        LOG(("DNS lookup thread - lookup completed for host [%s]: %s.\n",
+             rec->host, ai ? "success" : "failure: unknown host"));
         resolver->OnLookupComplete(rec, status, ai);
     }
     NS_RELEASE(resolver);
-    LOG(("DNS lookup thread ending execution.\n"));
+    LOG(("DNS lookup thread - queue empty, thread finished.\n"));
 }
 
 nsresult
 nsHostResolver::Create(uint32_t         maxCacheEntries,
                        uint32_t         maxCacheLifetime,
                        uint32_t         lifetimeGracePeriod,
                        nsHostResolver **result)
 {
--- a/netwerk/protocol/http/nsHttpChannel.cpp
+++ b/netwerk/protocol/http/nsHttpChannel.cpp
@@ -4543,16 +4543,17 @@ nsHttpChannel::BeginConnect()
         //
         // We keep the DNS prefetch object around so that we can retrieve
         // timing information from it. There is no guarantee that we actually
         // use the DNS prefetch data for the real connection, but as we keep
         // this data around for 3 minutes by default, this should almost always
         // be correct, and even when it isn't, the timing still represents _a_
         // valid DNS lookup timing for the site, even if it is not _the_
         // timing we used.
+        LOG(("nsHttpChannel::BeginConnect [this=%p] prefetching\n", this));
         mDNSPrefetch = new nsDNSPrefetch(mURI, mTimingEnabled);
         mDNSPrefetch->PrefetchHigh();
     }
 
     // Adjust mCaps according to our request headers:
     //  - If "Connection: close" is set as a request header, then do not bother
     //    trying to establish a keep-alive connection.
     if (mRequestHead.HasHeaderValue(nsHttp::Connection, "close"))