[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

net/http/http_stream_factory_impl_job.cc

Index: net/http/http_stream_factory_impl_job.cc
diff --git a/net/http/http_stream_factory_impl_job.cc b/net/http/http_stream_factory_impl_job.cc
index c837f75a0780e9131920c6860c0f6f47fa1d500a..ebc385c9c02442a37b96262b039f43df6d6055e3 100644
--- a/net/http/http_stream_factory_impl_job.cc
+++ b/net/http/http_stream_factory_impl_job.cc
@@ -120,6 +120,17 @@ void RecordChannelIDKeyMatch(SSLClientSocket* ssl_socket,
 
 }  // 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,
@@ -752,6 +763,8 @@ int HttpStreamFactoryImpl::Job::DoStart() {
 }
 
 int HttpStreamFactoryImpl::Job::DoResolveProxy() {
+  net_log_.AddEvent(NetLogEventType::HTTP_STREAM_JOB_RESOLVE_PROXY);
+
   DCHECK(!pac_request_);
   DCHECK(session_);
 
@@ -847,7 +860,12 @@ int HttpStreamFactoryImpl::Job::DoWaitComplete(int result) {
 }
 
 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);
 
@@ -855,6 +873,7 @@ int HttpStreamFactoryImpl::Job::DoInitConnection() {
 }
 
 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(
@@ -932,16 +951,21 @@ int HttpStreamFactoryImpl::Job::DoInitConnectionImpl() {
         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;
   }
 
@@ -1021,6 +1045,7 @@ int HttpStreamFactoryImpl::Job::DoInitConnectionImpl() {
 }
 
 int HttpStreamFactoryImpl::Job::DoInitConnectionComplete(int result) {
+  net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_INIT_CONNECTION);
   if (job_type_ == PRECONNECT) {
     if (using_quic_)
       return result;