Add some basic UMA for proxy service.

net/proxy/proxy_service.cc

 // Copyright (c) 2012 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_service.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/compiler_specific.h"
 #include "base/logging.h"
 #include "base/memory/weak_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "base/message_loop/message_loop_proxy.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/string_util.h"
 #include "base/thread_task_runner_handle.h"
+#include "base/time/time.h"
 #include "base/values.h"
 #include "net/base/completion_callback.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_util.h"
 #include "net/log/net_log.h"
 #include "net/proxy/dhcp_proxy_script_fetcher.h"
 #include "net/proxy/multi_threaded_proxy_resolver.h"
 #include "net/proxy/network_delegate_error_observer.h"
 #include "net/proxy/proxy_config_service_fixed.h"
@@ skipping 326 matching lines @@
   ~UnsetProxyConfigService() override {}
 
   void AddObserver(Observer* observer) override {}
   void RemoveObserver(Observer* observer) override {}
   ConfigAvailability GetLatestProxyConfig(ProxyConfig* config) override {
     return CONFIG_UNSET;
   }
 };
 #endif
 
+void RecordResolveProxyTime(TimeTicks start_time) {
+  UMA_HISTOGRAM_CUSTOM_TIMES("Net.ProxyService.ResolveProxyTime",
+                             TimeTicks::Now() - start_time,
+                             base::TimeDelta::FromMicroseconds(100),
+                             base::TimeDelta::FromSeconds(20), 50);
+}
+
+void ResolveProxyCallbackHelper(TimeTicks start_time,
+                                const CompletionCallback& callback,
+                                int result) {
+  RecordResolveProxyTime(start_time);
+  callback.Run(result);
+}
+
 }  // namespace
 
 // ProxyService::InitProxyResolver --------------------------------------------
 
 // This glues together two asynchronous steps:
 //   (1) ProxyScriptDecider -- try to fetch/validate a sequence of PAC scripts
 //       to figure out what we should configure against.
 //   (2) Feed the fetched PAC script into the ProxyResolver.
 //
 // InitProxyResolver is a single-use class which encapsulates cancellation as
