net/proxy/proxy_resolver_v8_tracing.cc

// Copyright (c) 2013 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/proxy/proxy_resolver_v8_tracing.h"

#include "base/bind.h"
#include "base/message_loop/message_loop_proxy.h"
#include "base/metrics/histogram.h"
#include "base/strings/stringprintf.h"
#include "base/synchronization/cancellation_flag.h"
#include "base/synchronization/waitable_event.h"
#include "base/threading/thread.h"
#include "base/threading/thread_restrictions.h"
#include "base/values.h"
#include "net/base/address_list.h"
#include "net/base/net_errors.h"
#include "net/base/net_log.h"
#include "net/dns/host_resolver.h"
#include "net/proxy/proxy_info.h"
#include "net/proxy/proxy_resolver_error_observer.h"
#include "net/proxy/proxy_resolver_v8.h"

// The intent of this class is explained in the design document:
// https://docs.google.com/a/chromium.org/document/d/16Ij5OcVnR3s0MH4Z5XkhI9VTPoMJdaBn9rKreAmGOdE/edit
//
// In a nutshell, PAC scripts are Javascript programs and may depend on
// network I/O, by calling functions like dnsResolve().
//
// This is problematic since functions such as dnsResolve() will block the
// Javascript execution until the DNS result is availble, thereby stalling the
// PAC thread, which hurts the ability to process parallel proxy resolves.
// An obvious solution is to simply start more PAC threads, however this scales
// poorly, which hurts the ability to process parallel proxy resolves.
//
// The solution in ProxyResolverV8Tracing is to model PAC scripts as being
// deterministic, and depending only on the inputted URL. When the script
// issues a dnsResolve() for a yet unresolved hostname, the Javascript
// execution is "aborted", and then re-started once the DNS result is
// known.
namespace net {

namespace {

// Upper bound on how many *unique* DNS resolves a PAC script is allowed
// to make. This is a failsafe both for scripts that do a ridiculous
// number of DNS resolves, as well as scripts which are misbehaving
// under the tracing optimization. It is not expected to hit this normally.
const size_t kMaxUniqueResolveDnsPerExec = 20;

// Approximate number of bytes to use for buffering alerts() and errors.
// This is a failsafe in case repeated executions of the script causes
// too much memory bloat. It is not expected for well behaved scripts to
// hit this. (In fact normal scripts should not even have alerts() or errors).
const size_t kMaxAlertsAndErrorsBytes = 2048;

// Returns event parameters for a PAC error message (line number + message).
base::Value* NetLogErrorCallback(int line_number,
                                 const base::string16* message,
                                 NetLog::LogLevel /* log_level */) {
  base::DictionaryValue* dict = new base::DictionaryValue();
  dict->SetInteger("line_number", line_number);
  dict->SetString("message", *message);
  return dict;
}

void IncrementWithoutOverflow(uint8* x) {
  if (*x != 0xFF)
    *x += 1;
}

}  // namespace

// The Job class is responsible for executing GetProxyForURL() and
// SetPacScript(), since both of these operations share similar code.
//
// The DNS for these operations can operate in either blocking or
// non-blocking mode. Blocking mode is used as a fallback when the PAC script
// seems to be misbehaving under the tracing optimization.
//
// Note that this class runs on both the origin thread and a worker
// thread. Most methods are expected to be used exclusively on one thread
// or the other.
//
// The lifetime of Jobs does not exceed that of the ProxyResolverV8Tracing that
// spawned it. Destruction might happen on either the origin thread or the
// worker thread.
class ProxyResolverV8Tracing::Job
    : public base::RefCountedThreadSafe<ProxyResolverV8Tracing::Job>,
      public ProxyResolverV8::JSBindings {
 public:
  // |parent| is non-owned. It is the ProxyResolverV8Tracing that spawned this
  // Job, and must oulive it.
  explicit Job(ProxyResolverV8Tracing* parent);

  // Called from origin thread.
  void StartSetPacScript(
      const scoped_refptr<ProxyResolverScriptData>& script_data,
      const CompletionCallback& callback);

  // Called from origin thread.
  void StartGetProxyForURL(const GURL& url,
                           ProxyInfo* results,
                           const BoundNetLog& net_log,
                           const CompletionCallback& callback);

  // Called from origin thread.
  void Cancel();

  // Called from origin thread.
  LoadState GetLoadState() const;

 private:
  typedef std::map<std::string, std::string> DnsCache;
  friend class base::RefCountedThreadSafe<ProxyResolverV8Tracing::Job>;

  enum Operation {
    SET_PAC_SCRIPT,
    GET_PROXY_FOR_URL,
  };

  struct AlertOrError {
    bool is_alert;
    int line_number;
    base::string16 message;
  };

  virtual ~Job();

  void CheckIsOnWorkerThread() const;
  void CheckIsOnOriginThread() const;

  void SetCallback(const CompletionCallback& callback);
  void ReleaseCallback();

  ProxyResolverV8* v8_resolver();
  base::MessageLoop* worker_loop();
  HostResolver* host_resolver();
  ProxyResolverErrorObserver* error_observer();
  NetLog* net_log();

  // Invokes the user's callback.
  void NotifyCaller(int result);
  void NotifyCallerOnOriginLoop(int result);

  void RecordMetrics() const;

  void Start(Operation op, bool blocking_dns,
             const CompletionCallback& callback);

  void ExecuteBlocking();
  void ExecuteNonBlocking();
  int ExecuteProxyResolver();

  // Implementation of ProxyResolverv8::JSBindings
  virtual bool ResolveDns(const std::string& host,
                          ResolveDnsOperation op,
                          std::string* output,
                          bool* terminate) OVERRIDE;
  virtual void Alert(const base::string16& message) OVERRIDE;
  virtual void OnError(int line_number, const base::string16& error) OVERRIDE;

  bool ResolveDnsBlocking(const std::string& host,
                          ResolveDnsOperation op,
                          std::string* output);

  bool ResolveDnsNonBlocking(const std::string& host,
                             ResolveDnsOperation op,
                             std::string* output,
                             bool* terminate);

  bool PostDnsOperationAndWait(const std::string& host,
                               ResolveDnsOperation op,
                               bool* completed_synchronously)
                               WARN_UNUSED_RESULT;

  void DoDnsOperation();
  void OnDnsOperationComplete(int result);

  void ScheduleRestartWithBlockingDns();

  bool GetDnsFromLocalCache(const std::string& host, ResolveDnsOperation op,
                            std::string* output, bool* return_value);

  void SaveDnsToLocalCache(const std::string& host, ResolveDnsOperation op,
                           int net_error, const net::AddressList& addresses);

  // Builds a RequestInfo to service the specified PAC DNS operation.
  static HostResolver::RequestInfo MakeDnsRequestInfo(const std::string& host,
                                                      ResolveDnsOperation op);

  // Makes a key for looking up |host, op| in |dns_cache_|. Strings are used for
  // convenience, to avoid defining custom comparators.
  static std::string MakeDnsCacheKey(const std::string& host,
                                     ResolveDnsOperation op);

  void HandleAlertOrError(bool is_alert, int line_number,
                          const base::string16& message);
  void DispatchBufferedAlertsAndErrors();
  void DispatchAlertOrError(bool is_alert, int line_number,
                            const base::string16& message);

  void LogEventToCurrentRequestAndGlobally(
      NetLog::EventType type,
      const NetLog::ParametersCallback& parameters_callback);

  // The thread which called into ProxyResolverV8Tracing, and on which the
  // completion callback is expected to run.
  scoped_refptr<base::MessageLoopProxy> origin_loop_;

  // The ProxyResolverV8Tracing which spawned this Job.
  // Initialized on origin thread and then accessed from both threads.
  ProxyResolverV8Tracing* parent_;

  // The callback to run (on the origin thread) when the Job finishes.
  // Should only be accessed from origin thread.
  CompletionCallback callback_;

  // Flag to indicate whether the request has been cancelled.
  base::CancellationFlag cancelled_;

  // The operation that this Job is running.
  // Initialized on origin thread and then accessed from both threads.
  Operation operation_;

  // The DNS mode for this Job.
  // Initialized on origin thread, mutated on worker thread, and accessed
  // by both the origin thread and worker thread.
  bool blocking_dns_;

  // Used to block the worker thread on a DNS operation taking place on the
  // origin thread.
  base::WaitableEvent event_;

  // Map of DNS operations completed so far. Written into on the origin thread
  // and read on the worker thread.
  DnsCache dns_cache_;

  // The job holds a reference to itself to ensure that it remains alive until
  // either completion or cancellation.
  scoped_refptr<Job> owned_self_reference_;

  // -------------------------------------------------------
  // State specific to SET_PAC_SCRIPT.
  // -------------------------------------------------------

  scoped_refptr<ProxyResolverScriptData> script_data_;

  // -------------------------------------------------------
  // State specific to GET_PROXY_FOR_URL.
  // -------------------------------------------------------

  ProxyInfo* user_results_;  // Owned by caller, lives on origin thread.
  GURL url_;
  ProxyInfo results_;
  BoundNetLog bound_net_log_;

  // ---------------------------------------------------------------------------
  // State for ExecuteNonBlocking()
  // ---------------------------------------------------------------------------
  // These variables are used exclusively on the worker thread and are only
  // meaningful when executing inside of ExecuteNonBlocking().

  // Whether this execution was abandoned due to a missing DNS dependency.
  bool abandoned_;

  // Number of calls made to ResolveDns() by this execution.
  int num_dns_;

  // Sequence of calls made to Alert() or OnError() by this execution.
  std::vector<AlertOrError> alerts_and_errors_;
  size_t alerts_and_errors_byte_cost_;  // Approximate byte cost of the above.

  // Number of calls made to ResolveDns() by the PREVIOUS execution.
  int last_num_dns_;

  // Whether the current execution needs to be restarted in blocking mode.
  bool should_restart_with_blocking_dns_;

  // ---------------------------------------------------------------------------
  // State for pending DNS request.
  // ---------------------------------------------------------------------------

  // Handle to the outstanding request in the HostResolver, or NULL.
  // This is mutated and used on the origin thread, however it may be read by
  // the worker thread for some DCHECKS().
  HostResolver::RequestHandle pending_dns_;

  // Indicates if the outstanding DNS request completed synchronously. Written
  // on the origin thread, and read by the worker thread.
  bool pending_dns_completed_synchronously_;

  // These are the inputs to DoDnsOperation(). Written on the worker thread,
  // read by the origin thread.
  std::string pending_dns_host_;
  ResolveDnsOperation pending_dns_op_;

  // This contains the resolved address list that DoDnsOperation() fills in.
  // Used exclusively on the origin thread.
  AddressList pending_dns_addresses_;

  // ---------------------------------------------------------------------------
  // Metrics for histograms
  // ---------------------------------------------------------------------------
  // These values are used solely for logging histograms. They do not affect
  // the execution flow of requests.

  // The time when the proxy resolve request started. Used exclusively on the
  // origin thread.
  base::TimeTicks metrics_start_time_;

  // The time when the proxy resolve request completes on the worker thread.
  // Written on the worker thread, read on the origin thread.
  base::TimeTicks metrics_end_time_;

  // The time when PostDnsOperationAndWait() was called. Written on the worker
  // thread, read by the origin thread.
  base::TimeTicks metrics_pending_dns_start_;

  // The total amount of time that has been spent by the script waiting for
  // DNS dependencies. This includes the time spent posting the task to
  // the origin thread, up until the DNS result is found on the origin
  // thread. It does not include any time spent waiting in the message loop
  // for the worker thread, nor any time restarting or executing the
  // script. Used exclusively on the origin thread.
  base::TimeDelta metrics_dns_total_time_;

  // The following variables are initialized on the origin thread,
  // incremented on the worker thread, and then read upon completion on the
  // origin thread. The values are not expected to exceed the range of a uint8.
  // If they do, then they will be clamped to 0xFF.
  uint8 metrics_num_executions_;
  uint8 metrics_num_unique_dns_;
  uint8 metrics_num_alerts_;
  uint8 metrics_num_errors_;

  // The time that the latest execution took (time spent inside of
  // ExecuteProxyResolver(), which includes time spent in bindings too).
  // Written on the worker thread, read on the origin thread.
  base::TimeDelta metrics_execution_time_;

  // The cumulative time spent in ExecuteProxyResolver() that was ultimately
  // discarded work.
  // Written on the worker thread, read on the origin thread.
  base::TimeDelta metrics_abandoned_execution_total_time_;

  // The duration that the worker thread was blocked waiting on DNS results from
  // the origin thread, when operating in nonblocking mode.
  // Written on the worker thread, read on the origin thread.
  base::TimeDelta metrics_nonblocking_dns_wait_total_time_;
};

ProxyResolverV8Tracing::Job::Job(ProxyResolverV8Tracing* parent)
    : origin_loop_(base::MessageLoopProxy::current()),
      parent_(parent),
      event_(true, false),
      last_num_dns_(0),
      pending_dns_(NULL),
      metrics_num_executions_(0),
      metrics_num_unique_dns_(0),
      metrics_num_alerts_(0),
      metrics_num_errors_(0) {
  CheckIsOnOriginThread();
}

void ProxyResolverV8Tracing::Job::StartSetPacScript(
    const scoped_refptr<ProxyResolverScriptData>& script_data,
    const CompletionCallback& callback) {
  CheckIsOnOriginThread();

  script_data_ = script_data;

  // Script initialization uses blocking DNS since there isn't any
  // advantage to using non-blocking mode here. That is because the
  // parent ProxyService can't submit any ProxyResolve requests until
  // initialization has completed successfully!
  Start(SET_PAC_SCRIPT, true /*blocking*/, callback);
}

void ProxyResolverV8Tracing::Job::StartGetProxyForURL(
    const GURL& url,
    ProxyInfo* results,
    const BoundNetLog& net_log,
    const CompletionCallback& callback) {
  CheckIsOnOriginThread();

  url_ = url;
  user_results_ = results;
  bound_net_log_ = net_log;

  Start(GET_PROXY_FOR_URL, false /*non-blocking*/, callback);
}

void ProxyResolverV8Tracing::Job::Cancel() {
  CheckIsOnOriginThread();

  // There are several possibilities to consider for cancellation:
  // (a) The job has been posted to the worker thread, however script execution
  //     has not yet started.
  // (b) The script is executing on the worker thread.
  // (c) The script is executing on the worker thread, however is blocked inside
  //     of dnsResolve() waiting for a response from the origin thread.
  // (d) Nothing is running on the worker thread, however the host resolver has
  //     a pending DNS request which upon completion will restart the script
  //     execution.
  // (e) The worker thread has a pending task to restart execution, which was
  //     posted after the DNS dependency was resolved and saved to local cache.
  // (f) The script execution completed entirely, and posted a task to the
  //     origin thread to notify the caller.
  //
  // |cancelled_| is read on both the origin thread and worker thread. The
  // code that runs on the worker thread is littered with checks on
  // |cancelled_| to break out early.
  cancelled_.Set();

  ReleaseCallback();

  if (pending_dns_) {
    host_resolver()->CancelRequest(pending_dns_);
    pending_dns_ = NULL;
  }

  // The worker thread might be blocked waiting for DNS.
  event_.Signal();

  owned_self_reference_ = NULL;
}

LoadState ProxyResolverV8Tracing::Job::GetLoadState() const {
  CheckIsOnOriginThread();

  if (pending_dns_)
    return LOAD_STATE_RESOLVING_HOST_IN_PROXY_SCRIPT;

  return LOAD_STATE_RESOLVING_PROXY_FOR_URL;
}

ProxyResolverV8Tracing::Job::~Job() {
  DCHECK(!pending_dns_);
  DCHECK(callback_.is_null());
}

void ProxyResolverV8Tracing::Job::CheckIsOnWorkerThread() const {
  DCHECK_EQ(base::MessageLoop::current(), parent_->thread_->message_loop());
}

void ProxyResolverV8Tracing::Job::CheckIsOnOriginThread() const {
  DCHECK(origin_loop_->BelongsToCurrentThread());
}

void ProxyResolverV8Tracing::Job::SetCallback(
    const CompletionCallback& callback) {
  CheckIsOnOriginThread();
  DCHECK(callback_.is_null());
  parent_->num_outstanding_callbacks_++;
  callback_ = callback;
}

void ProxyResolverV8Tracing::Job::ReleaseCallback() {
  CheckIsOnOriginThread();
  DCHECK(!callback_.is_null());
  CHECK_GT(parent_->num_outstanding_callbacks_, 0);
  parent_->num_outstanding_callbacks_--;
  callback_.Reset();

  // For good measure, clear this other user-owned pointer.
  user_results_ = NULL;
}

ProxyResolverV8* ProxyResolverV8Tracing::Job::v8_resolver() {
  return parent_->v8_resolver_.get();
}

base::MessageLoop* ProxyResolverV8Tracing::Job::worker_loop() {
  return parent_->thread_->message_loop();
}

HostResolver* ProxyResolverV8Tracing::Job::host_resolver() {
  return parent_->host_resolver_;
}

ProxyResolverErrorObserver* ProxyResolverV8Tracing::Job::error_observer() {
  return parent_->error_observer_.get();
}

NetLog* ProxyResolverV8Tracing::Job::net_log() {
  return parent_->net_log_;
}

void ProxyResolverV8Tracing::Job::NotifyCaller(int result) {
  CheckIsOnWorkerThread();

  metrics_end_time_ = base::TimeTicks::Now();

  origin_loop_->PostTask(
      FROM_HERE,
      base::Bind(&Job::NotifyCallerOnOriginLoop, this, result));
}

void ProxyResolverV8Tracing::Job::NotifyCallerOnOriginLoop(int result) {
  CheckIsOnOriginThread();

  if (cancelled_.IsSet())
    return;

  DCHECK(!callback_.is_null());
  DCHECK(!pending_dns_);

  if (operation_ == GET_PROXY_FOR_URL) {
    RecordMetrics();
    *user_results_ = results_;
  }

  // There is only ever 1 outstanding SET_PAC_SCRIPT job. It needs to be
  // tracked to support cancellation.
  if (operation_ == SET_PAC_SCRIPT) {
    DCHECK_EQ(parent_->set_pac_script_job_.get(), this);
    parent_->set_pac_script_job_ = NULL;
  }

  CompletionCallback callback = callback_;
  ReleaseCallback();
  callback.Run(result);

  owned_self_reference_ = NULL;
}

void ProxyResolverV8Tracing::Job::RecordMetrics() const {
  CheckIsOnOriginThread();
  DCHECK_EQ(GET_PROXY_FOR_URL, operation_);

  base::TimeTicks now = base::TimeTicks::Now();

  // Metrics are output for each completed request to GetProxyForURL()).
  //
  // Note that a different set of histograms is used to record the metrics for
  // requests that completed in non-blocking mode versus blocking mode. The
  // expectation is for requests to complete in non-blocking mode each time.
  // If they don't then something strange is happening, and the purpose of the
  // seprate statistics is to better understand that trend.
#define UPDATE_HISTOGRAMS(base_name) \
  do {\
  UMA_HISTOGRAM_MEDIUM_TIMES(base_name "TotalTime", now - metrics_start_time_);\
  UMA_HISTOGRAM_MEDIUM_TIMES(base_name "TotalTimeWorkerThread",\
                             metrics_end_time_ - metrics_start_time_);\
  UMA_HISTOGRAM_TIMES(base_name "OriginThreadLatency",\
                      now - metrics_end_time_);\
  UMA_HISTOGRAM_MEDIUM_TIMES(base_name "TotalTimeDNS",\
                             metrics_dns_total_time_);\
  UMA_HISTOGRAM_MEDIUM_TIMES(base_name "ExecutionTime",\
                             metrics_execution_time_);\
  UMA_HISTOGRAM_MEDIUM_TIMES(base_name "AbandonedExecutionTotalTime",\
                             metrics_abandoned_execution_total_time_);\
  UMA_HISTOGRAM_MEDIUM_TIMES(base_name "DnsWaitTotalTime",\
                             metrics_nonblocking_dns_wait_total_time_);\
  UMA_HISTOGRAM_CUSTOM_COUNTS(\
      base_name "NumRestarts", metrics_num_executions_ - 1,\
      1, kMaxUniqueResolveDnsPerExec, kMaxUniqueResolveDnsPerExec);\
  UMA_HISTOGRAM_CUSTOM_COUNTS(\
      base_name "UniqueDNS", metrics_num_unique_dns_,\
      1, kMaxUniqueResolveDnsPerExec, kMaxUniqueResolveDnsPerExec);\
  UMA_HISTOGRAM_COUNTS_100(base_name "NumAlerts", metrics_num_alerts_);\
  UMA_HISTOGRAM_CUSTOM_COUNTS(\
      base_name "NumErrors", metrics_num_errors_, 1, 10, 10);\
  } while (false)

  if (!blocking_dns_)
    UPDATE_HISTOGRAMS("Net.ProxyResolver.");
  else
    UPDATE_HISTOGRAMS("Net.ProxyResolver.BlockingDNSMode.");

#undef UPDATE_HISTOGRAMS

  // Histograms to better understand http://crbug.com/240536 -- long
  // URLs can cause a significant slowdown in PAC execution. Figure out how
  // severe this is in the wild.
  if (!blocking_dns_) {
    size_t url_size = url_.spec().size();

    UMA_HISTOGRAM_CUSTOM_COUNTS(
        "Net.ProxyResolver.URLSize", url_size, 1, 200000, 50);

    if (url_size > 2048) {
      UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver2K",
                                 metrics_execution_time_);
    }

    if (url_size > 4096) {
      UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver4K",
                                 metrics_execution_time_);
    }

