Add UMA to net::BidirectionalStream

net/http/bidirectional_stream.cc

 // Copyright 2015 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/http/bidirectional_stream.h"
 
 #include <memory>
 #include <string>
 
 #include "base/bind.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/memory/ptr_util.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/threading/thread_task_runner_handle.h"
+#include "base/time/default_tick_clock.h"
+#include "base/time/tick_clock.h"
 #include "base/time/time.h"
 #include "base/timer/timer.h"
 #include "base/values.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/http/bidirectional_stream_request_info.h"
 #include "net/http/http_log_util.h"
 #include "net/http/http_network_session.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_stream.h"
@@ skipping 54 matching lines @@
     Delegate* delegate,
     std::unique_ptr<base::Timer> timer)
     : request_info_(std::move(request_info)),
       net_log_(BoundNetLog::Make(session->net_log(),
                                  NetLog::SOURCE_BIDIRECTIONAL_STREAM)),
       session_(session),
       send_request_headers_automatically_(send_request_headers_automatically),
       request_headers_sent_(false),
       delegate_(delegate),
       timer_(std::move(timer)),
+      tick_clock_(new base::DefaultTickClock()),
       weak_factory_(this) {
   DCHECK(delegate_);
   DCHECK(request_info_);
 
   if (net_log_.IsCapturing()) {
     net_log_.BeginEvent(
         NetLog::TYPE_BIDIRECTIONAL_STREAM_ALIVE,
         base::Bind(&NetLogCallback, &request_info_->url, &request_info_->method,
                    base::Unretained(&request_info_->extra_headers)));
   }
@@ skipping 20 matching lines @@
           http_request_info, request_info_->priority, server_ssl_config,
           server_ssl_config, this, net_log_));
   // Check that this call cannot fail to set a non-NULL |stream_request_|.
   DCHECK(stream_request_);
   // Check that HttpStreamFactory does not invoke OnBidirectionalStreamImplReady
   // synchronously.
   DCHECK(!stream_impl_);
 }
 
 BidirectionalStream::~BidirectionalStream() {
+  UpdateHistograms();
   Cancel();
   if (net_log_.IsCapturing()) {
     net_log_.EndEvent(NetLog::TYPE_BIDIRECTIONAL_STREAM_ALIVE);
   }
 }
 
 void BidirectionalStream::SendRequestHeaders() {
   DCHECK(stream_impl_);
   DCHECK(!request_headers_sent_);
   DCHECK(!send_request_headers_automatically_);
 
   stream_impl_->SendRequestHeaders();
 }
 
 int BidirectionalStream::ReadData(IOBuffer* buf, int buf_len) {
   DCHECK(stream_impl_);
 
   int rv = stream_impl_->ReadData(buf, buf_len);
   if (rv > 0) {
+    read_end_time_ = tick_clock_->NowTicks();

[mef, 2016/08/10 01:05:20]

Can we use TimeTicks::Now() here and elsewhere? They use monotonic clock, which
seems like a right thing to use in this case.

[xunjieli, 2016/08/11 12:50:40]

Done.

     net_log_.AddByteTransferEvent(
         NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_RECEIVED, rv, buf->data());
   } else if (rv == ERR_IO_PENDING) {
     read_buffer_ = buf;
     // Bytes will be logged in OnDataRead().
   }
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(NetLog::TYPE_BIDIRECTIONAL_STREAM_READ_DATA,
                       NetLog::IntCallback("rv", rv));
   }
@@ skipping 64 matching lines @@
   return stream_impl_->GetTotalSentBytes();
 }
 
 void BidirectionalStream::OnStreamReady(bool request_headers_sent) {
   request_headers_sent_ = request_headers_sent;
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(
         NetLog::TYPE_BIDIRECTIONAL_STREAM_READY,
         NetLog::BoolCallback("request_headers_sent", request_headers_sent));
   }
+  send_start_time_ = tick_clock_->NowTicks();
+  send_end_time_ = send_start_time_;
   delegate_->OnStreamReady(request_headers_sent);
 }
 
 void BidirectionalStream::OnHeadersReceived(
     const SpdyHeaderBlock& response_headers) {
   HttpResponseInfo response_info;
   if (!SpdyHeadersToHttpResponse(response_headers, &response_info)) {
     DLOG(WARNING) << "Invalid headers";
     NotifyFailed(ERR_FAILED);
     return;
   }
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(NetLog::TYPE_BIDIRECTIONAL_STREAM_RECV_HEADERS,
                       base::Bind(&NetLogHeadersCallback, &response_headers));
   }
