[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

net/http/http_stream_factory_impl_job.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/http/http_stream_factory_impl_job.h"
 
 #include <algorithm>
 #include <string>
 
 #include "base/bind.h"
@@ skipping 102 matching lines @@
         request_key->ExportRawPublicKey(&raw_request_key) &&
         raw_socket_key == raw_request_key) {
       match = MATCH;
     }
   }
   UMA_HISTOGRAM_ENUMERATION("Net.TokenBinding.KeyMatch", match, KEY_MATCH_MAX);
 }
 
 }  // namespace
 
+// Returns parameters associated with the QUIC request creation.
+std::unique_ptr<base::Value> NetLogHttpStreamJobQuicRequestCallback(
+    int64_t delay,
+    bool using_existing_quic_session,
+    NetLogCaptureMode /* capture mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  dict->SetString("delay_in_macroseconds", base::Int64ToString(delay));

[eroman, 2017/03/16 04:32:08]

microseconds.

Also on a side-note, I expect it will be easier to read the logs if these are in
milliseconds.

+  dict->SetBoolean("using_existing_quic_session", using_existing_quic_session);
+  return std::move(dict);
+}
+
 // Returns parameters associated with the start of a HTTP stream job.
 std::unique_ptr<base::Value> NetLogHttpStreamJobCallback(
     const NetLogSource& source,
     const GURL* original_url,
     const GURL* url,
     const AlternativeService* alternative_service,
     RequestPriority priority,
     NetLogCaptureMode /* capture_mode */) {
   std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
   if (source.IsValid())
@@ skipping 612 matching lines @@
   if (!IsPortAllowedForScheme(destination_.port(),
                               request_info_.url.scheme())) {
     return ERR_UNSAFE_PORT;
   }
 
   next_state_ = STATE_RESOLVE_PROXY;
   return OK;
 }
 
 int HttpStreamFactoryImpl::Job::DoResolveProxy() {
+  net_log_.AddEvent(NetLogEventType::HTTP_STREAM_JOB_RESOLVE_PROXY);
+
   DCHECK(!pac_request_);
   DCHECK(session_);
 
   next_state_ = STATE_RESOLVE_PROXY_COMPLETE;
 
   if (request_info_.load_flags & LOAD_BYPASS_PROXY) {
     proxy_info_.UseDirect();
     return OK;
   }
 
@@ skipping 75 matching lines @@
 }
 
 int HttpStreamFactoryImpl::Job::DoWaitComplete(int result) {
   net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_WAITING);
   DCHECK_EQ(OK, result);
   next_state_ = STATE_INIT_CONNECTION;
   return OK;
 }
 
 int HttpStreamFactoryImpl::Job::DoInitConnection() {
+  net_log_.BeginEvent(NetLogEventType::HTTP_STREAM_JOB_INIT_CONNECTION);
   int result = DoInitConnectionImpl();
+  bool should_resume =
+      (result != ERR_SPDY_SESSION_ALREADY_EXISTS && result != OK);
+  net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_INIT_CONNECTION_IMPL,
+                    NetLog::BoolCallback("should_resume", should_resume));
   if (result != ERR_SPDY_SESSION_ALREADY_EXISTS)
     delegate_->OnConnectionInitialized(this, result);
 
   return result;
 }
 
 int HttpStreamFactoryImpl::Job::DoInitConnectionImpl() {
+  net_log_.BeginEvent(NetLogEventType::HTTP_STREAM_JOB_INIT_CONNECTION_IMPL);
   // TODO(pkasting): Remove ScopedTracker below once crbug.com/462812 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "462812 HttpStreamFactoryImpl::Job::DoInitConnection"));
   DCHECK(!connection_->is_initialized());
   DCHECK(proxy_info_.proxy_server().is_valid());
   next_state_ = STATE_INIT_CONNECTION_COMPLETE;
 
   if (delegate_->OnInitConnection(proxy_info_)) {
     // Return since the connection initialization can be skipped.
@@ skipping 57 matching lines @@
       // The certificate of a QUIC alternative server is expected to be valid
       // for the origin of the request (in addition to being valid for the
       // server itself).
       destination = destination_;
       ssl_config = &server_ssl_config_;
     }
     int rv =
         quic_request_.Request(destination, request_info_.privacy_mode,
                               ssl_config->GetCertVerifyFlags(), url,
                               request_info_.method, net_log_, io_callback_);
+    int64_t delay = 0;
     if (rv == OK) {
       using_existing_quic_session_ = true;
     } else {
       // There's no available QUIC session. Inform the delegate how long to
       // delay the main job.
       if (rv == ERR_IO_PENDING) {
-        delegate_->MaybeSetWaitTimeForMainJob(
-            quic_request_.GetTimeDelayForWaitingJob());
+        base::TimeDelta delay_delta = quic_request_.GetTimeDelayForWaitingJob();
+        delay = delay_delta.InMicroseconds();
+        delegate_->MaybeSetWaitTimeForMainJob(delay_delta);
       }
     }
+    net_log_.AddEvent(NetLogEventType::HTTP_STREAM_JOB_CREATE_QUIC_REQUEST,
+                      base::Bind(&NetLogHttpStreamJobQuicRequestCallback, delay,
+                                 using_existing_quic_session_));
     return rv;
   }
 
   SpdySessionKey spdy_session_key = GetSpdySessionKey();
 
   // Check first if we have a spdy session for this group.  If so, then go
   // straight to using that.
   if (CanUseExistingSpdySession()) {
     base::WeakPtr<SpdySession> spdy_session =
         session_->spdy_session_pool()->FindAvailableSession(
@@ skipping 59 matching lines @@
   }
 
   return InitSocketHandleForHttpRequest(
       GetSocketGroup(), destination_, request_info_.extra_headers,
       request_info_.load_flags, priority_, session_, proxy_info_, expect_spdy,
       server_ssl_config_, proxy_ssl_config_, request_info_.privacy_mode,
       net_log_, connection_.get(), resolution_callback, io_callback_);
 }
 
 int HttpStreamFactoryImpl::Job::DoInitConnectionComplete(int result) {
+  net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_INIT_CONNECTION);
   if (job_type_ == PRECONNECT) {
     if (using_quic_)
       return result;
     DCHECK_EQ(OK, result);
     return OK;
   }
 
   if (result == ERR_SPDY_SESSION_ALREADY_EXISTS) {
     // We found a SPDY connection after resolving the host. This is
     // probably an IP pooled connection.
@@ skipping 517 matching lines @@
 
   ConnectionAttempts socket_attempts = connection_->connection_attempts();
   if (connection_->socket()) {
     connection_->socket()->GetConnectionAttempts(&socket_attempts);
   }
 
   delegate_->AddConnectionAttemptsToRequest(this, socket_attempts);
 }
 
 }  // namespace net