Add some histograms for <a ping> requests.

content/browser/loader/detachable_resource_handler.cc

 // Copyright 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 "content/browser/loader/detachable_resource_handler.h"
 
 #include "base/logging.h"
+#include "base/metrics/histogram.h"
 #include "base/time/time.h"
 #include "content/browser/loader/resource_request_info_impl.h"
 #include "net/base/io_buffer.h"
 #include "net/base/net_errors.h"
 #include "net/url_request/url_request_status.h"
 
 namespace {
+
 // This matches the maximum allocation size of AsyncResourceHandler.
 const int kReadBufSize = 32 * 1024;
+
+// Enum type for <a ping> result.

[mmenke, 2014/01/27 22:51:54]

Think you should mention histograms, and new results being added to the end. 
I'm paranoid.

[davidben, 2014/01/28 19:52:41]

Done.

+enum UMAPingResultType {
+  // The ping request received a response.
+  UMA_PING_RESULT_TYPE_RESPONSE_STARTED = 0,
+  // The ping request was canceled due to the internal timeout.
+  UMA_PING_RESULT_TYPE_TIMEDOUT = 1,
+  // The ping request was canceled for some other reason.
+  UMA_PING_RESULT_TYPE_CANCELED = 2,
+  // The ping request failed for some reason.
+  UMA_PING_RESULT_TYPE_FAILED = 3,
+  // The ping request was aborted before OnResponseCompleted.
+  UMA_PING_RESULT_TYPE_UNCOMPLETED = 4,
+
+  UMA_PING_RESULT_TYPE_MAX,
+};
+
 }

[mmenke, 2014/01/27 22:51:54]

nit:  "}  // namespace"

[davidben, 2014/01/28 19:52:41]