+  read_start_time_ = tick_clock_->NowTicks();
+  read_end_time_ = read_start_time_;
   session_->http_stream_factory()->ProcessAlternativeServices(
       session_, response_info.headers.get(),
       url::SchemeHostPort(request_info_->url));
   delegate_->OnHeadersReceived(response_headers);
 }
 
 void BidirectionalStream::OnDataRead(int bytes_read) {
   DCHECK(read_buffer_);
 
   if (net_log_.IsCapturing()) {
     net_log_.AddByteTransferEvent(
         NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_RECEIVED, bytes_read,
         read_buffer_->data());
   }
+  read_end_time_ = tick_clock_->NowTicks();
   read_buffer_ = nullptr;
   delegate_->OnDataRead(bytes_read);
 }
 
 void BidirectionalStream::OnDataSent() {
   DCHECK(!write_buffer_list_.empty());
   DCHECK_EQ(write_buffer_list_.size(), write_buffer_len_list_.size());
 
   if (net_log_.IsCapturing()) {
     if (write_buffer_list_.size() > 1) {
       net_log_.BeginEvent(
           NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_SENT_COALESCED,
           NetLog::IntCallback("num_buffers_coalesced",
                               write_buffer_list_.size()));
     }
     for (size_t i = 0; i < write_buffer_list_.size(); ++i) {
       net_log_.AddByteTransferEvent(
           NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_SENT,
           write_buffer_len_list_[i], write_buffer_list_[i]->data());
     }
     if (write_buffer_list_.size() > 1) {
       net_log_.EndEvent(NetLog::TYPE_BIDIRECTIONAL_STREAM_BYTES_SENT_COALESCED);
     }
   }
+  send_end_time_ = tick_clock_->NowTicks();
   write_buffer_list_.clear();
   write_buffer_len_list_.clear();
   delegate_->OnDataSent();
 }
 
 void BidirectionalStream::OnTrailersReceived(const SpdyHeaderBlock& trailers) {
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(NetLog::TYPE_BIDIRECTIONAL_STREAM_RECV_TRAILERS,
                       base::Bind(&NetLogHeadersCallback, &trailers));
   }
+  read_end_time_ = tick_clock_->NowTicks();
   delegate_->OnTrailersReceived(trailers);
 }
 
 void BidirectionalStream::OnFailed(int status) {
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(NetLog::TYPE_BIDIRECTIONAL_STREAM_FAILED,
                       NetLog::IntCallback("net_error", status));
   }
   NotifyFailed(status);
 }
 
 void BidirectionalStream::OnStreamReady(const SSLConfig& used_ssl_config,
                                         const ProxyInfo& used_proxy_info,
                                         HttpStream* stream) {
   NOTREACHED();
 }
 
 void BidirectionalStream::OnBidirectionalStreamImplReady(
     const SSLConfig& used_ssl_config,
     const ProxyInfo& used_proxy_info,
     BidirectionalStreamImpl* stream) {
   DCHECK(!stream_impl_);
 
+  start_time_ = tick_clock_->NowTicks();
   stream_request_.reset();
   stream_impl_.reset(stream);
   stream_impl_->Start(request_info_.get(), net_log_,
                       send_request_headers_automatically_, this,
                       std::move(timer_));
 }
 
 void BidirectionalStream::OnWebSocketHandshakeStreamReady(
     const SSLConfig& used_ssl_config,
     const ProxyInfo& used_proxy_info,
@@ skipping 46 matching lines @@
 
   NotifyFailed(ERR_HTTPS_PROXY_TUNNEL_RESPONSE);
 }
 
 void BidirectionalStream::OnQuicBroken() {}
 
 void BidirectionalStream::NotifyFailed(int error) {
   delegate_->OnFailed(error);
 }
 
+void BidirectionalStream::UpdateHistograms() {
+  // If the request failed before response is started, treat the metrics as
+  // bogus and skip logging.
+  if (start_time_.is_null() || read_start_time_.is_null() ||
+      read_end_time_.is_null() || send_start_time_.is_null() ||
+      send_end_time_.is_null()) {
+    return;
+  }
+  if (GetProtocol() == kProtoHTTP2) {
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.HTTP2.TimeToReadStart",

[mef, 2016/08/10 01:05:20]

Should these names match those in histograms.xml?

[xunjieli, 2016/08/11 12:50:40]

I don't understand. They do match right? I added the HTTP2 and QUIC2 parts as a
suffix (which is declared in histograms.xml as well).

[mef, 2016/08/11 15:42:19]

I would've thought that suffix goes at the end of the name, not in the middle,
but I'm definitely not an expert in histograms.

[Ilya Sherman, 2016/08/11 18:48:46]

ordering=prefix should indeed put the "suffix" in the middle, I think exactly as
desired.  I'm not familiar with the presubmit script that's failing -- it's
possible that the script is not familiar with ordering=prefix.

[xunjieli, 2016/08/11 19:37:09]

I talked to csharrison@ who added a similar histogram, and he said the presubmit
script doesn't understand prefix and suffix. I think we are good here. Thanks
for the confirmation!

+                        read_start_time_ - start_time_);
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.HTTP2.TimeToReadEnd",
+                        read_end_time_ - start_time_);
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.HTTP2.TimeToSendStart",
+                        send_start_time_ - start_time_);
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.HTTP2.TimeToSendEnd",
+                        send_end_time_ - start_time_);
+    UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.HTTP2.ReceivedBytes",
+                         stream_impl_->GetTotalReceivedBytes());
+    UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.HTTP2.SentBytes",
+                         stream_impl_->GetTotalSentBytes());
+  } else if (GetProtocol() == kProtoQUIC1SPDY3) {
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.QUIC.TimeToReadStart",
+                        read_start_time_ - start_time_);
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.QUIC.TimeToReadEnd",
+                        read_end_time_ - start_time_);
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.QUIC.TimeToSendStart",
+                        send_start_time_ - start_time_);
+    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.QUIC.TimeToSendEnd",
+                        send_end_time_ - start_time_);
+    UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.QUIC.ReceivedBytes",
+                         stream_impl_->GetTotalReceivedBytes());
+    UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.QUIC.SentBytes",
+                         stream_impl_->GetTotalSentBytes());
+  }
+}
+
 }  // namespace net