From f2d8c4217a9214d12385ca43e2b22fd691a4f47a Mon Sep 17 00:00:00 2001 From: "eroman@chromium.org" Date: Tue, 2 Feb 2010 00:56:35 +0000 Subject: Add fine grain tracing to HostResolverImpl. This will help in diagnosing the "slow resolving host" bugs. Users can now click an "Enable tracing" button on "chrome://net-internals/hostresolver". This logs detailed information on the DNS requests flowing through the browser (when they were received, when they were posted to the thread pool, when they started running on the worker thread, etc...). BUG=12754 Review URL: http://codereview.chromium.org/556094 git-svn-id: svn://svn.chromium.org/chrome/trunk/src@37776 0039d316-1c4b-4281-b951-d872f2087c98 --- net/base/host_resolver_impl.cc | 142 +++++++++++++++++++++++++++++++++++++++-- 1 file changed, 135 insertions(+), 7 deletions(-) (limited to 'net/base/host_resolver_impl.cc') diff --git a/net/base/host_resolver_impl.cc b/net/base/host_resolver_impl.cc index b81b4cb..b654ad3 100644 --- a/net/base/host_resolver_impl.cc +++ b/net/base/host_resolver_impl.cc @@ -10,6 +10,7 @@ #include "base/basictypes.h" #include "base/compiler_specific.h" #include "base/debug_util.h" +#include "base/lock.h" #include "base/message_loop.h" #include "base/stl_util-inl.h" #include "base/string_util.h" @@ -150,28 +151,72 @@ class HostResolverImpl::Request { //----------------------------------------------------------------------------- +// Threadsafe log. +class HostResolverImpl::RequestsTrace + : public base::RefCountedThreadSafe { + public: + RequestsTrace() : log_(new LoadLog(LoadLog::kUnbounded)) {} + + void Add(const std::string& msg) { + AutoLock l(lock_); + LoadLog::AddString(log_, msg); + } + + void Get(LoadLog* out) { + AutoLock l(lock_); + out->Append(log_); + } + + void Clear() { + AutoLock l(lock_); + log_ = new LoadLog(LoadLog::kUnbounded); + } + + private: + Lock lock_; + scoped_refptr log_; +}; + +//----------------------------------------------------------------------------- + // This class represents a request to the worker pool for a "getaddrinfo()" // call. class HostResolverImpl::Job : public base::RefCountedThreadSafe { public: - Job(HostResolverImpl* resolver, const Key& key) - : key_(key), + Job(int id, HostResolverImpl* resolver, const Key& key, + RequestsTrace* requests_trace) + : id_(id), key_(key), resolver_(resolver), origin_loop_(MessageLoop::current()), resolver_proc_(resolver->effective_resolver_proc()), + requests_trace_(requests_trace), error_(OK) { + if (requests_trace_) { + requests_trace_->Add(StringPrintf( + "Created job j%d for {hostname='%s', address_family=%d}", + id_, key.hostname.c_str(), + static_cast(key.address_family))); + } } // Attaches a request to this job. The job takes ownership of |req| and will // take care to delete it. void AddRequest(Request* req) { + if (requests_trace_) { + requests_trace_->Add(StringPrintf( + "Attached request r%d to job j%d", req->id(), id_)); + } + req->set_job(this); requests_.push_back(req); } // Called from origin loop. void Start() { + if (requests_trace_) + requests_trace_->Add(StringPrintf("Starting job j%d", id_)); + // Dispatch the job to a worker thread. if (!WorkerPool::PostTask(FROM_HERE, NewRunnableMethod(this, &Job::DoLookup), true)) { @@ -191,6 +236,9 @@ class HostResolverImpl::Job HostResolver* resolver = resolver_; resolver_ = NULL; + if (requests_trace_) + requests_trace_->Add(StringPrintf("Cancelled job j%d", id_)); + // Mark the job as cancelled, so when worker thread completes it will // not try to post completion to origin loop. { @@ -239,12 +287,22 @@ class HostResolverImpl::Job } void DoLookup() { + if (requests_trace_) { + requests_trace_->Add(StringPrintf( + "[resolver thread] Running job j%d", id_)); + } + // Running on the worker thread error_ = ResolveAddrInfo(resolver_proc_, key_.hostname, key_.address_family, &results_); + if (requests_trace_) { + requests_trace_->Add(StringPrintf( + "[resolver thread] Completed job j%d", id_)); + } + Task* reply = NewRunnableMethod(this, &Job::OnLookupComplete); // The origin loop could go away while we are trying to post to it, so we @@ -269,6 +327,9 @@ class HostResolverImpl::Job //DCHECK_EQ(origin_loop_, MessageLoop::current()); DCHECK(error_ || results_.head()); + if (requests_trace_) + requests_trace_->Add(StringPrintf("Completing job j%d", id_)); + if (was_cancelled()) return; @@ -281,6 +342,9 @@ class HostResolverImpl::Job resolver_->OnJobComplete(this, error_, results_); } + // Immutable. Can be read from either thread, + const int id_; + // Set on the origin thread, read on the worker thread. Key key_; @@ -298,6 +362,9 @@ class HostResolverImpl::Job // reference ensures that it remains valid until we are done. scoped_refptr resolver_proc_; + // Thread safe log to write details into, or NULL. + scoped_refptr requests_trace_; + // Assigned on the worker thread, read on the origin thread. int error_; AddressList results_; @@ -463,6 +530,7 @@ HostResolverImpl::HostResolverImpl( : cache_(cache), max_jobs_(max_jobs), next_request_id_(0), + next_job_id_(0), resolver_proc_(resolver_proc), default_address_family_(ADDRESS_FAMILY_UNSPECIFIED), shutdown_(false), @@ -629,10 +697,6 @@ void HostResolverImpl::RemoveObserver(HostResolver::Observer* observer) { observers_.erase(it); } -HostCache* HostResolverImpl::GetHostCache() { - return cache_.get(); -} - void HostResolverImpl::Shutdown() { shutdown_ = true; @@ -642,6 +706,42 @@ void HostResolverImpl::Shutdown() { jobs_.clear(); } +void HostResolverImpl::ClearRequestsTrace() { + if (requests_trace_) + requests_trace_->Clear(); +} + +void HostResolverImpl::EnableRequestsTracing(bool enable) { + requests_trace_ = enable ? new RequestsTrace : NULL; + if (enable) { + // Print the state of the world when logging was started. + requests_trace_->Add("Enabled tracing"); + requests_trace_->Add(StringPrintf( + "Current num outstanding jobs: %d", + static_cast(jobs_.size()))); + + size_t total = 0u; + for (size_t i = 0; i < arraysize(job_pools_); ++i) + total += job_pools_[i]->GetNumPendingRequests(); + + requests_trace_->Add(StringPrintf( + "Number of queued requests: %d", static_cast(total))); + } +} + +bool HostResolverImpl::IsRequestsTracingEnabled() const { + return !!requests_trace_; // Cast to bool. +} + +scoped_refptr HostResolverImpl::GetRequestsTrace() { + if (!requests_trace_) + return NULL; + + scoped_refptr copy_of_log = new LoadLog(LoadLog::kUnbounded); + requests_trace_->Get(copy_of_log); + return copy_of_log; +} + void HostResolverImpl::SetPoolConstraints(JobPoolIndex pool_index, size_t max_outstanding_jobs, size_t max_pending_requests) { @@ -722,6 +822,20 @@ void HostResolverImpl::OnStartRequest(LoadLog* load_log, const RequestInfo& info) { LoadLog::BeginEvent(load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL); + if (requests_trace_) { + requests_trace_->Add(StringPrintf( + "Received request r%d for {hostname='%s', port=%d, priority=%d, " + "speculative=%d, address_family=%d, allow_cached=%d, referrer='%s'}", + request_id, + info.hostname().c_str(), + info.port(), + static_cast(info.priority()), + static_cast(info.is_speculative()), + static_cast(info.address_family()), + static_cast(info.allow_cached_response()), + info.referrer().spec().c_str())); + } + // Notify the observers of the start. if (!observers_.empty()) { LoadLog::BeginEvent( @@ -741,6 +855,11 @@ void HostResolverImpl::OnFinishRequest(LoadLog* load_log, int request_id, const RequestInfo& info, int error) { + if (requests_trace_) { + requests_trace_->Add(StringPrintf( + "Finished request r%d with error=%d", request_id, error)); + } + // Notify the observers of the completion. if (!observers_.empty()) { LoadLog::BeginEvent( @@ -764,6 +883,9 @@ void HostResolverImpl::OnCancelRequest(LoadLog* load_log, const RequestInfo& info) { LoadLog::AddEvent(load_log, LoadLog::TYPE_CANCELLED); + if (requests_trace_) + requests_trace_->Add(StringPrintf("Cancelled request r%d", request_id)); + // Notify the observers of the cancellation. if (!observers_.empty()) { LoadLog::BeginEvent( @@ -829,7 +951,7 @@ void HostResolverImpl::ProcessQueuedRequests() { HostResolverImpl::Job* HostResolverImpl::CreateAndStartJob(Request* req) { DCHECK(CanCreateJobForPool(*GetPoolForRequest(req))); Key key(req->info().hostname(), req->info().address_family()); - scoped_refptr job = new Job(this, key); + scoped_refptr job = new Job(next_job_id_++, this, key, requests_trace_); job->AddRequest(req); AddOutstandingJob(job); job->Start(); @@ -837,6 +959,9 @@ HostResolverImpl::Job* HostResolverImpl::CreateAndStartJob(Request* req) { } int HostResolverImpl::EnqueueRequest(JobPool* pool, Request* req) { + if (requests_trace_) + requests_trace_->Add(StringPrintf("Queued request r%d", req->id())); + scoped_ptr req_evicted_from_queue( pool->InsertPendingRequest(req)); @@ -845,6 +970,9 @@ int HostResolverImpl::EnqueueRequest(JobPool* pool, Request* req) { Request* r = req_evicted_from_queue.get(); int error = ERR_HOST_RESOLVER_QUEUE_TOO_LARGE; + if (requests_trace_) + requests_trace_->Add(StringPrintf("Evicted request r%d", r->id())); + OnFinishRequest(r->load_log(), r->id(), r->info(), error); if (r == req) -- cgit v1.1