@@ skipping 446 matching lines @@
   bool is_started() const {
     // Note that !! casts to bool. (VS gives a warning otherwise).
     return !!resolve_job_;
   }
 
   void StartAndCompleteCheckingForSynchronous() {
     int rv = service_->TryToCompleteSynchronously(url_, load_flags_,
                                                   network_delegate_, results_);
     if (rv == ERR_IO_PENDING)
       rv = Start();
+    else
+      UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ResolvedUsingScript", false);
+
     if (rv != ERR_IO_PENDING)
       QueryComplete(rv);
   }
 
   void CancelResolveJob() {
     DCHECK(is_started());
     // The request may already be running in the resolver.
     resolver()->CancelRequest(resolve_job_);
     resolve_job_ = NULL;
     DCHECK(!is_started());
@@ skipping 16 matching lines @@
   // Returns true if Cancel() has been called.
   bool was_cancelled() const {
     return user_callback_.is_null();
   }
 
   // Helper to call after ProxyResolver completion (both synchronous and
   // asynchronous). Fixes up the result that is to be returned to user.
   int QueryDidComplete(int result_code) {
     DCHECK(!was_cancelled());
 
+    TimeTicks now = TimeTicks::Now();
+    if (is_started()) {
+      // The resolve job was completed as a result of calling |GetProxyForURL|.
+      UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ResolvedUsingScript", true);
+      UMA_HISTOGRAM_CUSTOM_TIMES("Net.ProxyService.GetProxyUsingScriptTime",
+                                 now - proxy_resolve_start_time_,
+                                 base::TimeDelta::FromMicroseconds(100),
+                                 base::TimeDelta::FromSeconds(20), 50);
+    }
+
     // Clear |resolve_job_| so is_started() returns false while
     // DidFinishResolvingProxy() runs.
     resolve_job_ = nullptr;
 
     // Note that DidFinishResolvingProxy might modify |results_|.
     int rv = service_->DidFinishResolvingProxy(url_, load_flags_,
                                                network_delegate_, results_,
                                                result_code, net_log_);
 
     // Make a note in the results which configuration was in use at the
     // time of the resolve.
     results_->config_id_ = config_id_;
     results_->config_source_ = config_source_;
     results_->did_use_pac_script_ = true;
     results_->proxy_resolve_start_time_ = proxy_resolve_start_time_;
-    results_->proxy_resolve_end_time_ = TimeTicks::Now();
+    results_->proxy_resolve_end_time_ = now;
 
     // Reset the state associated with in-progress-resolve.
     config_id_ = ProxyConfig::kInvalidConfigID;
     config_source_ = PROXY_CONFIG_SOURCE_UNKNOWN;
 
     return rv;
   }
 
   BoundNetLog* net_log() { return &net_log_; }
 
@@ skipping 148 matching lines @@
 
 int ProxyService::ResolveProxyHelper(const GURL& raw_url,
                                      int load_flags,
                                      ProxyInfo* result,
                                      const CompletionCallback& callback,
                                      PacRequest** pac_request,
                                      NetworkDelegate* network_delegate,
                                      const BoundNetLog& net_log) {
   DCHECK(CalledOnValidThread());
 
+  TimeTicks start_time = TimeTicks::Now();
   net_log.BeginEvent(NetLog::TYPE_PROXY_SERVICE);
 
   // Notify our polling-based dependencies that a resolve is taking place.
   // This way they can schedule their polls in response to network activity.
   config_service_->OnLazyPoll();
   if (script_poller_.get())
      script_poller_->OnLazyPoll();
 
   if (current_state_ == STATE_NONE)
     ApplyProxyConfigIfAvailable();
 
   // Strip away any reference fragments and the username/password, as they
   // are not relevant to proxy resolution.
   GURL url = SimplifyUrlForRequest(raw_url);
 
   // Check if the request can be completed right away. (This is the case when
   // using a direct connection for example).
   int rv = TryToCompleteSynchronously(url, load_flags,
                                       network_delegate, result);
-  if (rv != ERR_IO_PENDING)
-    return DidFinishResolvingProxy(url, load_flags, network_delegate,
-                                   result, rv, net_log);
+  if (rv != ERR_IO_PENDING) {
+    UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ResolvedUsingScript", false);

[eroman, 2015/05/08 21:12:39]

This is split between multiple locations.
Please put the logging at a single choke point, namely:
  DidFinishResolvingProxy()

This does mean that DidFinishResolvingProxy() will need to be augmented with a
parameter for the start time, and whether the completion was synchronous.
However it is better to just have one place where the completion logic is
applied.

[Anand Mistry (off Chromium), 2015/05/11 07:40:35]

Done.

+    rv = DidFinishResolvingProxy(url, load_flags, network_delegate, result, rv,
+                                 net_log);
+    RecordResolveProxyTime(start_time);
+    return rv;
+  }
 
-  if (callback.is_null())
+  if (callback.is_null()) {
+    UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ResolvedUsingScript", false);

[eroman, 2015/05/08 21:12:39]

Remove the logging here.
If there was no callback it means resolving will not be attempted.
I believe this is being used to implement TryResolveProxySynchronously()

[Anand Mistry (off Chromium), 2015/05/11 07:40:35]

Done.

+    RecordResolveProxyTime(start_time);
     return ERR_IO_PENDING;
+  }
 
-  scoped_refptr<PacRequest> req(
-      new PacRequest(this, url, load_flags, network_delegate,
-                     result, callback, net_log));
+  scoped_refptr<PacRequest> req(new PacRequest(
+      this, url, load_flags, network_delegate, result,
+      base::Bind(&ResolveProxyCallbackHelper, start_time, callback), net_log));
 
   if (current_state_ == STATE_READY) {
     // Start the resolve request.
     rv = req->Start();
-    if (rv != ERR_IO_PENDING)
+    if (rv != ERR_IO_PENDING) {
+      RecordResolveProxyTime(start_time);
       return req->QueryDidComplete(rv);
+    }
   } else {
     req->net_log()->BeginEvent(NetLog::TYPE_PROXY_SERVICE_WAITING_FOR_INIT_PAC);
   }
 
   DCHECK_EQ(ERR_IO_PENDING, rv);
   DCHECK(!ContainsPendingRequest(req.get()));
   pending_requests_.push_back(req);
 
   // Completion will be notified through |callback|, unless the caller cancels
   // the request using |pac_request|.
@@ skipping 277 matching lines @@
       pending_requests_.begin(), pending_requests_.end(), req);
   pending_requests_.erase(it);
 }
 
 int ProxyService::DidFinishResolvingProxy(const GURL& url,
                                           int load_flags,
                                           NetworkDelegate* network_delegate,
                                           ProxyInfo* result,
                                           int result_code,
                                           const BoundNetLog& net_log) {
+  // This function "fixes" the result code, so make sure script terminated
+  // errors are tracked.
+  UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ScriptTerminated",
+                        result_code == ERR_PAC_SCRIPT_TERMINATED);
+
   // Log the result of the proxy resolution.
   if (result_code == OK) {
     // Allow the network delegate to interpose on the resolution decision,
     // possibly modifying the ProxyInfo.
     if (network_delegate)
       network_delegate->NotifyResolveProxy(url, load_flags, *this, result);
 
     // When logging all events is enabled, dump the proxy list.
     if (net_log.GetCaptureMode().enabled()) {
       net_log.AddEvent(
@@ skipping 246 matching lines @@
   State previous_state = ResetProxyConfig(false);
   if (previous_state != STATE_NONE)
     ApplyProxyConfigIfAvailable();
 }
 
 void ProxyService::OnDNSChanged() {
   OnIPAddressChanged();
 }
 
 }  // namespace net