    if (url_size > 8192) {
      UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver8K",
                                 metrics_execution_time_);
    }

    if (url_size > 131072) {
      UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver128K",
                                 metrics_execution_time_);
    }
  }
}


void ProxyResolverV8Tracing::Job::Start(Operation op, bool blocking_dns,
                                        const CompletionCallback& callback) {
  CheckIsOnOriginThread();

  metrics_start_time_ = base::TimeTicks::Now();
  operation_ = op;
  blocking_dns_ = blocking_dns;
  SetCallback(callback);

  owned_self_reference_ = this;

  worker_loop()->PostTask(FROM_HERE,
      blocking_dns_ ? base::Bind(&Job::ExecuteBlocking, this) :
                      base::Bind(&Job::ExecuteNonBlocking, this));
}

void ProxyResolverV8Tracing::Job::ExecuteBlocking() {
  CheckIsOnWorkerThread();
  DCHECK(blocking_dns_);

  if (cancelled_.IsSet())
    return;

  NotifyCaller(ExecuteProxyResolver());
}

void ProxyResolverV8Tracing::Job::ExecuteNonBlocking() {
  CheckIsOnWorkerThread();
  DCHECK(!blocking_dns_);

  if (cancelled_.IsSet())
    return;

  // Reset state for the current execution.
  abandoned_ = false;
  num_dns_ = 0;
  alerts_and_errors_.clear();
  alerts_and_errors_byte_cost_ = 0;
  should_restart_with_blocking_dns_ = false;

  int result = ExecuteProxyResolver();

  if (abandoned_)
    metrics_abandoned_execution_total_time_ += metrics_execution_time_;

  if (should_restart_with_blocking_dns_) {
    DCHECK(!blocking_dns_);
    DCHECK(abandoned_);
    blocking_dns_ = true;
    ExecuteBlocking();
    return;
  }

  if (abandoned_)
    return;

  DispatchBufferedAlertsAndErrors();
  NotifyCaller(result);
}

