Add fine grain tracing to HostResolverImpl....

net/base/host_resolver_impl.cc

 // Copyright (c) 2006-2008 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/base/host_resolver_impl.h"
 
 #include <cmath>
 #include <deque>
 
 #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"
 #include "base/time.h"
 #include "base/worker_pool.h"
 #include "net/base/address_list.h"
 #include "net/base/host_resolver_proc.h"
 #include "net/base/load_log.h"
 #include "net/base/net_errors.h"
 #include "net/base/network_change_notifier.h"
@@ skipping 120 matching lines @@
   CompletionCallback* callback_;
 
   // The address list to save result into.
   AddressList* addresses_;
 
   DISALLOW_COPY_AND_ASSIGN(Request);
 };
 
 //-----------------------------------------------------------------------------
 
+// Threadsafe log.
+class HostResolverImpl::RequestsTrace
+    : public base::RefCountedThreadSafe<HostResolverImpl::RequestsTrace> {
+ public:
+  RequestsTrace() : log_(new LoadLog(LoadLog::kUnbounded)) {}
+
+  void Add(const std::string& msg) {

[willchan no longer on Chromium, 2010/02/01 19:31:01]

I don't care too much, but my impression is that we generally avoid locking.  It
looks like the reason you have it here is because multiple worker threads may be
trying to write to this while the IOThread may be reading/writing it.  It seems
like another way of doing it is having the worker threads do
origin_loop_->PostTask instead of locking.  Is there a worry of incorrect
ordering of the log messages or something that led you to use Locks instead?

[eroman, 2010/02/01 20:31:25]

Since the locking is *only* going to be used in cases where DNS tracing is
enabled, and the lock duration is very short, I don't think this is going to be
much of an issue.

I prefer locking to message posting, since it is simple (and i don't want the
logging code to add more complexity).

I added the logging in the worker thread, since we have seen cases of suspected
worker pool starvation (in particular on mac). By logging the start/end on this
thread, we can see when the job really starts running.

[willchan no longer on Chromium, 2010/02/01 21:27:33]

I agree the performance isn't an issue.
I can see a counter-argument where most of our code uses message passing, so a
mutex-based approach is inconsistent and thus more confusing.  I agree that in
terms of this single change the locking approach is simpler.
I'm not sure I understand why message passing doesn't work for what you describe
here.  You could have a easily have a LoadLog::AddStringAtTime() function, so
that the timeticks delay between the posting of the task and its actual running
does not get recorded, since the current time would be passed as a parameter.

+    AutoLock l(lock_);
+    LoadLog::AddString(log_, msg);
+  }
+
+  void Get(LoadLog* out) {
+    AutoLock l(lock_);
+    out->Append(log_);
+  }
+
+ private:
+  Lock lock_;
+  scoped_refptr<LoadLog> log_;
+};
+
+//-----------------------------------------------------------------------------
+
 // This class represents a request to the worker pool for a "getaddrinfo()"
 // call.
 class HostResolverImpl::Job
     : public base::RefCountedThreadSafe<HostResolverImpl::Job> {
  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<int>(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_) {

[willchan no longer on Chromium, 2010/02/01 19:31:01]

No need for the braces

+      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)) {
       NOTREACHED();
 
       // Since we could be running within Resolve() right now, we can't just
       // call OnLookupComplete().  Instead we must wait until Resolve() has
       // returned (IO_PENDING).
       error_ = ERR_UNEXPECTED;
       MessageLoop::current()->PostTask(
           FROM_HERE, NewRunnableMethod(this, &Job::OnLookupComplete));
     }
   }
 
   // Cancels the current job. Callable from origin thread.
   void Cancel() {
     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.
     {
       AutoLock locked(origin_loop_lock_);
       origin_loop_ = NULL;
     }
 
     // We will call HostResolverImpl::CancelRequest(Request*) on each one
     // in order to notify any observers.
     for (RequestsList::const_iterator it = requests_.begin();
@@ skipping 28 matching lines @@
 
  private:
   friend class base::RefCountedThreadSafe<HostResolverImpl::Job>;
 
   ~Job() {
     // Free the requests attached to this job.
     STLDeleteElements(&requests_);
   }
 
   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
     // need to call its PostTask method inside a lock.  See ~HostResolver.
     {
       AutoLock locked(origin_loop_lock_);
       if (origin_loop_) {
         origin_loop_->PostTask(FROM_HERE, reply);
         reply = NULL;
       }
     }
 
     // Does nothing if it got posted.
     delete reply;
   }
 
   // Callback for when DoLookup() completes (runs on origin thread).
   void OnLookupComplete() {
     // Should be running on origin loop.
     // TODO(eroman): this is being hit by URLRequestTest.CancelTest*,
     // because MessageLoop::current() == NULL.
     //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;
 
     DCHECK(!requests_.empty());
 
      // Use the port number of the first request.
     if (error_ == OK)
       results_.SetPort(requests_[0]->port());
 
     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_;
 
   // Only used on the origin thread (where Resolve was called).
   HostResolverImpl* resolver_;
   RequestsList requests_;  // The requests waiting on this job.
 
   // Used to post ourselves onto the origin thread.
   Lock origin_loop_lock_;
   MessageLoop* origin_loop_;
 
   // Hold an owning reference to the HostResolverProc that we are going to use.
   // This may not be the current resolver procedure by the time we call
   // ResolveAddrInfo, but that's OK... we'll use it anyways, and the owning
   // reference ensures that it remains valid until we are done.
   scoped_refptr<HostResolverProc> resolver_proc_;
 
+  // Thread safe log to write details into, or NULL.
+  scoped_refptr<RequestsTrace> requests_trace_;
+
   // Assigned on the worker thread, read on the origin thread.
   int error_;
   AddressList results_;
 
   DISALLOW_COPY_AND_ASSIGN(Job);
 };
 
 //-----------------------------------------------------------------------------
 
 // We rely on the priority enum values being sequential having starting at 0,
@@ skipping 145 matching lines @@
 //-----------------------------------------------------------------------------
 
 HostResolverImpl::HostResolverImpl(
     HostResolverProc* resolver_proc,
     HostCache* cache,
     const scoped_refptr<NetworkChangeNotifier>& network_change_notifier,
     size_t max_jobs)
     : 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),
       network_change_notifier_(network_change_notifier) {
   DCHECK_GT(max_jobs, 0u);
 
   // It is cumbersome to expose all of the constraints in the constructor,
   // so we choose some defaults, which users can override later.
   job_pools_[POOL_NORMAL] = new JobPool(max_jobs, 100u * max_jobs);
 
@@ skipping 146 matching lines @@
 void HostResolverImpl::RemoveObserver(HostResolver::Observer* observer) {
   ObserversList::iterator it =
       std::find(observers_.begin(), observers_.end(), observer);
 
   // Observer must exist.
   DCHECK(it != observers_.end());
 
   observers_.erase(it);
 }
 
-HostCache* HostResolverImpl::GetHostCache() {
-  return cache_.get();
-}
-
 void HostResolverImpl::Shutdown() {
   shutdown_ = true;
 
   // Cancel the outstanding jobs.
   for (JobMap::iterator it = jobs_.begin(); it != jobs_.end(); ++it)
     it->second->Cancel();
   jobs_.clear();
 }
 
+void HostResolverImpl::ClearRequestsTrace() {
+  requests_trace_ = NULL;
+}
+
+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<int>(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<int>(total)));
+  }
+}
+
+bool HostResolverImpl::IsRequestsTracingEnabled() const {
+  return !!requests_trace_;  // Cast to bool.
+}
+
+scoped_refptr<LoadLog> HostResolverImpl::GetRequestsTrace() {
+  if (!requests_trace_)
+    return NULL;
+
+  scoped_refptr<LoadLog> 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) {
   CHECK(pool_index >= 0);
   CHECK(pool_index < POOL_COUNT);
   CHECK(jobs_.empty()) << "Can only set constraints during setup";
   JobPool* pool = job_pools_[pool_index];
   pool->SetConstraints(max_outstanding_jobs, max_pending_requests);
 }
 
