Add GetLoadTimingInfo to net::BidirectionalStream

net/http/bidirectional_stream.cc

Index: net/http/bidirectional_stream.cc
diff --git a/net/http/bidirectional_stream.cc b/net/http/bidirectional_stream.cc
index 93e28f1d3d76d63819d6e6c0ff9830417b0b48b1..67aca745c36bb1efcc4210ac2733ae890e960ec9 100644
--- a/net/http/bidirectional_stream.cc
+++ b/net/http/bidirectional_stream.cc
@@ -92,6 +92,10 @@ BidirectionalStream::BidirectionalStream(
   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,
@@ -216,6 +220,11 @@ int64_t BidirectionalStream::GetTotalSentBytes() const {
   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()) {
@@ -223,8 +232,8 @@ void BidirectionalStream::OnStreamReady(bool request_headers_sent) {
         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);
 }
 
@@ -240,8 +249,17 @@ void BidirectionalStream::OnHeadersReceived(
     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));
@@ -282,7 +300,7 @@ void BidirectionalStream::OnDataSent() {
           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();
@@ -317,7 +335,6 @@ void BidirectionalStream::OnBidirectionalStreamImplReady(
     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_,
@@ -387,33 +404,40 @@ void BidirectionalStream::NotifyFailed(int 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",