int ProxyResolverV8Tracing::Job::ExecuteProxyResolver() {
  IncrementWithoutOverflow(&metrics_num_executions_);

  base::TimeTicks start = base::TimeTicks::Now();

  JSBindings* prev_bindings = v8_resolver()->js_bindings();
  v8_resolver()->set_js_bindings(this);

  int result = ERR_UNEXPECTED;  // Initialized to silence warnings.

  switch (operation_) {
    case SET_PAC_SCRIPT:
      result = v8_resolver()->SetPacScript(
          script_data_, CompletionCallback());
      break;
    case GET_PROXY_FOR_URL:
      result = v8_resolver()->GetProxyForURL(
        url_,
        // Important: Do not write directly into |user_results_|, since if the
        // request were to be cancelled from the origin thread, must guarantee
        // that |user_results_| is not accessed anymore.
        &results_,
        CompletionCallback(),
        NULL,
        bound_net_log_);
      break;
  }

  v8_resolver()->set_js_bindings(prev_bindings);

  metrics_execution_time_ = base::TimeTicks::Now() - start;

  return result;
}

bool ProxyResolverV8Tracing::Job::ResolveDns(const std::string& host,
                                             ResolveDnsOperation op,
                                             std::string* output,
                                             bool* terminate) {
  if (cancelled_.IsSet()) {
    *terminate = true;
    return false;
  }

  if ((op == DNS_RESOLVE || op == DNS_RESOLVE_EX) && host.empty()) {
    // a DNS resolve with an empty hostname is considered an error.
    return false;
  }

  return blocking_dns_ ?
      ResolveDnsBlocking(host, op, output) :
      ResolveDnsNonBlocking(host, op, output, terminate);
}