Done.

 
 namespace content {
 
 DetachableResourceHandler::DetachableResourceHandler(
     net::URLRequest* request,
     base::TimeDelta cancel_delay,
     scoped_ptr<ResourceHandler> next_handler)
     : ResourceHandler(request),
       next_handler_(next_handler.Pass()),
       cancel_delay_(cancel_delay),
       is_deferred_(false),
-      is_finished_(false) {
+      is_finished_(false),
+      timed_out_(false),
+      response_started_(false),
+      response_completed_(false) {
   GetRequestInfo()->set_detachable_handler(this);
 }
 
 DetachableResourceHandler::~DetachableResourceHandler() {
   // Cleanup back-pointer stored on the request info.
   GetRequestInfo()->set_detachable_handler(NULL);
+
+  // Record the status of <a ping> requests.
+  // http://crbug.com/302816
+  if (GetRequestInfo()->GetResourceType() == ResourceType::PING) {
+    UMAPingResultType result_type = UMA_PING_RESULT_TYPE_MAX;
+    if (response_started_) {

[mmenke, 2014/01/27 22:51:54]

optional:  Just out of curiousity/paranoia / whatever, maybe log the
successfully completed ones separately from those that just started?  I don't
expect a whole lot with start and not (response_completed_ + status is OK), but
just seems a little odd not to separate them out.

[davidben, 2014/01/28 19:52:41]

Done.

+      result_type = UMA_PING_RESULT_TYPE_RESPONSE_STARTED;
+    } else if (timed_out_) {
+      result_type = UMA_PING_RESULT_TYPE_TIMEDOUT;

[mmenke, 2014/01/27 22:51:54]

Shouldn't we end up in the CANCELED bucket here?  If so, I think it's a bit more
consistent to put this below the response_completed_ test, just before the
canceled one.

[davidben, 2014/01/28 19:52:41]

Done.

+    } else if (!response_completed_) {

[mmenke, 2014/01/27 22:51:54]

I think response_completed_ is a confusing name here, since at this point, it
means the request "completed" with an error message, without a response ever
being started.

Maybe just a comment about the weirdness?

[davidben, 2014/01/28 19:52:41]

Added a comment.

+      result_type = UMA_PING_RESULT_TYPE_UNCOMPLETED;
+    } else if (status_ == net::URLRequestStatus::CANCELED) {
+      result_type = UMA_PING_RESULT_TYPE_CANCELED;
+    } else if (status_ == net::URLRequestStatus::FAILED) {
+      result_type = UMA_PING_RESULT_TYPE_FAILED;
+    }
+
+    if (result_type < UMA_PING_RESULT_TYPE_MAX) {
+      UMA_HISTOGRAM_ENUMERATION("Net.Ping_Result", result_type,
+                                UMA_PING_RESULT_TYPE_MAX);
+    } else {
+      // This shouldn't happen. If the request succeeds, |response_started_|
+      // will be true.
+      NOTREACHED();
+    }
+  }
 }
 
 void DetachableResourceHandler::Detach() {
   if (is_detached())
     return;
 
   if (!is_finished_) {
     // Simulate a cancel on the next handler before destroying it.
     net::URLRequestStatus status(net::URLRequestStatus::CANCELED,
                                  net::ERR_ABORTED);
@@ skipping 12 matching lines @@
   // OnWillRead passes back a scoped_refptr, so downstream handler's buffer will
   // survive long enough to complete that read. From there, future reads will
   // drain into |read_buffer_|. (If |next_handler_| is an AsyncResourceHandler,
   // the net::IOBuffer takes a reference to the ResourceBuffer which owns the
   // shared memory.)
   next_handler_.reset();
 
   // Time the request out if it takes too long.
   detached_timer_.reset(new base::OneShotTimer<DetachableResourceHandler>());
   detached_timer_->Start(
-      FROM_HERE, cancel_delay_, this, &DetachableResourceHandler::Cancel);
+      FROM_HERE, cancel_delay_, this, &DetachableResourceHandler::TimedOut);
 
   // Resume if necessary. The request may have been deferred, say, waiting on a
   // full buffer in AsyncResourceHandler. Now that it has been detached, resume
   // and drain it.
   if (is_deferred_)
     Resume();
 }
 
 void DetachableResourceHandler::SetController(ResourceController* controller) {
   ResourceHandler::SetController(controller);
@@ skipping 25 matching lines @@
   bool ret = next_handler_->OnRequestRedirected(request_id, url, response,
                                                 &is_deferred_);
   *defer = is_deferred_;
   return ret;
 }
 
 bool DetachableResourceHandler::OnResponseStarted(int request_id,
                                                   ResourceResponse* response,
                                                   bool* defer) {
   DCHECK(!is_deferred_);
+  DCHECK(!response_started_);
+  response_started_ = true;
+
+  // Record how long it takes for <a ping> to respond.
+  // http://crbug.com/302816
+  if (GetRequestInfo()->GetResourceType() == ResourceType::PING) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Net.Ping_ResponseStartedTime",
+                               time_since_start_.Elapsed());
+  }
 
   if (!next_handler_)
     return true;
 
   bool ret =
       next_handler_->OnResponseStarted(request_id, response, &is_deferred_);
   *defer = is_deferred_;
   return ret;
 }
 
@@ skipping 53 matching lines @@
 }
 
 void DetachableResourceHandler::OnResponseCompleted(
     int request_id,
     const net::URLRequestStatus& status,
     const std::string& security_info,
     bool* defer) {
   // No DCHECK(!is_deferred_) as the request may have been cancelled while
   // deferred.
 
+  response_completed_ = true;
+  status_ = status.status();
+
   if (!next_handler_)
     return;
 
   is_finished_ = true;
 
   next_handler_->OnResponseCompleted(request_id, status, security_info,
                                      &is_deferred_);
   *defer = is_deferred_;
 }
 
@@ skipping 16 matching lines @@
 }
 
 void DetachableResourceHandler::CancelAndIgnore() {
   controller()->CancelAndIgnore();
 }
 
 void DetachableResourceHandler::CancelWithError(int error_code) {
   controller()->CancelWithError(error_code);
 }
 
+void DetachableResourceHandler::TimedOut() {
+  timed_out_ = true;
+  controller()->Cancel();
+}
+
 }  // namespace content