Bug 938803 - Improve DNS debugs to show which path is taken in nsHostResolver::ResolveHost r=mcmanus

This commit is contained in:
Steve Workman 2013-11-18 11:32:00 -08:00
parent 8a980bb01a
commit 9ac8727c00
3 changed files with 38 additions and 20 deletions

View File

@ -972,7 +972,10 @@ nsSocketTransport::SendStatus(nsresult status)
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;

View File

@ -517,7 +517,8 @@ nsHostResolver::ResolveHost(const char *host,
{
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.
@ -552,13 +553,15 @@ nsHostResolver::ResolveHost(const char *host,
(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);
@ -569,6 +572,7 @@ nsHostResolver::ResolveHost(const char *host,
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;
@ -577,6 +581,7 @@ nsHostResolver::ResolveHost(const char *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;
@ -585,6 +590,7 @@ nsHostResolver::ResolveHost(const char *host,
// 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();
@ -597,12 +603,16 @@ nsHostResolver::ResolveHost(const char *host,
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;
}
@ -624,9 +634,8 @@ nsHostResolver::ResolveHost(const char *host,
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
@ -658,6 +667,8 @@ nsHostResolver::ResolveHost(const char *host,
// 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;
@ -669,25 +680,26 @@ nsHostResolver::ResolveHost(const char *host,
// 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,
@ -782,7 +794,7 @@ nsHostResolver::ConditionallyCreateThread(nsHostRecord *rec)
}
#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;
}
@ -818,7 +830,7 @@ nsHostResolver::IssueLookup(nsHostRecord *rec)
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,
@ -833,7 +845,7 @@ 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);
@ -1053,7 +1065,7 @@ nsHostResolver::CancelAsyncRequest(const char *host,
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"));
@ -1065,7 +1077,8 @@ nsHostResolver::ThreadFunc(void *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))
@ -1115,11 +1128,12 @@ nsHostResolver::ThreadFunc(void *arg)
}
// 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

View File

@ -4526,6 +4526,7 @@ nsHttpChannel::BeginConnect()
// 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();
}