src/net/proxy/proxy_resolver_v8_tracing.cc

   1 // Copyright (c) 2013 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "net/proxy/proxy_resolver_v8_tracing.h"
   6
   7 #include "base/bind.h"
   8 #include "base/message_loop/message_loop_proxy.h"
   9 #include "base/metrics/histogram.h"
  10 #include "base/strings/stringprintf.h"
  11 #include "base/synchronization/cancellation_flag.h"
  12 #include "base/synchronization/waitable_event.h"
  13 #include "base/threading/thread.h"
  14 #include "base/threading/thread_restrictions.h"
  15 #include "base/values.h"
  16 #include "net/base/address_list.h"
  17 #include "net/base/net_errors.h"
  18 #include "net/base/net_log.h"
  19 #include "net/dns/host_resolver.h"
  20 #include "net/proxy/proxy_info.h"
  21 #include "net/proxy/proxy_resolver_error_observer.h"
  22 #include "net/proxy/proxy_resolver_v8.h"
  23
  24 // The intent of this class is explained in the design document:
  25 // https://docs.google.com/a/chromium.org/document/d/16Ij5OcVnR3s0MH4Z5XkhI9VTPoMJdaBn9rKreAmGOdE/edit
  26 //
  27 // In a nutshell, PAC scripts are Javascript programs and may depend on
  28 // network I/O, by calling functions like dnsResolve().
  29 //
  30 // This is problematic since functions such as dnsResolve() will block the
  31 // Javascript execution until the DNS result is availble, thereby stalling the
  32 // PAC thread, which hurts the ability to process parallel proxy resolves.
  33 // An obvious solution is to simply start more PAC threads, however this scales
  34 // poorly, which hurts the ability to process parallel proxy resolves.
  35 //
  36 // The solution in ProxyResolverV8Tracing is to model PAC scripts as being
  37 // deterministic, and depending only on the inputted URL. When the script
  38 // issues a dnsResolve() for a yet unresolved hostname, the Javascript
  39 // execution is "aborted", and then re-started once the DNS result is
  40 // known.
  41 namespace net {
  42
  43 namespace {
  44
  45 // Upper bound on how many *unique* DNS resolves a PAC script is allowed
  46 // to make. This is a failsafe both for scripts that do a ridiculous
  47 // number of DNS resolves, as well as scripts which are misbehaving
  48 // under the tracing optimization. It is not expected to hit this normally.
  49 const size_t kMaxUniqueResolveDnsPerExec = 20;
  50
  51 // Approximate number of bytes to use for buffering alerts() and errors.
  52 // This is a failsafe in case repeated executions of the script causes
  53 // too much memory bloat. It is not expected for well behaved scripts to
  54 // hit this. (In fact normal scripts should not even have alerts() or errors).
  55 const size_t kMaxAlertsAndErrorsBytes = 2048;
  56
  57 // Returns event parameters for a PAC error message (line number + message).
  58 base::Value* NetLogErrorCallback(int line_number,
  59                                  const base::string16* message,
  60                                  NetLog::LogLevel /* log_level */) {
  61   base::DictionaryValue* dict = new base::DictionaryValue();
  62   dict->SetInteger("line_number", line_number);
  63   dict->SetString("message", *message);
  64   return dict;
  65 }
  66
  67 void IncrementWithoutOverflow(uint8* x) {
  68   if (*x != 0xFF)
  69     *x += 1;
  70 }
  71
  72 }  // namespace
  73
  74 // The Job class is responsible for executing GetProxyForURL() and
  75 // SetPacScript(), since both of these operations share similar code.
  76 //
  77 // The DNS for these operations can operate in either blocking or
  78 // non-blocking mode. Blocking mode is used as a fallback when the PAC script
  79 // seems to be misbehaving under the tracing optimization.
  80 //
  81 // Note that this class runs on both the origin thread and a worker
  82 // thread. Most methods are expected to be used exclusively on one thread
  83 // or the other.
  84 //
  85 // The lifetime of Jobs does not exceed that of the ProxyResolverV8Tracing that
  86 // spawned it. Destruction might happen on either the origin thread or the
  87 // worker thread.
  88 class ProxyResolverV8Tracing::Job
  89     : public base::RefCountedThreadSafe<ProxyResolverV8Tracing::Job>,
  90       public ProxyResolverV8::JSBindings {
  91  public:
  92   // |parent| is non-owned. It is the ProxyResolverV8Tracing that spawned this
  93   // Job, and must oulive it.
  94   explicit Job(ProxyResolverV8Tracing* parent);
  95
  96   // Called from origin thread.
  97   void StartSetPacScript(
  98       const scoped_refptr<ProxyResolverScriptData>& script_data,
  99       const CompletionCallback& callback);
 100
 101   // Called from origin thread.
 102   void StartGetProxyForURL(const GURL& url,
 103                            ProxyInfo* results,
 104                            const BoundNetLog& net_log,
 105                            const CompletionCallback& callback);
 106
 107   // Called from origin thread.
 108   void Cancel();
 109
 110   // Called from origin thread.
 111   LoadState GetLoadState() const;
 112
 113  private:
 114   typedef std::map<std::string, std::string> DnsCache;
 115   friend class base::RefCountedThreadSafe<ProxyResolverV8Tracing::Job>;
 116
 117   enum Operation {
 118     SET_PAC_SCRIPT,
 119     GET_PROXY_FOR_URL,
 120   };
 121
 122   struct AlertOrError {
 123     bool is_alert;
 124     int line_number;
 125     base::string16 message;
 126   };
 127
 128   virtual ~Job();
 129
 130   void CheckIsOnWorkerThread() const;
 131   void CheckIsOnOriginThread() const;
 132
 133   void SetCallback(const CompletionCallback& callback);
 134   void ReleaseCallback();
 135
 136   ProxyResolverV8* v8_resolver();
 137   base::MessageLoop* worker_loop();
 138   HostResolver* host_resolver();
 139   ProxyResolverErrorObserver* error_observer();
 140   NetLog* net_log();
 141
 142   // Invokes the user's callback.
 143   void NotifyCaller(int result);
 144   void NotifyCallerOnOriginLoop(int result);
 145
 146   void RecordMetrics() const;
 147
 148   void Start(Operation op, bool blocking_dns,
 149              const CompletionCallback& callback);
 150
 151   void ExecuteBlocking();
 152   void ExecuteNonBlocking();
 153   int ExecuteProxyResolver();
 154
 155   // Implementation of ProxyResolverv8::JSBindings
 156   virtual bool ResolveDns(const std::string& host,
 157                           ResolveDnsOperation op,
 158                           std::string* output,
 159                           bool* terminate) OVERRIDE;
 160   virtual void Alert(const base::string16& message) OVERRIDE;
 161   virtual void OnError(int line_number, const base::string16& error) OVERRIDE;
 162
 163   bool ResolveDnsBlocking(const std::string& host,
 164                           ResolveDnsOperation op,
 165                           std::string* output);
 166
 167   bool ResolveDnsNonBlocking(const std::string& host,
 168                              ResolveDnsOperation op,
 169                              std::string* output,
 170                              bool* terminate);
 171
 172   bool PostDnsOperationAndWait(const std::string& host,
 173                                ResolveDnsOperation op,
 174                                bool* completed_synchronously)
 175                                WARN_UNUSED_RESULT;
 176
 177   void DoDnsOperation();
 178   void OnDnsOperationComplete(int result);
 179
 180   void ScheduleRestartWithBlockingDns();
 181
 182   bool GetDnsFromLocalCache(const std::string& host, ResolveDnsOperation op,
 183                             std::string* output, bool* return_value);
 184
 185   void SaveDnsToLocalCache(const std::string& host, ResolveDnsOperation op,
 186                            int net_error, const net::AddressList& addresses);
 187
 188   // Builds a RequestInfo to service the specified PAC DNS operation.
 189   static HostResolver::RequestInfo MakeDnsRequestInfo(const std::string& host,
 190                                                       ResolveDnsOperation op);
 191
 192   // Makes a key for looking up |host, op| in |dns_cache_|. Strings are used for
 193   // convenience, to avoid defining custom comparators.
 194   static std::string MakeDnsCacheKey(const std::string& host,
 195                                      ResolveDnsOperation op);
 196
 197   void HandleAlertOrError(bool is_alert, int line_number,
 198                           const base::string16& message);
 199   void DispatchBufferedAlertsAndErrors();
 200   void DispatchAlertOrError(bool is_alert, int line_number,
 201                             const base::string16& message);
 202
 203   void LogEventToCurrentRequestAndGlobally(
 204       NetLog::EventType type,
 205       const NetLog::ParametersCallback& parameters_callback);
 206
 207   // The thread which called into ProxyResolverV8Tracing, and on which the
 208   // completion callback is expected to run.
 209   scoped_refptr<base::MessageLoopProxy> origin_loop_;
 210
 211   // The ProxyResolverV8Tracing which spawned this Job.
 212   // Initialized on origin thread and then accessed from both threads.
 213   ProxyResolverV8Tracing* parent_;
 214
 215   // The callback to run (on the origin thread) when the Job finishes.
 216   // Should only be accessed from origin thread.
 217   CompletionCallback callback_;
 218
 219   // Flag to indicate whether the request has been cancelled.
 220   base::CancellationFlag cancelled_;
 221
 222   // The operation that this Job is running.
 223   // Initialized on origin thread and then accessed from both threads.
 224   Operation operation_;
 225
 226   // The DNS mode for this Job.
 227   // Initialized on origin thread, mutated on worker thread, and accessed
 228   // by both the origin thread and worker thread.
 229   bool blocking_dns_;
 230
 231   // Used to block the worker thread on a DNS operation taking place on the
 232   // origin thread.
 233   base::WaitableEvent event_;
 234
 235   // Map of DNS operations completed so far. Written into on the origin thread
 236   // and read on the worker thread.
 237   DnsCache dns_cache_;
 238
 239   // The job holds a reference to itself to ensure that it remains alive until
 240   // either completion or cancellation.
 241   scoped_refptr<Job> owned_self_reference_;
 242
 243   // -------------------------------------------------------
 244   // State specific to SET_PAC_SCRIPT.
 245   // -------------------------------------------------------
 246
 247   scoped_refptr<ProxyResolverScriptData> script_data_;
 248
 249   // -------------------------------------------------------
 250   // State specific to GET_PROXY_FOR_URL.
 251   // -------------------------------------------------------
 252
 253   ProxyInfo* user_results_;  // Owned by caller, lives on origin thread.
 254   GURL url_;
 255   ProxyInfo results_;
 256   BoundNetLog bound_net_log_;
 257
 258   // ---------------------------------------------------------------------------
 259   // State for ExecuteNonBlocking()
 260   // ---------------------------------------------------------------------------
 261   // These variables are used exclusively on the worker thread and are only
 262   // meaningful when executing inside of ExecuteNonBlocking().
 263
 264   // Whether this execution was abandoned due to a missing DNS dependency.
 265   bool abandoned_;
 266
 267   // Number of calls made to ResolveDns() by this execution.
 268   int num_dns_;
 269
 270   // Sequence of calls made to Alert() or OnError() by this execution.
 271   std::vector<AlertOrError> alerts_and_errors_;
 272   size_t alerts_and_errors_byte_cost_;  // Approximate byte cost of the above.
 273
 274   // Number of calls made to ResolveDns() by the PREVIOUS execution.
 275   int last_num_dns_;
 276
 277   // Whether the current execution needs to be restarted in blocking mode.
 278   bool should_restart_with_blocking_dns_;
 279
 280   // ---------------------------------------------------------------------------
 281   // State for pending DNS request.
 282   // ---------------------------------------------------------------------------
 283
 284   // Handle to the outstanding request in the HostResolver, or NULL.
 285   // This is mutated and used on the origin thread, however it may be read by
 286   // the worker thread for some DCHECKS().
 287   HostResolver::RequestHandle pending_dns_;
 288
 289   // Indicates if the outstanding DNS request completed synchronously. Written
 290   // on the origin thread, and read by the worker thread.
 291   bool pending_dns_completed_synchronously_;
 292
 293   // These are the inputs to DoDnsOperation(). Written on the worker thread,
 294   // read by the origin thread.
 295   std::string pending_dns_host_;
 296   ResolveDnsOperation pending_dns_op_;
 297
 298   // This contains the resolved address list that DoDnsOperation() fills in.
 299   // Used exclusively on the origin thread.
 300   AddressList pending_dns_addresses_;
 301
 302   // ---------------------------------------------------------------------------
 303   // Metrics for histograms
 304   // ---------------------------------------------------------------------------
 305   // These values are used solely for logging histograms. They do not affect
 306   // the execution flow of requests.
 307
 308   // The time when the proxy resolve request started. Used exclusively on the
 309   // origin thread.
 310   base::TimeTicks metrics_start_time_;
 311
 312   // The time when the proxy resolve request completes on the worker thread.
 313   // Written on the worker thread, read on the origin thread.
 314   base::TimeTicks metrics_end_time_;
 315
 316   // The time when PostDnsOperationAndWait() was called. Written on the worker
 317   // thread, read by the origin thread.
 318   base::TimeTicks metrics_pending_dns_start_;
 319
 320   // The total amount of time that has been spent by the script waiting for
 321   // DNS dependencies. This includes the time spent posting the task to
 322   // the origin thread, up until the DNS result is found on the origin
 323   // thread. It does not include any time spent waiting in the message loop
 324   // for the worker thread, nor any time restarting or executing the
 325   // script. Used exclusively on the origin thread.
 326   base::TimeDelta metrics_dns_total_time_;
 327
 328   // The following variables are initialized on the origin thread,
 329   // incremented on the worker thread, and then read upon completion on the
 330   // origin thread. The values are not expected to exceed the range of a uint8.
 331   // If they do, then they will be clamped to 0xFF.
 332   uint8 metrics_num_executions_;
 333   uint8 metrics_num_unique_dns_;
 334   uint8 metrics_num_alerts_;
 335   uint8 metrics_num_errors_;
 336
 337   // The time that the latest execution took (time spent inside of
 338   // ExecuteProxyResolver(), which includes time spent in bindings too).
 339   // Written on the worker thread, read on the origin thread.
 340   base::TimeDelta metrics_execution_time_;
 341
 342   // The cumulative time spent in ExecuteProxyResolver() that was ultimately
 343   // discarded work.
 344   // Written on the worker thread, read on the origin thread.
 345   base::TimeDelta metrics_abandoned_execution_total_time_;
 346
 347   // The duration that the worker thread was blocked waiting on DNS results from
 348   // the origin thread, when operating in nonblocking mode.
 349   // Written on the worker thread, read on the origin thread.
 350   base::TimeDelta metrics_nonblocking_dns_wait_total_time_;
 351 };
 352
 353 ProxyResolverV8Tracing::Job::Job(ProxyResolverV8Tracing* parent)
 354     : origin_loop_(base::MessageLoopProxy::current()),
 355       parent_(parent),
 356       event_(true, false),
 357       last_num_dns_(0),
 358       pending_dns_(NULL),
 359       metrics_num_executions_(0),
 360       metrics_num_unique_dns_(0),
 361       metrics_num_alerts_(0),
 362       metrics_num_errors_(0) {
 363   CheckIsOnOriginThread();
 364 }
 365
 366 void ProxyResolverV8Tracing::Job::StartSetPacScript(
 367     const scoped_refptr<ProxyResolverScriptData>& script_data,
 368     const CompletionCallback& callback) {
 369   CheckIsOnOriginThread();
 370
 371   script_data_ = script_data;
 372
 373   // Script initialization uses blocking DNS since there isn't any
 374   // advantage to using non-blocking mode here. That is because the
 375   // parent ProxyService can't submit any ProxyResolve requests until
 376   // initialization has completed successfully!
 377   Start(SET_PAC_SCRIPT, true /*blocking*/, callback);
 378 }
 379
 380 void ProxyResolverV8Tracing::Job::StartGetProxyForURL(
 381     const GURL& url,
 382     ProxyInfo* results,
 383     const BoundNetLog& net_log,
 384     const CompletionCallback& callback) {
 385   CheckIsOnOriginThread();
 386
 387   url_ = url;
 388   user_results_ = results;
 389   bound_net_log_ = net_log;
 390
 391   Start(GET_PROXY_FOR_URL, false /*non-blocking*/, callback);
 392 }
 393
 394 void ProxyResolverV8Tracing::Job::Cancel() {
 395   CheckIsOnOriginThread();
 396
 397   // There are several possibilities to consider for cancellation:
 398   // (a) The job has been posted to the worker thread, however script execution
 399   //     has not yet started.
 400   // (b) The script is executing on the worker thread.
 401   // (c) The script is executing on the worker thread, however is blocked inside
 402   //     of dnsResolve() waiting for a response from the origin thread.
 403   // (d) Nothing is running on the worker thread, however the host resolver has
 404   //     a pending DNS request which upon completion will restart the script
 405   //     execution.
 406   // (e) The worker thread has a pending task to restart execution, which was
 407   //     posted after the DNS dependency was resolved and saved to local cache.
 408   // (f) The script execution completed entirely, and posted a task to the
 409   //     origin thread to notify the caller.
 410   //
 411   // |cancelled_| is read on both the origin thread and worker thread. The
 412   // code that runs on the worker thread is littered with checks on
 413   // |cancelled_| to break out early.
 414   cancelled_.Set();
 415
 416   ReleaseCallback();
 417
 418   if (pending_dns_) {
 419     host_resolver()->CancelRequest(pending_dns_);
 420     pending_dns_ = NULL;
 421   }
 422
 423   // The worker thread might be blocked waiting for DNS.
 424   event_.Signal();
 425
 426   owned_self_reference_ = NULL;
 427 }
 428
 429 LoadState ProxyResolverV8Tracing::Job::GetLoadState() const {
 430   CheckIsOnOriginThread();
 431
 432   if (pending_dns_)
 433     return LOAD_STATE_RESOLVING_HOST_IN_PROXY_SCRIPT;
 434
 435   return LOAD_STATE_RESOLVING_PROXY_FOR_URL;
 436 }
 437
 438 ProxyResolverV8Tracing::Job::~Job() {
 439   DCHECK(!pending_dns_);
 440   DCHECK(callback_.is_null());
 441 }
 442
 443 void ProxyResolverV8Tracing::Job::CheckIsOnWorkerThread() const {
 444   DCHECK_EQ(base::MessageLoop::current(), parent_->thread_->message_loop());
 445 }
 446
 447 void ProxyResolverV8Tracing::Job::CheckIsOnOriginThread() const {
 448   DCHECK(origin_loop_->BelongsToCurrentThread());
 449 }
 450
 451 void ProxyResolverV8Tracing::Job::SetCallback(
 452     const CompletionCallback& callback) {
 453   CheckIsOnOriginThread();
 454   DCHECK(callback_.is_null());
 455   parent_->num_outstanding_callbacks_++;
 456   callback_ = callback;
 457 }
 458
 459 void ProxyResolverV8Tracing::Job::ReleaseCallback() {
 460   CheckIsOnOriginThread();
 461   DCHECK(!callback_.is_null());
 462   CHECK_GT(parent_->num_outstanding_callbacks_, 0);
 463   parent_->num_outstanding_callbacks_--;
 464   callback_.Reset();
 465
 466   // For good measure, clear this other user-owned pointer.
 467   user_results_ = NULL;
 468 }
 469
 470 ProxyResolverV8* ProxyResolverV8Tracing::Job::v8_resolver() {
 471   return parent_->v8_resolver_.get();
 472 }
 473
 474 base::MessageLoop* ProxyResolverV8Tracing::Job::worker_loop() {
 475   return parent_->thread_->message_loop();
 476 }
 477
 478 HostResolver* ProxyResolverV8Tracing::Job::host_resolver() {
 479   return parent_->host_resolver_;
 480 }
 481
 482 ProxyResolverErrorObserver* ProxyResolverV8Tracing::Job::error_observer() {
 483   return parent_->error_observer_.get();
 484 }
 485
 486 NetLog* ProxyResolverV8Tracing::Job::net_log() {
 487   return parent_->net_log_;
 488 }
 489
 490 void ProxyResolverV8Tracing::Job::NotifyCaller(int result) {
 491   CheckIsOnWorkerThread();
 492
 493   metrics_end_time_ = base::TimeTicks::Now();
 494
 495   origin_loop_->PostTask(
 496       FROM_HERE,
 497       base::Bind(&Job::NotifyCallerOnOriginLoop, this, result));
 498 }
 499
 500 void ProxyResolverV8Tracing::Job::NotifyCallerOnOriginLoop(int result) {
 501   CheckIsOnOriginThread();
 502
 503   if (cancelled_.IsSet())
 504     return;
 505
 506   DCHECK(!callback_.is_null());
 507   DCHECK(!pending_dns_);
 508
 509   if (operation_ == GET_PROXY_FOR_URL) {
 510     RecordMetrics();
 511     *user_results_ = results_;
 512   }
 513
 514   // There is only ever 1 outstanding SET_PAC_SCRIPT job. It needs to be
 515   // tracked to support cancellation.
 516   if (operation_ == SET_PAC_SCRIPT) {
 517     DCHECK_EQ(parent_->set_pac_script_job_.get(), this);
 518     parent_->set_pac_script_job_ = NULL;
 519   }
 520
 521   CompletionCallback callback = callback_;
 522   ReleaseCallback();
 523   callback.Run(result);
 524
 525   owned_self_reference_ = NULL;
 526 }
 527
 528 void ProxyResolverV8Tracing::Job::RecordMetrics() const {
 529   CheckIsOnOriginThread();
 530   DCHECK_EQ(GET_PROXY_FOR_URL, operation_);
 531
 532   base::TimeTicks now = base::TimeTicks::Now();
 533
 534   // Metrics are output for each completed request to GetProxyForURL()).
 535   //
 536   // Note that a different set of histograms is used to record the metrics for
 537   // requests that completed in non-blocking mode versus blocking mode. The
 538   // expectation is for requests to complete in non-blocking mode each time.
 539   // If they don't then something strange is happening, and the purpose of the
 540   // seprate statistics is to better understand that trend.
 541 #define UPDATE_HISTOGRAMS(base_name) \
 542   do {\
 543   UMA_HISTOGRAM_MEDIUM_TIMES(base_name "TotalTime", now - metrics_start_time_);\
 544   UMA_HISTOGRAM_MEDIUM_TIMES(base_name "TotalTimeWorkerThread",\
 545                              metrics_end_time_ - metrics_start_time_);\
 546   UMA_HISTOGRAM_TIMES(base_name "OriginThreadLatency",\
 547                       now - metrics_end_time_);\
 548   UMA_HISTOGRAM_MEDIUM_TIMES(base_name "TotalTimeDNS",\
 549                              metrics_dns_total_time_);\
 550   UMA_HISTOGRAM_MEDIUM_TIMES(base_name "ExecutionTime",\
 551                              metrics_execution_time_);\
 552   UMA_HISTOGRAM_MEDIUM_TIMES(base_name "AbandonedExecutionTotalTime",\
 553                              metrics_abandoned_execution_total_time_);\
 554   UMA_HISTOGRAM_MEDIUM_TIMES(base_name "DnsWaitTotalTime",\
 555                              metrics_nonblocking_dns_wait_total_time_);\
 556   UMA_HISTOGRAM_CUSTOM_COUNTS(\
 557       base_name "NumRestarts", metrics_num_executions_ - 1,\
 558       1, kMaxUniqueResolveDnsPerExec, kMaxUniqueResolveDnsPerExec);\
 559   UMA_HISTOGRAM_CUSTOM_COUNTS(\
 560       base_name "UniqueDNS", metrics_num_unique_dns_,\
 561       1, kMaxUniqueResolveDnsPerExec, kMaxUniqueResolveDnsPerExec);\
 562   UMA_HISTOGRAM_COUNTS_100(base_name "NumAlerts", metrics_num_alerts_);\
 563   UMA_HISTOGRAM_CUSTOM_COUNTS(\
 564       base_name "NumErrors", metrics_num_errors_, 1, 10, 10);\
 565   } while (false)
 566
 567   if (!blocking_dns_)
 568     UPDATE_HISTOGRAMS("Net.ProxyResolver.");
 569   else
 570     UPDATE_HISTOGRAMS("Net.ProxyResolver.BlockingDNSMode.");
 571
 572 #undef UPDATE_HISTOGRAMS
 573
 574   // Histograms to better understand http://crbug.com/240536 -- long
 575   // URLs can cause a significant slowdown in PAC execution. Figure out how
 576   // severe this is in the wild.
 577   if (!blocking_dns_) {
 578     size_t url_size = url_.spec().size();
 579
 580     UMA_HISTOGRAM_CUSTOM_COUNTS(
 581         "Net.ProxyResolver.URLSize", url_size, 1, 200000, 50);
 582
 583     if (url_size > 2048) {
 584       UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver2K",
 585                                  metrics_execution_time_);
 586     }
 587
 588     if (url_size > 4096) {
 589       UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver4K",
 590                                  metrics_execution_time_);
 591     }
 592
 593     if (url_size > 8192) {
 594       UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver8K",
 595                                  metrics_execution_time_);
 596     }
 597
 598     if (url_size > 131072) {
 599       UMA_HISTOGRAM_MEDIUM_TIMES("Net.ProxyResolver.ExecutionTime_UrlOver128K",
 600                                  metrics_execution_time_);
 601     }
 602   }
 603 }
 604
 605
 606 void ProxyResolverV8Tracing::Job::Start(Operation op, bool blocking_dns,
 607                                         const CompletionCallback& callback) {
 608   CheckIsOnOriginThread();
 609
 610   metrics_start_time_ = base::TimeTicks::Now();
 611   operation_ = op;
 612   blocking_dns_ = blocking_dns;
 613   SetCallback(callback);
 614
 615   owned_self_reference_ = this;
 616
 617   worker_loop()->PostTask(FROM_HERE,
 618       blocking_dns_ ? base::Bind(&Job::ExecuteBlocking, this) :
 619                       base::Bind(&Job::ExecuteNonBlocking, this));
 620 }
 621
 622 void ProxyResolverV8Tracing::Job::ExecuteBlocking() {
 623   CheckIsOnWorkerThread();
 624   DCHECK(blocking_dns_);
 625
 626   if (cancelled_.IsSet())
 627     return;
 628
 629   NotifyCaller(ExecuteProxyResolver());
 630 }
 631
 632 void ProxyResolverV8Tracing::Job::ExecuteNonBlocking() {
 633   CheckIsOnWorkerThread();
 634   DCHECK(!blocking_dns_);
 635
 636   if (cancelled_.IsSet())
 637     return;
 638
 639   // Reset state for the current execution.
 640   abandoned_ = false;
 641   num_dns_ = 0;
 642   alerts_and_errors_.clear();
 643   alerts_and_errors_byte_cost_ = 0;
 644   should_restart_with_blocking_dns_ = false;
 645
 646   int result = ExecuteProxyResolver();
 647
 648   if (abandoned_)
 649     metrics_abandoned_execution_total_time_ += metrics_execution_time_;
 650
 651   if (should_restart_with_blocking_dns_) {
 652     DCHECK(!blocking_dns_);
 653     DCHECK(abandoned_);
 654     blocking_dns_ = true;
 655     ExecuteBlocking();
 656     return;
 657   }
 658
 659   if (abandoned_)
 660     return;
 661
 662   DispatchBufferedAlertsAndErrors();
 663   NotifyCaller(result);
 664 }
 665
 666 int ProxyResolverV8Tracing::Job::ExecuteProxyResolver() {
 667   IncrementWithoutOverflow(&metrics_num_executions_);
 668
 669   base::TimeTicks start = base::TimeTicks::Now();
 670
 671   JSBindings* prev_bindings = v8_resolver()->js_bindings();
 672   v8_resolver()->set_js_bindings(this);
 673
 674   int result = ERR_UNEXPECTED;  // Initialized to silence warnings.
 675
 676   switch (operation_) {
 677     case SET_PAC_SCRIPT:
 678       result = v8_resolver()->SetPacScript(
 679           script_data_, CompletionCallback());
 680       break;
 681     case GET_PROXY_FOR_URL:
 682       result = v8_resolver()->GetProxyForURL(
 683         url_,
 684         // Important: Do not write directly into |user_results_|, since if the
 685         // request were to be cancelled from the origin thread, must guarantee
 686         // that |user_results_| is not accessed anymore.
 687         &results_,
 688         CompletionCallback(),
 689         NULL,
 690         bound_net_log_);
 691       break;
 692   }
 693
 694   v8_resolver()->set_js_bindings(prev_bindings);
 695
 696   metrics_execution_time_ = base::TimeTicks::Now() - start;
 697
 698   return result;
 699 }
 700
 701 bool ProxyResolverV8Tracing::Job::ResolveDns(const std::string& host,
 702                                              ResolveDnsOperation op,
 703                                              std::string* output,
 704                                              bool* terminate) {
 705   if (cancelled_.IsSet()) {
 706     *terminate = true;
 707     return false;
 708   }
 709
 710   if ((op == DNS_RESOLVE || op == DNS_RESOLVE_EX) && host.empty()) {
 711     // a DNS resolve with an empty hostname is considered an error.
 712     return false;
 713   }
 714
 715   return blocking_dns_ ?
 716       ResolveDnsBlocking(host, op, output) :
 717       ResolveDnsNonBlocking(host, op, output, terminate);
 718 }
 719
 720 void ProxyResolverV8Tracing::Job::Alert(const base::string16& message) {
 721   HandleAlertOrError(true, -1, message);
 722 }
 723
 724 void ProxyResolverV8Tracing::Job::OnError(int line_number,
 725                                           const base::string16& error) {
 726   HandleAlertOrError(false, line_number, error);
 727 }
 728
 729 bool ProxyResolverV8Tracing::Job::ResolveDnsBlocking(const std::string& host,
 730                                                      ResolveDnsOperation op,
 731                                                      std::string* output) {
 732   CheckIsOnWorkerThread();
 733
 734   // Check if the DNS result for this host has already been cached.
 735   bool rv;
 736   if (GetDnsFromLocalCache(host, op, output, &rv)) {
 737     // Yay, cache hit!
 738     return rv;
 739   }
 740
 741   // If the host was not in the local cache, this is a new hostname.
 742   IncrementWithoutOverflow(&metrics_num_unique_dns_);
 743
 744   if (dns_cache_.size() >= kMaxUniqueResolveDnsPerExec) {
 745     // Safety net for scripts with unexpectedly many DNS calls.
 746     // We will continue running to completion, but will fail every
 747     // subsequent DNS request.
 748     return false;
 749   }
 750
 751   if (!PostDnsOperationAndWait(host, op, NULL))
 752     return false;  // Was cancelled.
 753
 754   CHECK(GetDnsFromLocalCache(host, op, output, &rv));
 755   return rv;
 756 }
 757
 758 bool ProxyResolverV8Tracing::Job::ResolveDnsNonBlocking(const std::string& host,
 759                                                         ResolveDnsOperation op,
 760                                                         std::string* output,
 761                                                         bool* terminate) {
 762   CheckIsOnWorkerThread();
 763
 764   if (abandoned_) {
 765     // If this execution was already abandoned can fail right away. Only 1 DNS
 766     // dependency will be traced at a time (for more predictable outcomes).
 767     return false;
 768   }
 769
 770   num_dns_ += 1;
 771
 772   // Check if the DNS result for this host has already been cached.
 773   bool rv;
 774   if (GetDnsFromLocalCache(host, op, output, &rv)) {
 775     // Yay, cache hit!
 776     return rv;
 777   }
 778
 779   // If the host was not in the local cache, then this is a new hostname.
 780   IncrementWithoutOverflow(&metrics_num_unique_dns_);
 781
 782   if (num_dns_ <= last_num_dns_) {
 783     // The sequence of DNS operations is different from last time!
 784     ScheduleRestartWithBlockingDns();
 785     *terminate = true;
 786     return false;
 787   }
 788
 789   if (dns_cache_.size() >= kMaxUniqueResolveDnsPerExec) {
 790     // Safety net for scripts with unexpectedly many DNS calls.
 791     return false;
 792   }
 793
 794   DCHECK(!should_restart_with_blocking_dns_);
 795
 796   bool completed_synchronously;
 797   if (!PostDnsOperationAndWait(host, op, &completed_synchronously))
 798     return false;  // Was cancelled.
 799
 800   if (completed_synchronously) {
 801     CHECK(GetDnsFromLocalCache(host, op, output, &rv));
 802     return rv;
 803   }
 804
 805   // Otherwise if the result was not in the cache, then a DNS request has
 806   // been started. Abandon this invocation of FindProxyForURL(), it will be
 807   // restarted once the DNS request completes.
 808   abandoned_ = true;
 809   *terminate = true;
 810   last_num_dns_ = num_dns_;
 811   return false;
 812 }
 813
 814 bool ProxyResolverV8Tracing::Job::PostDnsOperationAndWait(
 815     const std::string& host, ResolveDnsOperation op,
 816     bool* completed_synchronously) {
 817
 818   base::TimeTicks start = base::TimeTicks::Now();
 819
 820   // Post the DNS request to the origin thread.
 821   DCHECK(!pending_dns_);
 822   metrics_pending_dns_start_ = base::TimeTicks::Now();
 823   pending_dns_host_ = host;
 824   pending_dns_op_ = op;
 825   origin_loop_->PostTask(FROM_HERE, base::Bind(&Job::DoDnsOperation, this));
 826
 827   event_.Wait();
 828   event_.Reset();
 829
 830   if (cancelled_.IsSet())
 831     return false;
 832
 833   if (completed_synchronously)
 834     *completed_synchronously = pending_dns_completed_synchronously_;
 835
 836   if (!blocking_dns_)
 837     metrics_nonblocking_dns_wait_total_time_ += base::TimeTicks::Now() - start;
 838
 839   return true;
 840 }
 841
 842 void ProxyResolverV8Tracing::Job::DoDnsOperation() {
 843   CheckIsOnOriginThread();
 844   DCHECK(!pending_dns_);
 845
 846   if (cancelled_.IsSet())
 847     return;
 848
 849   HostResolver::RequestHandle dns_request = NULL;
 850   int result = host_resolver()->Resolve(
 851       MakeDnsRequestInfo(pending_dns_host_, pending_dns_op_),
 852       DEFAULT_PRIORITY,
 853       &pending_dns_addresses_,
 854       base::Bind(&Job::OnDnsOperationComplete, this),
 855       &dns_request,
 856       bound_net_log_);
 857
 858   pending_dns_completed_synchronously_ = result != ERR_IO_PENDING;
 859
 860   // Check if the request was cancelled as a side-effect of calling into the
 861   // HostResolver. This isn't the ordinary execution flow, however it is
 862   // exercised by unit-tests.
 863   if (cancelled_.IsSet()) {
 864     if (!pending_dns_completed_synchronously_)
 865       host_resolver()->CancelRequest(dns_request);
 866     return;
 867   }
 868
 869   if (pending_dns_completed_synchronously_) {
 870     OnDnsOperationComplete(result);
 871   } else {
 872     DCHECK(dns_request);
 873     pending_dns_ = dns_request;
 874     // OnDnsOperationComplete() will be called by host resolver on completion.
 875   }
 876
 877   if (!blocking_dns_) {
 878     // The worker thread always blocks waiting to see if the result can be
 879     // serviced from cache before restarting.
 880     event_.Signal();
 881   }
 882 }
 883
 884 void ProxyResolverV8Tracing::Job::OnDnsOperationComplete(int result) {
 885   CheckIsOnOriginThread();
 886
 887   DCHECK(!cancelled_.IsSet());
 888   DCHECK(pending_dns_completed_synchronously_ == (pending_dns_ == NULL));
 889
 890   SaveDnsToLocalCache(pending_dns_host_, pending_dns_op_, result,
 891                       pending_dns_addresses_);
 892   pending_dns_ = NULL;
 893
 894   metrics_dns_total_time_ +=
 895       base::TimeTicks::Now() - metrics_pending_dns_start_;
 896
 897   if (blocking_dns_) {
 898     event_.Signal();
 899     return;
 900   }
 901
 902   if (!blocking_dns_ && !pending_dns_completed_synchronously_) {
 903     // Restart. This time it should make more progress due to having
 904     // cached items.
 905     worker_loop()->PostTask(FROM_HERE,
 906                             base::Bind(&Job::ExecuteNonBlocking, this));
 907   }
 908 }
 909
 910 void ProxyResolverV8Tracing::Job::ScheduleRestartWithBlockingDns() {
 911   CheckIsOnWorkerThread();
 912
 913   DCHECK(!should_restart_with_blocking_dns_);
 914   DCHECK(!abandoned_);
 915   DCHECK(!blocking_dns_);
 916
 917   abandoned_ = true;
 918
 919   // The restart will happen after ExecuteNonBlocking() finishes.
 920   should_restart_with_blocking_dns_ = true;
 921 }
 922
 923 bool ProxyResolverV8Tracing::Job::GetDnsFromLocalCache(
 924     const std::string& host,
 925     ResolveDnsOperation op,
 926     std::string* output,
 927     bool* return_value) {
 928   CheckIsOnWorkerThread();
 929
 930   DnsCache::const_iterator it = dns_cache_.find(MakeDnsCacheKey(host, op));
 931   if (it == dns_cache_.end())
 932     return false;
 933
 934   *output = it->second;
 935   *return_value = !it->second.empty();
 936   return true;
 937 }
 938
 939 void ProxyResolverV8Tracing::Job::SaveDnsToLocalCache(
 940     const std::string& host,
 941     ResolveDnsOperation op,
 942     int net_error,
 943     const net::AddressList& addresses) {
 944   CheckIsOnOriginThread();
 945
 946   // Serialize the result into a string to save to the cache.
 947   std::string cache_value;
 948   if (net_error != OK) {
 949     cache_value = std::string();
 950   } else if (op == DNS_RESOLVE || op == MY_IP_ADDRESS) {
 951     // dnsResolve() and myIpAddress() are expected to return a single IP
 952     // address.
 953     cache_value = addresses.front().ToStringWithoutPort();
 954   } else {
 955     // The *Ex versions are expected to return a semi-colon separated list.
 956     for (AddressList::const_iterator iter = addresses.begin();
 957          iter != addresses.end(); ++iter) {
 958       if (!cache_value.empty())
 959         cache_value += ";";
 960       cache_value += iter->ToStringWithoutPort();
 961     }
 962   }
 963
 964   dns_cache_[MakeDnsCacheKey(host, op)] = cache_value;
 965 }
 966
 967 // static
 968 HostResolver::RequestInfo ProxyResolverV8Tracing::Job::MakeDnsRequestInfo(
 969     const std::string& host, ResolveDnsOperation op) {
 970   HostPortPair host_port = HostPortPair(host, 80);
 971   if (op == MY_IP_ADDRESS || op == MY_IP_ADDRESS_EX) {
 972     host_port.set_host(GetHostName());
 973   }
 974
 975   HostResolver::RequestInfo info(host_port);
 976
 977   // The non-ex flavors are limited to IPv4 results.
 978   if (op == MY_IP_ADDRESS || op == DNS_RESOLVE) {
 979     info.set_address_family(ADDRESS_FAMILY_IPV4);
 980   }
 981
 982   return info;
 983 }
 984
 985 std::string ProxyResolverV8Tracing::Job::MakeDnsCacheKey(
 986     const std::string& host, ResolveDnsOperation op) {
 987   return base::StringPrintf("%d:%s", op, host.c_str());
 988 }
 989
 990 void ProxyResolverV8Tracing::Job::HandleAlertOrError(
 991     bool is_alert,
 992     int line_number,
 993     const base::string16& message) {
 994   CheckIsOnWorkerThread();
 995
 996   if (cancelled_.IsSet())
 997     return;
 998
 999   if (blocking_dns_) {
1000     // In blocking DNS mode the events can be dispatched immediately.
1001     DispatchAlertOrError(is_alert, line_number, message);
1002     return;
1003   }
1004
1005   // Otherwise in nonblocking mode, buffer all the messages until
1006   // the end.
1007
1008   if (abandoned_)
1009     return;
1010
1011   alerts_and_errors_byte_cost_ += sizeof(AlertOrError) + message.size() * 2;
1012
1013   // If there have been lots of messages, enqueing could be expensive on
1014   // memory. Consider a script which does megabytes worth of alerts().
1015   // Avoid this by falling back to blocking mode.
1016   if (alerts_and_errors_byte_cost_ > kMaxAlertsAndErrorsBytes) {
1017     ScheduleRestartWithBlockingDns();
1018     return;
1019   }
1020
1021   AlertOrError entry = {is_alert, line_number, message};
1022   alerts_and_errors_.push_back(entry);
1023 }
1024
1025 void ProxyResolverV8Tracing::Job::DispatchBufferedAlertsAndErrors() {
1026   CheckIsOnWorkerThread();
1027   DCHECK(!blocking_dns_);
1028   DCHECK(!abandoned_);
1029
1030   for (size_t i = 0; i < alerts_and_errors_.size(); ++i) {
1031     const AlertOrError& x = alerts_and_errors_[i];
1032     DispatchAlertOrError(x.is_alert, x.line_number, x.message);
1033   }
1034 }
1035
1036 void ProxyResolverV8Tracing::Job::DispatchAlertOrError(
1037     bool is_alert, int line_number, const base::string16& message) {
1038   CheckIsOnWorkerThread();
1039
1040   // Note that the handling of cancellation is racy with regard to
1041   // alerts/errors. The request might get cancelled shortly after this
1042   // check! (There is no lock being held to guarantee otherwise).
1043   //
1044   // If this happens, then some information will get written to the NetLog
1045   // needlessly, however the NetLog will still be alive so it shouldn't cause
1046   // problems.
1047   if (cancelled_.IsSet())
1048     return;
1049
1050   if (is_alert) {
1051     // -------------------
1052     // alert
1053     // -------------------
1054     IncrementWithoutOverflow(&metrics_num_alerts_);
1055     VLOG(1) << "PAC-alert: " << message;
1056
1057     // Send to the NetLog.
1058     LogEventToCurrentRequestAndGlobally(
1059         NetLog::TYPE_PAC_JAVASCRIPT_ALERT,
1060         NetLog::StringCallback("message", &message));
1061   } else {
1062     // -------------------
1063     // error
1064     // -------------------
1065     IncrementWithoutOverflow(&metrics_num_errors_);
1066     if (line_number == -1)
1067       VLOG(1) << "PAC-error: " << message;
1068     else
1069       VLOG(1) << "PAC-error: " << "line: " << line_number << ": " << message;
1070
1071     // Send the error to the NetLog.
1072     LogEventToCurrentRequestAndGlobally(
1073         NetLog::TYPE_PAC_JAVASCRIPT_ERROR,
1074         base::Bind(&NetLogErrorCallback, line_number, &message));
1075
1076     if (error_observer())
1077       error_observer()->OnPACScriptError(line_number, message);
1078   }
1079 }
1080
1081 void ProxyResolverV8Tracing::Job::LogEventToCurrentRequestAndGlobally(
1082     NetLog::EventType type,
1083     const NetLog::ParametersCallback& parameters_callback) {
1084   CheckIsOnWorkerThread();
1085   bound_net_log_.AddEvent(type, parameters_callback);
1086
1087   // Emit to the global NetLog event stream.
1088   if (net_log())
1089     net_log()->AddGlobalEntry(type, parameters_callback);
1090 }
1091
1092 ProxyResolverV8Tracing::ProxyResolverV8Tracing(
1093     HostResolver* host_resolver,
1094     ProxyResolverErrorObserver* error_observer,
1095     NetLog* net_log)
1096     : ProxyResolver(true /*expects_pac_bytes*/),
1097       host_resolver_(host_resolver),
1098       error_observer_(error_observer),
1099       net_log_(net_log),
1100       num_outstanding_callbacks_(0) {
1101   DCHECK(host_resolver);
1102   // Start up the thread.
1103   thread_.reset(new base::Thread("Proxy resolver"));
1104   CHECK(thread_->Start());
1105
1106   v8_resolver_.reset(new ProxyResolverV8);
1107 }
1108
1109 ProxyResolverV8Tracing::~ProxyResolverV8Tracing() {
1110   // Note, all requests should have been cancelled.
1111   CHECK(!set_pac_script_job_.get());
1112   CHECK_EQ(0, num_outstanding_callbacks_);
1113
1114   // Join the worker thread. See http://crbug.com/69710. Note that we call
1115   // Stop() here instead of simply clearing thread_ since there may be pending
1116   // callbacks on the worker thread which want to dereference thread_.
1117   base::ThreadRestrictions::ScopedAllowIO allow_io;
1118   thread_->Stop();
1119 }
1120
1121 int ProxyResolverV8Tracing::GetProxyForURL(const GURL& url,
1122                                            ProxyInfo* results,
1123                                            const CompletionCallback& callback,
1124                                            RequestHandle* request,
1125                                            const BoundNetLog& net_log) {
1126   DCHECK(CalledOnValidThread());
1127   DCHECK(!callback.is_null());
1128   DCHECK(!set_pac_script_job_.get());
1129
1130   scoped_refptr<Job> job = new Job(this);
1131
1132   if (request)
1133     *request = job.get();
1134
1135   job->StartGetProxyForURL(url, results, net_log, callback);
1136   return ERR_IO_PENDING;
1137 }
1138
1139 void ProxyResolverV8Tracing::CancelRequest(RequestHandle request) {
1140   Job* job = reinterpret_cast<Job*>(request);
1141   job->Cancel();
1142 }
1143
1144 LoadState ProxyResolverV8Tracing::GetLoadState(RequestHandle request) const {
1145   Job* job = reinterpret_cast<Job*>(request);
1146   return job->GetLoadState();
1147 }
1148
1149 void ProxyResolverV8Tracing::CancelSetPacScript() {
1150   DCHECK(set_pac_script_job_.get());
1151   set_pac_script_job_->Cancel();
1152   set_pac_script_job_ = NULL;
1153 }
1154
1155 void ProxyResolverV8Tracing::PurgeMemory() {
1156   thread_->message_loop()->PostTask(
1157       FROM_HERE,
1158       base::Bind(&ProxyResolverV8::PurgeMemory,
1159                  // The use of unretained is safe, since the worker thread
1160                  // cannot outlive |this|.
1161                  base::Unretained(v8_resolver_.get())));
1162 }
1163
1164 int ProxyResolverV8Tracing::SetPacScript(
1165     const scoped_refptr<ProxyResolverScriptData>& script_data,
1166     const CompletionCallback& callback) {
1167   DCHECK(CalledOnValidThread());
1168   DCHECK(!callback.is_null());
1169
1170   // Note that there should not be any outstanding (non-cancelled) Jobs when
1171   // setting the PAC script (ProxyService should guarantee this). If there are,
1172   // then they might complete in strange ways after the new script is set.
1173   DCHECK(!set_pac_script_job_.get());
1174   CHECK_EQ(0, num_outstanding_callbacks_);
1175
1176   set_pac_script_job_ = new Job(this);
1177   set_pac_script_job_->StartSetPacScript(script_data, callback);
1178
1179   return ERR_IO_PENDING;
1180 }
1181
1182 }  // namespace net