Implement QuicHttpStream::GetLoadTimingInfo

net/quic/chromium/quic_chromium_client_session.cc

Index: net/quic/chromium/quic_chromium_client_session.cc
diff --git a/net/quic/chromium/quic_chromium_client_session.cc b/net/quic/chromium/quic_chromium_client_session.cc
index e2759c459a9413fa5c352c19277d39ffa5276102..76ccfc90243f5aecb43930e54c7b265379b2313c 100644
--- a/net/quic/chromium/quic_chromium_client_session.cc
+++ b/net/quic/chromium/quic_chromium_client_session.cc
@@ -213,6 +213,7 @@ QuicChromiumClientSession::QuicChromiumClientSession(
     const QuicConfig& config,
     QuicCryptoClientConfig* crypto_config,
     const char* const connection_description,
+    base::TimeTicks dns_resolution_start_time,
     base::TimeTicks dns_resolution_end_time,
     QuicClientPushPromiseIndex* push_promise_index,
     base::TaskRunner* task_runner,
@@ -228,7 +229,6 @@ QuicChromiumClientSession::QuicChromiumClientSession(
       num_total_streams_(0),
       task_runner_(task_runner),
       net_log_(BoundNetLog::Make(net_log, NetLogSourceType::QUIC_SESSION)),
-      dns_resolution_end_time_(dns_resolution_end_time),
       logger_(new QuicConnectionLogger(this,
                                        connection_description,
                                        std::move(socket_performance_watcher),
@@ -262,6 +262,8 @@ QuicChromiumClientSession::QuicChromiumClientSession(
     connection->SetMaxPacketLength(connection->max_packet_length() -
                                    kAdditionalOverheadForIPv6);
   }
+  connect_timing_.dns_start = dns_resolution_start_time;
+  connect_timing_.dns_end = dns_resolution_end_time;
 }
 
 QuicChromiumClientSession::~QuicChromiumClientSession() {
@@ -603,17 +605,22 @@ int QuicChromiumClientSession::CryptoConnect(
     const CompletionCallback& callback) {
   require_confirmation_ = require_confirmation;
   handshake_start_ = base::TimeTicks::Now();
+  connect_timing_.connect_start = handshake_start_;
   RecordHandshakeState(STATE_STARTED);
   DCHECK(flow_controller());
   crypto_stream_->CryptoConnect();
 
-  if (IsCryptoHandshakeConfirmed())
+  if (IsCryptoHandshakeConfirmed()) {
+    connect_timing_.connect_end = base::TimeTicks::Now();
     return OK;
+  }
 
   // Unless we require handshake confirmation, activate the session if
   // we have established initial encryption.
-  if (!require_confirmation_ && IsEncryptionEstablished())
+  if (!require_confirmation_ && IsEncryptionEstablished()) {
+    connect_timing_.connect_end = base::TimeTicks::Now();

[Ryan Hamilton, 2016/09/09 20:02:49]

Do you know what the semantics of connect_end should be in the case of 0-RTT?
Should it be when we're able to send the request (in which case your code is
correct). Or should it be when we receive confirmation from the server?

Also, we should make sure we do the right thing in the case of failed 0-RTT:

T0: Send CHLO
T1: Send encrypted GET
T2: Receive rej
T3: Send new CHLO
T4: Send re-encrypted GET

[xunjieli, 2016/09/09 21:26:59]

Done. That's a really good point! I didn't think of that. I have changed the
code to track the handshake confirmation instead. I think this sould handle the
failed 0-RTT case as well,since the |connect_end| is only updated when handshake
is confirmed.

I checked with mmenke@ too -- We should wait until handshake is confirmed, and
the time should include multiple rounds of authentication attempts.

[Ryan Hamilton, 2016/09/09 22:05:39]

This seems reasonable to me. But it's worth keeping in mind that in the case of
a successful 0-RTT connection, the request can be sent immediately after the
handshake is started. For example:
T0: dns start
T1: dns end
T2: handshake start
T2 + epsilon: send request
T3: handshake end
T3 + epsilon: receive response.

The current code would say that
DNS = T1-T0
CONNECT = T3- T2
REQUEST = T3- T2
TOTAL = T3- T2 + T3- T2 + T1-T0
But the actual elapsed time is simply: T3-T0

(My notation is getting really sloppy, but I hope it's clear enough).

So I'm not sure what the callers for LoadTiming expect to see for Connect time
in the case of successful 0-RTT.

     return OK;
+  }
 
   callback_ = callback;
   return ERR_IO_PENDING;
@@ -621,8 +628,10 @@ int QuicChromiumClientSession::CryptoConnect(
 
 int QuicChromiumClientSession::ResumeCryptoConnect(
     const CompletionCallback& callback) {
-  if (IsCryptoHandshakeConfirmed())
+  if (IsCryptoHandshakeConfirmed()) {
+    connect_timing_.connect_end = base::TimeTicks::Now();
     return OK;
+  }
 
   if (!connection()->connected())
     return ERR_QUIC_HANDSHAKE_FAILED;
@@ -766,6 +775,9 @@ void QuicChromiumClientSession::OnCryptoHandshakeEvent(
   if (!callback_.is_null() &&
       (!require_confirmation_ || event == HANDSHAKE_CONFIRMED ||
        event == ENCRYPTION_REESTABLISHED)) {
+    // Update |connect_end_| if CryptoConnect() returned ERR_IO_PENDING.
+    connect_timing_.connect_end = base::TimeTicks::Now();
+
     // TODO(rtenneti): Currently for all CryptoHandshakeEvent events, callback_
     // could be called because there are no error events in CryptoHandshakeEvent
     // enum. If error events are added to CryptoHandshakeEvent, then the
@@ -791,10 +803,10 @@ void QuicChromiumClientSession::OnCryptoHandshakeEvent(
     }
     // Track how long it has taken to finish handshake after we have finished
     // DNS host resolution.
-    if (!dns_resolution_end_time_.is_null()) {
+    if (!connect_timing_.dns_end.is_null()) {
       UMA_HISTOGRAM_TIMES(
           "Net.QuicSession.HostResolution.HandshakeConfirmedTime",
-          base::TimeTicks::Now() - dns_resolution_end_time_);
+          base::TimeTicks::Now() - connect_timing_.dns_end);
     }
 
     ObserverSet::iterator it = observers_.begin();
@@ -1235,4 +1247,11 @@ void QuicChromiumClientSession::DeletePromised(
   QuicClientSessionBase::DeletePromised(promised);
 }
 
+const LoadTimingInfo::ConnectTiming&
+QuicChromiumClientSession::GetConnectTiming() {
+  connect_timing_.ssl_start = connect_timing_.connect_start;
+  connect_timing_.ssl_end = connect_timing_.connect_end;
+  return connect_timing_;
+}
+
 }  // namespace net