void ProxyResolverV8Tracing::Job::Alert(const base::string16& message) {
  HandleAlertOrError(true, -1, message);
}

void ProxyResolverV8Tracing::Job::OnError(int line_number,
                                          const base::string16& error) {
  HandleAlertOrError(false, line_number, error);
}

bool ProxyResolverV8Tracing::Job::ResolveDnsBlocking(const std::string& host,
                                                     ResolveDnsOperation op,
                                                     std::string* output) {
  CheckIsOnWorkerThread();

  // Check if the DNS result for this host has already been cached.
  bool rv;
  if (GetDnsFromLocalCache(host, op, output, &rv)) {
    // Yay, cache hit!
    return rv;
  }

  // If the host was not in the local cache, this is a new hostname.
  IncrementWithoutOverflow(&metrics_num_unique_dns_);

  if (dns_cache_.size() >= kMaxUniqueResolveDnsPerExec) {
    // Safety net for scripts with unexpectedly many DNS calls.
    // We will continue running to completion, but will fail every
    // subsequent DNS request.
    return false;
  }

  if (!PostDnsOperationAndWait(host, op, NULL))
    return false;  // Was cancelled.

  CHECK(GetDnsFromLocalCache(host, op, output, &rv));
  return rv;
}

bool ProxyResolverV8Tracing::Job::ResolveDnsNonBlocking(const std::string& host,
                                                        ResolveDnsOperation op,
                                                        std::string* output,
                                                        bool* terminate) {
  CheckIsOnWorkerThread();

  if (abandoned_) {
    // If this execution was already abandoned can fail right away. Only 1 DNS
    // dependency will be traced at a time (for more predictable outcomes).
    return false;
  }

  num_dns_ += 1;

  // Check if the DNS result for this host has already been cached.
  bool rv;
  if (GetDnsFromLocalCache(host, op, output, &rv)) {
    // Yay, cache hit!
    return rv;
  }

  // If the host was not in the local cache, then this is a new hostname.
  IncrementWithoutOverflow(&metrics_num_unique_dns_);

  if (num_dns_ <= last_num_dns_) {
    // The sequence of DNS operations is different from last time!
    ScheduleRestartWithBlockingDns();
    *terminate = true;
    return false;
  }

  if (dns_cache_.size() >= kMaxUniqueResolveDnsPerExec) {
    // Safety net for scripts with unexpectedly many DNS calls.
    return false;
  }

  DCHECK(!should_restart_with_blocking_dns_);

  bool completed_synchronously;
  if (!PostDnsOperationAndWait(host, op, &completed_synchronously))
    return false;  // Was cancelled.

  if (completed_synchronously) {
    CHECK(GetDnsFromLocalCache(host, op, output, &rv));
    return rv;
  }

  // Otherwise if the result was not in the cache, then a DNS request has
  // been started. Abandon this invocation of FindProxyForURL(), it will be
  // restarted once the DNS request completes.
  abandoned_ = true;
  *terminate = true;
  last_num_dns_ = num_dns_;
  return false;
}

