Implement QuicHttpStream::GetLoadTimingInfo

net/quic/chromium/quic_chromium_client_session.cc

 // Copyright (c) 2012 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/quic/chromium/quic_chromium_client_session.h"
 
 #include <utility>
 
 #include "base/callback_helpers.h"
 #include "base/location.h"
@@ skipping 195 matching lines @@
     QuicClock* clock,
     TransportSecurityState* transport_security_state,
     std::unique_ptr<QuicServerInfo> server_info,
     const QuicServerId& server_id,
     int yield_after_packets,
     QuicTime::Delta yield_after_duration,
     int cert_verify_flags,
     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,
     std::unique_ptr<SocketPerformanceWatcher> socket_performance_watcher,
     NetLog* net_log)
     : QuicClientSessionBase(connection, push_promise_index, config),
       server_id_(server_id),
       require_confirmation_(false),
       stream_factory_(stream_factory),
       transport_security_state_(transport_security_state),
       server_info_(std::move(server_info)),
       pkp_bypassed_(false),
       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),
                                        net_log_)),
       going_away_(false),
       port_migration_detected_(false),
       disabled_reason_(QUIC_DISABLED_NOT),
       token_binding_signatures_(kTokenBindingSignatureMapSize),
       streams_pushed_count_(0),
       streams_pushed_and_claimed_count_(0),
@@ skipping 13 matching lines @@
   connection->set_creator_debug_delegate(logger_.get());
   net_log_.BeginEvent(NetLogEventType::QUIC_SESSION,
                       base::Bind(NetLogQuicClientSessionCallback, &server_id,
                                  cert_verify_flags, require_confirmation_));
   IPEndPoint address;
   if (socket && socket->GetLocalAddress(&address) == OK &&
       address.GetFamily() == ADDRESS_FAMILY_IPV6) {
     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() {
   if (!dynamic_streams().empty())
     RecordUnexpectedOpenStreams(DESTRUCTOR);
   if (!observers_.empty())
     RecordUnexpectedObservers(DESTRUCTOR);
   if (!going_away_)
     RecordUnexpectedNotGoingAway(DESTRUCTOR);
 
@@ skipping 321 matching lines @@
     return ERR_FAILED;
   token_binding_signatures_.Put(raw_public_key, *out);
   return OK;
 }
 
 int QuicChromiumClientSession::CryptoConnect(
     bool require_confirmation,
     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;
 }
 
 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;
 
   callback_ = callback;
   return ERR_IO_PENDING;
 }
 
 int QuicChromiumClientSession::GetNumSentClientHellos() const {
   return crypto_stream_->num_sent_client_hellos();
@@ skipping 123 matching lines @@
     CryptoHandshakeEvent event) {
   if (stream_factory_ && event == HANDSHAKE_CONFIRMED &&
       (stream_factory_->OnHandshakeConfirmed(
           this, logger_->ReceivedPacketLossRate()))) {
     return;
   }
 
   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
     // following code needs to changed.
     base::ResetAndReturn(&callback_).Run(OK);
   }
   if (event == HANDSHAKE_CONFIRMED) {
     UMA_HISTOGRAM_TIMES("Net.QuicSession.HandshakeConfirmedTime",
                         base::TimeTicks::Now() - handshake_start_);
     if (server_info_) {
       // TODO(rtenneti): Should we delete this histogram?
       // Track how long it has taken to finish handshake once we start waiting
       // for reading of QUIC server information from disk cache. We could use
       // this data to compare total time taken if we were to cancel the disk
       // cache read vs waiting for the read to complete.
       base::TimeTicks wait_for_data_start_time =
           server_info_->wait_for_data_start_time();
       if (!wait_for_data_start_time.is_null()) {
         UMA_HISTOGRAM_TIMES(
             "Net.QuicServerInfo.WaitForDataReady.HandshakeConfirmedTime",
             base::TimeTicks::Now() - wait_for_data_start_time);
       }
     }
     // 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();
     while (it != observers_.end()) {
       Observer* observer = *it;
       ++it;
       observer->OnCryptoHandshakeConfirmed();
     }
     if (server_info_)
       server_info_->OnExternalCacheHit();
@@ skipping 420 matching lines @@
                                id, promised_id));
 }
 
 void QuicChromiumClientSession::DeletePromised(
     QuicClientPromisedInfo* promised) {
   if (IsOpenStream(promised->id()))
     streams_pushed_and_claimed_count_++;
   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