Add GetLoadTimingInfo to net::BidirectionalStream

This CL adds GetLoadTimingInfo to net::BidirectionalStream.
This is a part of the effort to expose timing metrics to
net embedders.

This CL additionally moves |start_time| to BidirectionalStream's
constructor so we measure the true request start time (before
dns, ssl)

BUG=648346

Review-Url: https://codereview.chromium.org/2359493003
Cr-Commit-Position: refs/heads/master@{#420676}

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_;
+  // Impl should only provide |connect_timing| and |socket_reused| info,
+  // so use a copy to get these information only.
+  LoadTimingInfo impl_load_timing_info;
+  bool has_load_timing =
+      stream_impl_->GetLoadTimingInfo(&impl_load_timing_info);
+  if (has_load_timing) {
+    load_timing_info_.connect_timing = impl_load_timing_info.connect_timing;
+    load_timing_info_.socket_reused = impl_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",

net/http/bidirectional_stream.h

@@ -14,6 +14,7 @@
 #include "base/memory/ref_counted.h"
 #include "base/memory/weak_ptr.h"
 #include "base/time/time.h"
+#include "net/base/load_timing_info.h"
 #include "net/http/bidirectional_stream_impl.h"
 #include "net/http/http_stream_factory.h"
 #include "net/log/net_log.h"
@@ -171,8 +172,8 @@ class NET_EXPORT BidirectionalStream
   // not associated with any stream, and are not included in this value.
   int64_t GetTotalSentBytes() const;
 
-  // TODO(xunjieli): Implement a method to do flow control and a method to ping
-  // remote end point.
+  // Gets LoadTimingInfo of this stream.
+  void GetLoadTimingInfo(LoadTimingInfo* load_timing_info) const;
 
  private:
   // BidirectionalStreamImpl::Delegate implementation:
@@ -246,11 +247,12 @@ class NET_EXPORT BidirectionalStream
   // List of buffer length.
   std::vector<int> write_buffer_len_list_;
 
-  base::TimeTicks start_time_;
-  base::TimeTicks read_start_time_;
+  // TODO(xunjieli): Remove this once LoadTimingInfo has response end.
   base::TimeTicks read_end_time_;
-  base::TimeTicks send_start_time_;
-  base::TimeTicks send_end_time_;
+
+  // Load timing info of this stream. |connect_timing| is obtained when headers
+  // are received. Other fields are populated at different stages of the request
+  LoadTimingInfo load_timing_info_;
 
   base::WeakPtrFactory<BidirectionalStream> weak_factory_;
 

net/http/bidirectional_stream_unittest.cc

@@ -14,6 +14,8 @@
 #include "base/strings/string_piece.h"
 #include "base/time/time.h"
 #include "base/timer/mock_timer.h"
+#include "net/base/load_timing_info.h"
+#include "net/base/load_timing_info_test_util.h"
 #include "net/base/net_errors.h"
 #include "net/http/bidirectional_stream_request_info.h"
 #include "net/http/http_network_session.h"
@@ -46,6 +48,38 @@ const size_t kBodyDataSize = arraysize(kBodyData);
 // Size of the buffer to be allocated for each read.
 const size_t kReadBufferSize = 4096;
 
+// Expects that fields of |load_timing_info| are valid time stamps.
+void ExpectLoadTimingValid(const LoadTimingInfo& load_timing_info) {
+  EXPECT_FALSE(load_timing_info.request_start.is_null());
+  EXPECT_FALSE(load_timing_info.request_start_time.is_null());
+  EXPECT_FALSE(load_timing_info.receive_headers_end.is_null());
+  EXPECT_FALSE(load_timing_info.send_start.is_null());
+  EXPECT_FALSE(load_timing_info.send_end.is_null());
+  EXPECT_TRUE(load_timing_info.request_start <
+              load_timing_info.receive_headers_end);
+  EXPECT_TRUE(load_timing_info.send_start <= load_timing_info.send_end);
+}
+
+// Tests the load timing of a stream that's connected and is not the first
+// request sent on a connection.
+void TestLoadTimingReused(const LoadTimingInfo& load_timing_info) {
+  EXPECT_TRUE(load_timing_info.socket_reused);
+
+  ExpectConnectTimingHasNoTimes(load_timing_info.connect_timing);
+  ExpectLoadTimingValid(load_timing_info);
+}
+
+// Tests the load timing of a stream that's connected and using a fresh
+// connection.
+void TestLoadTimingNotReused(const LoadTimingInfo& load_timing_info) {
+  EXPECT_FALSE(load_timing_info.socket_reused);
+
+  ExpectConnectTimingHasTimes(
+      load_timing_info.connect_timing,
+      CONNECT_TIMING_HAS_SSL_TIMES | CONNECT_TIMING_HAS_DNS_TIMES);
+  ExpectLoadTimingValid(load_timing_info);
+}
+
 // Delegate that reads data but does not send any data.
 class TestDelegateBase : public BidirectionalStream::Delegate {
  public:
@@ -140,9 +174,11 @@ class TestDelegateBase : public BidirectionalStream::Delegate {
     stream_.reset(new BidirectionalStream(std::move(request_info), session,
                                           true, this, std::move(timer_)));
     if (run_until_completion_)
-      loop_->Run();
+      WaitUntilCompletion();
   }
 
+  void WaitUntilCompletion() { loop_->Run(); }
+
   void SendData(const scoped_refptr<IOBuffer>& data,
                 int length,
                 bool end_of_stream) {
@@ -185,6 +221,7 @@ class TestDelegateBase : public BidirectionalStream::Delegate {
     next_proto_ = stream_->GetProtocol();
     received_bytes_ = stream_->GetTotalReceivedBytes();
     sent_bytes_ = stream_->GetTotalSentBytes();
+    stream_->GetLoadTimingInfo(&load_timing_info_);
     stream_.reset();
   }
 
@@ -206,6 +243,14 @@ class TestDelegateBase : public BidirectionalStream::Delegate {
     return sent_bytes_;
   }
 
+  void GetLoadTimingInfo(LoadTimingInfo* load_timing_info) const {
+    if (stream_) {
+      stream_->GetLoadTimingInfo(load_timing_info);
+      return;
+    }
+    *load_timing_info = load_timing_info_;
+  }
+
   // Const getters for internal states.
   const std::string& data_received() const { return data_received_; }
   int error() const { return error_; }
@@ -240,6 +285,7 @@ class TestDelegateBase : public BidirectionalStream::Delegate {
   NextProto next_proto_;
   int64_t received_bytes_;
   int64_t sent_bytes_;
+  LoadTimingInfo load_timing_info_;
   int error_;
   int on_data_read_count_;
   int on_data_sent_count_;
@@ -406,6 +452,108 @@ TEST_F(BidirectionalStreamTest, CreateInsecureStream) {
   EXPECT_THAT(delegate.error(), IsError(ERR_DISALLOWED_URL_SCHEME));
 }
 
+TEST_F(BidirectionalStreamTest, SimplePostRequest) {
+  SpdySerializedFrame req(spdy_util_.ConstructSpdyPost(
+      kDefaultUrl, 1, kBodyDataSize, LOW, nullptr, 0));
+  SpdySerializedFrame data_frame(spdy_util_.ConstructSpdyDataFrame(
+      1, kBodyData, kBodyDataSize, /*fin=*/true));
+  MockWrite writes[] = {
+      CreateMockWrite(req, 0), CreateMockWrite(data_frame, 3),
+  };
+  SpdySerializedFrame resp(spdy_util_.ConstructSpdyPostReply(nullptr, 0));
+  SpdySerializedFrame response_body_frame(
+      spdy_util_.ConstructSpdyDataFrame(1, /*fin=*/true));
+  MockRead reads[] = {
+      CreateMockRead(resp, 1),
+      MockRead(ASYNC, ERR_IO_PENDING, 2),  // Force a pause.
+      CreateMockRead(response_body_frame, 4), MockRead(ASYNC, 0, 5),
+  };
+  InitSession(reads, arraysize(reads), writes, arraysize(writes));
+
+  std::unique_ptr<BidirectionalStreamRequestInfo> request_info(
+      new BidirectionalStreamRequestInfo);
+  request_info->method = "POST";
+  request_info->url = default_url_;
+  request_info->extra_headers.SetHeader(net::HttpRequestHeaders::kContentLength,
+                                        base::SizeTToString(kBodyDataSize));
+  scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
+  std::unique_ptr<TestDelegateBase> delegate(
+      new TestDelegateBase(read_buffer.get(), kReadBufferSize));
+  delegate->Start(std::move(request_info), http_session_.get());
+  sequenced_data_->RunUntilPaused();
+
+  scoped_refptr<StringIOBuffer> write_buffer(
+      new StringIOBuffer(std::string(kBodyData, kBodyDataSize)));
+  delegate->SendData(write_buffer.get(), write_buffer->size(), true);
+  sequenced_data_->Resume();
+  base::RunLoop().RunUntilIdle();
+  LoadTimingInfo load_timing_info;
+  delegate->GetLoadTimingInfo(&load_timing_info);
+  TestLoadTimingNotReused(load_timing_info);
+
+  EXPECT_EQ(1, delegate->on_data_read_count());
+  EXPECT_EQ(1, delegate->on_data_sent_count());
+  EXPECT_EQ(kProtoHTTP2, delegate->GetProtocol());
+  EXPECT_EQ(CountWriteBytes(writes, arraysize(writes)),
+            delegate->GetTotalSentBytes());
+  EXPECT_EQ(CountReadBytes(reads, arraysize(reads)),
+            delegate->GetTotalReceivedBytes());
+}
+
+TEST_F(BidirectionalStreamTest, LoadTimingTwoRequests) {
+  SpdySerializedFrame req(
+      spdy_util_.ConstructSpdyGet(nullptr, 0, /*stream_id=*/1, LOW, true));
+  SpdySerializedFrame req2(
+      spdy_util_.ConstructSpdyGet(nullptr, 0, /*stream_id=*/3, LOW, true));
+  MockWrite writes[] = {
+      CreateMockWrite(req, 0), CreateMockWrite(req2, 2),
+  };
+  SpdySerializedFrame resp(
+      spdy_util_.ConstructSpdyGetReply(nullptr, 0, /*stream_id=*/1));
+  SpdySerializedFrame resp2(
+      spdy_util_.ConstructSpdyGetReply(nullptr, 0, /*stream_id=*/3));
+  SpdySerializedFrame resp_body(
+      spdy_util_.ConstructSpdyDataFrame(/*stream_id=*/1, /*fin=*/true));
+  SpdySerializedFrame resp_body2(
+      spdy_util_.ConstructSpdyDataFrame(/*stream_id=*/3, /*fin=*/true));
+  MockRead reads[] = {CreateMockRead(resp, 1), CreateMockRead(resp_body, 3),
+                      CreateMockRead(resp2, 4), CreateMockRead(resp_body2, 5),
+                      MockRead(ASYNC, 0, 6)};
+  InitSession(reads, arraysize(reads), writes, arraysize(writes));
+
+  std::unique_ptr<BidirectionalStreamRequestInfo> request_info(
+      new BidirectionalStreamRequestInfo);
+  request_info->method = "GET";
+  request_info->url = default_url_;
+  request_info->end_stream_on_headers = true;
+  std::unique_ptr<BidirectionalStreamRequestInfo> request_info2(
+      new BidirectionalStreamRequestInfo);
+  request_info2->method = "GET";
+  request_info2->url = default_url_;
+  request_info2->end_stream_on_headers = true;
+
+  scoped_refptr<IOBuffer> read_buffer(new IOBuffer(kReadBufferSize));
+  scoped_refptr<IOBuffer> read_buffer2(new IOBuffer(kReadBufferSize));
+  std::unique_ptr<TestDelegateBase> delegate(
+      new TestDelegateBase(read_buffer.get(), kReadBufferSize));
+  std::unique_ptr<TestDelegateBase> delegate2(
+      new TestDelegateBase(read_buffer2.get(), kReadBufferSize));
+  delegate->Start(std::move(request_info), http_session_.get());
+  delegate2->Start(std::move(request_info2), http_session_.get());
+  delegate->SetRunUntilCompletion(true);
+  delegate2->SetRunUntilCompletion(true);
+  base::RunLoop().RunUntilIdle();
+
+  delegate->WaitUntilCompletion();
+  delegate2->WaitUntilCompletion();
+  LoadTimingInfo load_timing_info;
+  delegate->GetLoadTimingInfo(&load_timing_info);
+  TestLoadTimingNotReused(load_timing_info);
+  LoadTimingInfo load_timing_info2;
+  delegate2->GetLoadTimingInfo(&load_timing_info2);
+  TestLoadTimingReused(load_timing_info2);
+}
+
 // Creates a BidirectionalStream with an insecure scheme. Destroy the stream
 // without waiting for the OnFailed task to be executed.
 TEST_F(BidirectionalStreamTest,