bool ProxyResolverV8Tracing::Job::PostDnsOperationAndWait(
    const std::string& host, ResolveDnsOperation op,
    bool* completed_synchronously) {

  base::TimeTicks start = base::TimeTicks::Now();

  // Post the DNS request to the origin thread.
  DCHECK(!pending_dns_);
  metrics_pending_dns_start_ = base::TimeTicks::Now();
  pending_dns_host_ = host;
  pending_dns_op_ = op;
  origin_loop_->PostTask(FROM_HERE, base::Bind(&Job::DoDnsOperation, this));

  event_.Wait();
  event_.Reset();

  if (cancelled_.IsSet())
    return false;

  if (completed_synchronously)
    *completed_synchronously = pending_dns_completed_synchronously_;

  if (!blocking_dns_)
    metrics_nonblocking_dns_wait_total_time_ += base::TimeTicks::Now() - start;

  return true;
}

void ProxyResolverV8Tracing::Job::DoDnsOperation() {
  CheckIsOnOriginThread();
  DCHECK(!pending_dns_);

  if (cancelled_.IsSet())
    return;

  HostResolver::RequestHandle dns_request = NULL;
  int result = host_resolver()->Resolve(
      MakeDnsRequestInfo(pending_dns_host_, pending_dns_op_),
      &pending_dns_addresses_,
      base::Bind(&Job::OnDnsOperationComplete, this),
      &dns_request,
      bound_net_log_);

  pending_dns_completed_synchronously_ = result != ERR_IO_PENDING;

  // Check if the request was cancelled as a side-effect of calling into the
  // HostResolver. This isn't the ordinary execution flow, however it is
  // exercised by unit-tests.
  if (cancelled_.IsSet()) {
    if (!pending_dns_completed_synchronously_)
      host_resolver()->CancelRequest(dns_request);
    return;
  }

  if (pending_dns_completed_synchronously_) {
    OnDnsOperationComplete(result);
  } else {
    DCHECK(dns_request);
    pending_dns_ = dns_request;
    // OnDnsOperationComplete() will be called by host resolver on completion.
  }

  if (!blocking_dns_) {
    // The worker thread always blocks waiting to see if the result can be
    // serviced from cache before restarting.
    event_.Signal();
  }
}