@@ skipping 60 matching lines @@
   }
 
   cur_completing_job_ = NULL;
 }
 
 void HostResolverImpl::OnStartRequest(LoadLog* load_log,
                                       int request_id,
                                       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<int>(info.priority()),
+         static_cast<int>(info.is_speculative()),
+         static_cast<int>(info.address_family()),
+         static_cast<int>(info.allow_cached_response()),
+         info.referrer().spec().c_str()));
+  }
+
   // Notify the observers of the start.
   if (!observers_.empty()) {
     LoadLog::BeginEvent(
         load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL_OBSERVER_ONSTART);
 
     for (ObserversList::iterator it = observers_.begin();
          it != observers_.end(); ++it) {
       (*it)->OnStartResolution(request_id, info);
     }
 
     LoadLog::EndEvent(
         load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL_OBSERVER_ONSTART);
   }
 }
 
 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(
         load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL_OBSERVER_ONFINISH);
 
     bool was_resolved = error == OK;
     for (ObserversList::iterator it = observers_.begin();
          it != observers_.end(); ++it) {
       (*it)->OnFinishResolutionWithStatus(request_id, was_resolved, info);
     }
 
     LoadLog::EndEvent(
         load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL_OBSERVER_ONFINISH);
   }
 
   LoadLog::EndEvent(load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL);
 }
 
 void HostResolverImpl::OnCancelRequest(LoadLog* load_log,
                                        int request_id,
                                        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(
         load_log, LoadLog::TYPE_HOST_RESOLVER_IMPL_OBSERVER_ONCANCEL);
 
     for (ObserversList::iterator it = observers_.begin();
          it != observers_.end(); ++it) {
       (*it)->OnCancelResolution(request_id, info);
     }
 
@@ skipping 45 matching lines @@
   // Search for any other pending request which can piggy-back off this job.
   for (size_t pool_i = 0; pool_i < POOL_COUNT; ++pool_i) {
     JobPool* pool = job_pools_[pool_i];
     pool->MoveRequestsToJob(job);
   }
 }
 
 HostResolverImpl::Job* HostResolverImpl::CreateAndStartJob(Request* req) {
   DCHECK(CanCreateJobForPool(*GetPoolForRequest(req)));
   Key key(req->info().hostname(), req->info().address_family());
-  scoped_refptr<Job> job = new Job(this, key);
+  scoped_refptr<Job> job = new Job(next_job_id_++, this, key, requests_trace_);
   job->AddRequest(req);
   AddOutstandingJob(job);
   job->Start();
   return job.get();
 }
 
 int HostResolverImpl::EnqueueRequest(JobPool* pool, Request* req) {
+  if (requests_trace_)
+    requests_trace_->Add(StringPrintf("Queued request r%d", req->id()));
+
   scoped_ptr<Request> req_evicted_from_queue(
       pool->InsertPendingRequest(req));
 
   // If the queue has become too large, we need to kick something out.
   if (req_evicted_from_queue.get()) {
     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)
       return error;
 
     r->OnComplete(error, AddressList());
   }
 
   return ERR_IO_PENDING;
 }
 
 }  // namespace net