Add GetLoadTimingInfo 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"
@@ skipping 74 matching lines @@
                                  NetLogSourceType::BIDIRECTIONAL_STREAM)),
       session_(session),
       send_request_headers_automatically_(send_request_headers_automatically),
       request_headers_sent_(false),
       delegate_(delegate),
       timer_(std::move(timer)),
       weak_factory_(this) {
   DCHECK(delegate_);
   DCHECK(request_info_);
 
+  // Start time should be measured before connect.
+  load_timing_info_.request_start_time = base::Time::Now();
+  load_timing_info_.request_start = base::TimeTicks::Now();
+
   if (net_log_.IsCapturing()) {
     net_log_.BeginEvent(
         NetLogEventType::BIDIRECTIONAL_STREAM_ALIVE,
         base::Bind(&NetLogCallback, &request_info_->url, &request_info_->method,
                    base::Unretained(&request_info_->extra_headers)));
   }
 
   SSLConfig server_ssl_config;
   session->ssl_config_service()->GetSSLConfig(&server_ssl_config);
   session->GetAlpnProtos(&server_ssl_config.alpn_protos);
@@ skipping 104 matching lines @@
   return stream_impl_->GetTotalReceivedBytes();
 }
 
 int64_t BidirectionalStream::GetTotalSentBytes() const {
   if (!stream_impl_)
     return 0;
 
   return stream_impl_->GetTotalSentBytes();
 }
 
+void BidirectionalStream::GetLoadTimingInfo(
+    LoadTimingInfo* load_timing_info) const {
+  *load_timing_info = load_timing_info_;
+}
+
 void BidirectionalStream::OnStreamReady(bool request_headers_sent) {
   request_headers_sent_ = request_headers_sent;
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(
         NetLogEventType::BIDIRECTIONAL_STREAM_READY,
         NetLog::BoolCallback("request_headers_sent", request_headers_sent));
   }
-  send_start_time_ = base::TimeTicks::Now();
-  send_end_time_ = send_start_time_;
+  load_timing_info_.send_start = base::TimeTicks::Now();
+  load_timing_info_.send_end = load_timing_info_.send_start;
   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(NetLogEventType::BIDIRECTIONAL_STREAM_RECV_HEADERS,
                       base::Bind(&NetLogHeadersCallback, &response_headers));
   }
-  read_start_time_ = base::TimeTicks::Now();
-  read_end_time_ = read_start_time_;
+  // Subclasses should only provide |connect_timing| and |socket_reused| info,

[mef, 2016/09/23 15:50:56]

Technically BidirectionalStreamImpl is not subclass of BidirectionalStream,
right?
Also, it is a bit weird get a copy of LoadTimingInfo and throw away everything
except for two fields.

Maybe replace BidirectionalStreamImpl::GetLoadTimingInfo with
GetConnectTimingInfo which just produces connect timing and socket reused?

[xunjieli, 2016/09/23 16:43:24]

I've adjusted the comment to remove the subclass reference.

SpdyStream exposes GetLoadTimingInfo and that's what's BidirectionalStreamImpl
uses. There are some other information (just H2 push), but we are not currently
using it since QUIC doesn't have the counterpart.

I think we should still leave GetLoadTimingInfo. This is a defensive measure so
we don't get any unexpected fields or override the existing
|load_timing_info_|'s fields.

[mef, 2016/09/23 17:40:05]

Thanks for explanation!

+  // so use a copy to get these information only.
+  LoadTimingInfo subclass_load_timing_info;
+  bool has_load_timing =
+      stream_impl_->GetLoadTimingInfo(&subclass_load_timing_info);
+  if (has_load_timing) {
+    load_timing_info_.connect_timing = subclass_load_timing_info.connect_timing;
+    load_timing_info_.socket_reused = subclass_load_timing_info.socket_reused;
+  }
+  load_timing_info_.receive_headers_end = base::TimeTicks::Now();
+  read_end_time_ = load_timing_info_.receive_headers_end;
   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()) {
@@ skipping 20 matching lines @@
     for (size_t i = 0; i < write_buffer_list_.size(); ++i) {
       net_log_.AddByteTransferEvent(
           NetLogEventType::BIDIRECTIONAL_STREAM_BYTES_SENT,
           write_buffer_len_list_[i], write_buffer_list_[i]->data());
     }
     if (write_buffer_list_.size() > 1) {
       net_log_.EndEvent(
           NetLogEventType::BIDIRECTIONAL_STREAM_BYTES_SENT_COALESCED);
     }
   }