void ProxyResolverV8Tracing::Job::OnDnsOperationComplete(int result) {
  CheckIsOnOriginThread();

  DCHECK(!cancelled_.IsSet());
  DCHECK(pending_dns_completed_synchronously_ == (pending_dns_ == NULL));

  SaveDnsToLocalCache(pending_dns_host_, pending_dns_op_, result,
                      pending_dns_addresses_);
  pending_dns_ = NULL;

  metrics_dns_total_time_ +=
      base::TimeTicks::Now() - metrics_pending_dns_start_;

  if (blocking_dns_) {
    event_.Signal();
    return;
  }

  if (!blocking_dns_ && !pending_dns_completed_synchronously_) {
    // Restart. This time it should make more progress due to having
    // cached items.
    worker_loop()->PostTask(FROM_HERE,
                            base::Bind(&Job::ExecuteNonBlocking, this));
  }
}

void ProxyResolverV8Tracing::Job::ScheduleRestartWithBlockingDns() {
  CheckIsOnWorkerThread();

  DCHECK(!should_restart_with_blocking_dns_);
  DCHECK(!abandoned_);
  DCHECK(!blocking_dns_);

  abandoned_ = true;

  // The restart will happen after ExecuteNonBlocking() finishes.
  should_restart_with_blocking_dns_ = true;
}

