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 821 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());
 
+    // This state is cleared when resolve_job_ is set to nullptr below.
+    bool script_executed = is_started();
+
     // 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_);
+    int rv = service_->DidFinishResolvingProxy(
+        url_, load_flags_, network_delegate_, results_, result_code, net_log_,
+        creation_time_, script_executed);

[eroman, 2015/05/11 23:42:40]

Creation time of the Request may not be the same as when the
ProxyService::Resolve started. Pretty similar to the issue in bug 484902, so
maybe fine to leave it to that to solve (by passing in the start time as a
dependency to Request rather than using Now() in its constructor)

[Anand Mistry (off Chromium), 2015/05/12 00:33:25]

Since ResolveProxyHelper creates this object, which sets the creation time in
the constructor, I think the time difference between the two is going to be very
small. On the order of microseconds, or less.

 
     // 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_ = creation_time_;
     results_->proxy_resolve_end_time_ = TimeTicks::Now();
 
     // Reset the state associated with in-progress-resolve.
@@ skipping 175 matching lines @@
     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) {
+    rv = DidFinishResolvingProxy(
+        url, load_flags, network_delegate, result, rv, net_log,
+        callback.is_null() ? TimeTicks() : TimeTicks::Now(), false);
+    return rv;
+  }
 
   if (callback.is_null())
     return ERR_IO_PENDING;
 
   scoped_refptr<PacRequest> req(
       new PacRequest(this, url, load_flags, network_delegate,
                      result, callback, net_log));
 
   if (current_state_ == STATE_READY) {
     // Start the resolve request.
@@ skipping 289 matching lines @@
   PendingRequests::iterator it = std::find(
       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) {
+                                          const BoundNetLog& net_log,
+                                          base::TimeTicks start_time,
+                                          bool script_executed) {
+  // Don't track any metrics if start_time is 0, which will happen when the user
+  // calls |TryResolveProxySynchronously|.
+  if (!start_time.is_null()) {
+    TimeDelta diff = TimeTicks::Now() - start_time;
+    if (script_executed) {
+      // This function "fixes" the result code, so make sure script terminated
+      // errors are tracked. Only track result codes that were a result of
+      // script execution.
+      UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ScriptTerminated",
+                            result_code == ERR_PAC_SCRIPT_TERMINATED);
+      UMA_HISTOGRAM_CUSTOM_TIMES("Net.ProxyService.GetProxyUsingScriptTime",
+                                 diff, base::TimeDelta::FromMicroseconds(100),
+                                 base::TimeDelta::FromSeconds(20), 50);
+    }
+    UMA_HISTOGRAM_BOOLEAN("Net.ProxyService.ResolvedUsingScript",
+                          script_executed);
+    UMA_HISTOGRAM_CUSTOM_TIMES("Net.ProxyService.ResolveProxyTime", diff,
+                               base::TimeDelta::FromMicroseconds(100),
+                               base::TimeDelta::FromSeconds(20), 50);
+  }
+
   // 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.IsCapturing()) {
       net_log.AddEvent(
@@ skipping 246 matching lines @@
   State previous_state = ResetProxyConfig(false);
   if (previous_state != STATE_NONE)
     ApplyProxyConfigIfAvailable();
 }
 
 void ProxyService::OnDNSChanged() {
   OnIPAddressChanged();
 }
 
 }  // namespace net