-  send_end_time_ = base::TimeTicks::Now();
+  load_timing_info_.send_end = base::TimeTicks::Now();
   write_buffer_list_.clear();
   write_buffer_len_list_.clear();
   delegate_->OnDataSent();
 }
 
 void BidirectionalStream::OnTrailersReceived(const SpdyHeaderBlock& trailers) {
   if (net_log_.IsCapturing()) {
     net_log_.AddEvent(NetLogEventType::BIDIRECTIONAL_STREAM_RECV_TRAILERS,
                       base::Bind(&NetLogHeadersCallback, &trailers));
   }
@@ skipping 14 matching lines @@
                                         HttpStream* stream) {
   NOTREACHED();
 }
 
 void BidirectionalStream::OnBidirectionalStreamImplReady(
     const SSLConfig& used_ssl_config,
     const ProxyInfo& used_proxy_info,
     BidirectionalStreamImpl* stream) {
   DCHECK(!stream_impl_);
 
-  start_time_ = base::TimeTicks::Now();
   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 49 matching lines @@
 
 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()) {
+  if (load_timing_info_.request_start.is_null() ||
+      load_timing_info_.receive_headers_end.is_null() ||
+      read_end_time_.is_null() || load_timing_info_.send_start.is_null() ||
+      load_timing_info_.send_end.is_null()) {
     return;
   }
   if (GetProtocol() == kProtoHTTP2) {
     UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToReadStart.HTTP2",
-                        read_start_time_ - start_time_);
+                        load_timing_info_.receive_headers_end -
+                            load_timing_info_.request_start);
     UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToReadEnd.HTTP2",
-                        read_end_time_ - start_time_);
-    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToSendStart.HTTP2",
-                        send_start_time_ - start_time_);
-    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToSendEnd.HTTP2",
-                        send_end_time_ - start_time_);
+                        read_end_time_ - load_timing_info_.request_start);
+    UMA_HISTOGRAM_TIMES(
+        "Net.BidirectionalStream.TimeToSendStart.HTTP2",
+        load_timing_info_.send_start - load_timing_info_.request_start);
+    UMA_HISTOGRAM_TIMES(
+        "Net.BidirectionalStream.TimeToSendEnd.HTTP2",
+        load_timing_info_.send_end - load_timing_info_.request_start);
     UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.ReceivedBytes.HTTP2",
                          stream_impl_->GetTotalReceivedBytes());
     UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.SentBytes.HTTP2",
                          stream_impl_->GetTotalSentBytes());
   } else if (GetProtocol() == kProtoQUIC1SPDY3) {
     UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToReadStart.QUIC",
-                        read_start_time_ - start_time_);
+                        load_timing_info_.receive_headers_end -
+                            load_timing_info_.request_start);
     UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToReadEnd.QUIC",
-                        read_end_time_ - start_time_);
-    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToSendStart.QUIC",
-                        send_start_time_ - start_time_);
-    UMA_HISTOGRAM_TIMES("Net.BidirectionalStream.TimeToSendEnd.QUIC",
-                        send_end_time_ - start_time_);
+                        read_end_time_ - load_timing_info_.request_start);
+    UMA_HISTOGRAM_TIMES(
+        "Net.BidirectionalStream.TimeToSendStart.QUIC",
+        load_timing_info_.send_start - load_timing_info_.request_start);
+    UMA_HISTOGRAM_TIMES(
+        "Net.BidirectionalStream.TimeToSendEnd.QUIC",
+        load_timing_info_.send_end - load_timing_info_.request_start);
     UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.ReceivedBytes.QUIC",
                          stream_impl_->GetTotalReceivedBytes());
     UMA_HISTOGRAM_COUNTS("Net.BidirectionalStream.SentBytes.QUIC",
                          stream_impl_->GetTotalSentBytes());
   }
 }
 
 }  // namespace net