bool ProxyResolverV8Tracing::Job::GetDnsFromLocalCache(
    const std::string& host,
    ResolveDnsOperation op,
    std::string* output,
    bool* return_value) {
  CheckIsOnWorkerThread();

  DnsCache::const_iterator it = dns_cache_.find(MakeDnsCacheKey(host, op));
  if (it == dns_cache_.end())
    return false;

  *output = it->second;
  *return_value = !it->second.empty();
  return true;
}

void ProxyResolverV8Tracing::Job::SaveDnsToLocalCache(
    const std::string& host,
    ResolveDnsOperation op,
    int net_error,
    const net::AddressList& addresses) {
  CheckIsOnOriginThread();

  // Serialize the result into a string to save to the cache.
  std::string cache_value;
  if (net_error != OK) {
    cache_value = std::string();
  } else if (op == DNS_RESOLVE || op == MY_IP_ADDRESS) {
    // dnsResolve() and myIpAddress() are expected to return a single IP
    // address.
    cache_value = addresses.front().ToStringWithoutPort();
  } else {
    // The *Ex versions are expected to return a semi-colon separated list.
    for (AddressList::const_iterator iter = addresses.begin();
         iter != addresses.end(); ++iter) {
      if (!cache_value.empty())
        cache_value += ";";
      cache_value += iter->ToStringWithoutPort();
    }
  }

  dns_cache_[MakeDnsCacheKey(host, op)] = cache_value;
}

// static
HostResolver::RequestInfo ProxyResolverV8Tracing::Job::MakeDnsRequestInfo(
    const std::string& host, ResolveDnsOperation op) {
  HostPortPair host_port = HostPortPair(host, 80);
  if (op == MY_IP_ADDRESS || op == MY_IP_ADDRESS_EX) {
    host_port.set_host(GetHostName());
  }

  HostResolver::RequestInfo info(host_port);

  // The non-ex flavors are limited to IPv4 results.
  if (op == MY_IP_ADDRESS || op == DNS_RESOLVE) {
    info.set_address_family(ADDRESS_FAMILY_IPV4);
  }

  return info;
}

std::string ProxyResolverV8Tracing::Job::MakeDnsCacheKey(
    const std::string& host, ResolveDnsOperation op) {
  return base::StringPrintf("%d:%s", op, host.c_str());
}

void ProxyResolverV8Tracing::Job::HandleAlertOrError(
    bool is_alert,
    int line_number,
    const base::string16& message) {
  CheckIsOnWorkerThread();

  if (cancelled_.IsSet())
    return;

  if (blocking_dns_) {
    // In blocking DNS mode the events can be dispatched immediately.
    DispatchAlertOrError(is_alert, line_number, message);
    return;
  }

  // Otherwise in nonblocking mode, buffer all the messages until
  // the end.

  if (abandoned_)
    return;

  alerts_and_errors_byte_cost_ += sizeof(AlertOrError) + message.size() * 2;

  // If there have been lots of messages, enqueing could be expensive on
  // memory. Consider a script which does megabytes worth of alerts().
  // Avoid this by falling back to blocking mode.
  if (alerts_and_errors_byte_cost_ > kMaxAlertsAndErrorsBytes) {
    ScheduleRestartWithBlockingDns();
    return;
  }

  AlertOrError entry = {is_alert, line_number, message};
  alerts_and_errors_.push_back(entry);
}

void ProxyResolverV8Tracing::Job::DispatchBufferedAlertsAndErrors() {
  CheckIsOnWorkerThread();
  DCHECK(!blocking_dns_);
  DCHECK(!abandoned_);

  for (size_t i = 0; i < alerts_and_errors_.size(); ++i) {
    const AlertOrError& x = alerts_and_errors_[i];
    DispatchAlertOrError(x.is_alert, x.line_number, x.message);
  }
}

void ProxyResolverV8Tracing::Job::DispatchAlertOrError(
    bool is_alert, int line_number, const base::string16& message) {
  CheckIsOnWorkerThread();

  // Note that the handling of cancellation is racy with regard to
  // alerts/errors. The request might get cancelled shortly after this
  // check! (There is no lock being held to guarantee otherwise).
  //
  // If this happens, then some information will get written to the NetLog
  // needlessly, however the NetLog will still be alive so it shouldn't cause
  // problems.
  if (cancelled_.IsSet())
    return;

  if (is_alert) {
    // -------------------
    // alert
    // -------------------
    IncrementWithoutOverflow(&metrics_num_alerts_);
    VLOG(1) << "PAC-alert: " << message;

    // Send to the NetLog.
    LogEventToCurrentRequestAndGlobally(
        NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
        NetLog::StringCallback("message", &message));
  } else {
    // -------------------
    // error
    // -------------------
    IncrementWithoutOverflow(&metrics_num_errors_);
    if (line_number == -1)
      VLOG(1) << "PAC-error: " << message;
    else
      VLOG(1) << "PAC-error: " << "line: " << line_number << ": " << message;

    // Send the error to the NetLog.
    LogEventToCurrentRequestAndGlobally(
        NetLog::TYPE_PAC_JAVASCRIPT_ERROR,
        base::Bind(&NetLogErrorCallback, line_number, &message));

    if (error_observer())
      error_observer()->OnPACScriptError(line_number, message);
  }
}

void ProxyResolverV8Tracing::Job::LogEventToCurrentRequestAndGlobally(
    NetLog::EventType type,
    const NetLog::ParametersCallback& parameters_callback) {
  CheckIsOnWorkerThread();
  bound_net_log_.AddEvent(type, parameters_callback);

  // Emit to the global NetLog event stream.
  if (net_log())
    net_log()->AddGlobalEntry(type, parameters_callback);
}

ProxyResolverV8Tracing::ProxyResolverV8Tracing(
    HostResolver* host_resolver,
    ProxyResolverErrorObserver* error_observer,
    NetLog* net_log)
    : ProxyResolver(true /*expects_pac_bytes*/),
      host_resolver_(host_resolver),
      error_observer_(error_observer),
      net_log_(net_log),
      num_outstanding_callbacks_(0) {
  DCHECK(host_resolver);
  // Start up the thread.
  thread_.reset(new base::Thread("Proxy resolver"));
  CHECK(thread_->Start());

  v8_resolver_.reset(new ProxyResolverV8);
}

ProxyResolverV8Tracing::~ProxyResolverV8Tracing() {
  // Note, all requests should have been cancelled.
  CHECK(!set_pac_script_job_.get());
  CHECK_EQ(0, num_outstanding_callbacks_);

  // Join the worker thread. See http://crbug.com/69710. Note that we call
  // Stop() here instead of simply clearing thread_ since there may be pending
  // callbacks on the worker thread which want to dereference thread_.
  base::ThreadRestrictions::ScopedAllowIO allow_io;
  thread_->Stop();
}

int ProxyResolverV8Tracing::GetProxyForURL(const GURL& url,
                                           ProxyInfo* results,
                                           const CompletionCallback& callback,
                                           RequestHandle* request,
                                           const BoundNetLog& net_log) {
  DCHECK(CalledOnValidThread());
  DCHECK(!callback.is_null());
  DCHECK(!set_pac_script_job_.get());

  scoped_refptr<Job> job = new Job(this);

  if (request)
    *request = job.get();

  job->StartGetProxyForURL(url, results, net_log, callback);
  return ERR_IO_PENDING;
}

void ProxyResolverV8Tracing::CancelRequest(RequestHandle request) {
  Job* job = reinterpret_cast<Job*>(request);
  job->Cancel();
}

LoadState ProxyResolverV8Tracing::GetLoadState(RequestHandle request) const {
  Job* job = reinterpret_cast<Job*>(request);
  return job->GetLoadState();
}

void ProxyResolverV8Tracing::CancelSetPacScript() {
  DCHECK(set_pac_script_job_.get());
  set_pac_script_job_->Cancel();
  set_pac_script_job_ = NULL;
}

void ProxyResolverV8Tracing::PurgeMemory() {
  thread_->message_loop()->PostTask(
      FROM_HERE,
      base::Bind(&ProxyResolverV8::PurgeMemory,
                 // The use of unretained is safe, since the worker thread
                 // cannot outlive |this|.
                 base::Unretained(v8_resolver_.get())));
}

int ProxyResolverV8Tracing::SetPacScript(
    const scoped_refptr<ProxyResolverScriptData>& script_data,
    const CompletionCallback& callback) {
  DCHECK(CalledOnValidThread());
  DCHECK(!callback.is_null());

  // Note that there should not be any outstanding (non-cancelled) Jobs when
  // setting the PAC script (ProxyService should guarantee this). If there are,
  // then they might complete in strange ways after the new script is set.
  DCHECK(!set_pac_script_job_.get());
  CHECK_EQ(0, num_outstanding_callbacks_);

  set_pac_script_job_ = new Job(this);
  set_pac_script_job_->StartSetPacScript(script_data, callback);

  return ERR_IO_PENDING;
}

}  // namespace net