Add net-log entries when HttpStream jobs are forced to wait, and when they're delayed and resumed.

net/http/http_stream_factory_impl_job_controller.cc

 // Copyright (c) 2016 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_controller.h"
 
 #include <memory>
 #include <string>
 #include <utility>
 
@@ skipping 15 matching lines @@
 #include "net/spdy/spdy_session.h"
 #include "url/url_constants.h"
 
 namespace net {
 
 // Returns parameters associated with the delay of the HTTP stream job.
 std::unique_ptr<base::Value> NetLogHttpStreamJobDelayCallback(
     base::TimeDelta delay,
     NetLogCaptureMode /* capture_mode */) {
   std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
-  dict->SetInteger("resume_after_ms", static_cast<int>(delay.InMilliseconds()));
+  dict->SetInteger("delay_ms", static_cast<int>(delay.InMilliseconds()));

[eroman, 2017/02/14 21:18:36]

Optional: replace this funciton with NetLog::Int64Callback() or
NetLog::IntCallback() ?

   return std::move(dict);
 }
 
 std::unique_ptr<base::Value> NetLogJobControllerCallback(
     const GURL* url,
     bool is_preconnect,
     NetLogCaptureMode /* capture_mode */) {
   auto dict = base::MakeUnique<base::DictionaryValue>();
   dict->SetString("url", url->possibly_invalid_spec());
   dict->SetBoolean("is_preconnect", is_preconnect);
@@ skipping 492 matching lines @@
 void HttpStreamFactoryImpl::JobController::AddConnectionAttemptsToRequest(
     Job* job,
     const ConnectionAttempts& attempts) {
   if (is_preconnect_ || (job_bound_ && bound_job_ != job))
     return;
 
   DCHECK(request_);
   request_->AddConnectionAttempts(attempts);
 }
 
+void HttpStreamFactoryImpl::JobController::ResumeMainJobLater(
+    const base::TimeDelta& delay) {
+  net_log_.AddEvent(NetLogEventType::HTTP_STREAM_JOB_DELAYED,
+                    base::Bind(&NetLogHttpStreamJobDelayCallback, delay));
+  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+      FROM_HERE,
+      base::Bind(&HttpStreamFactoryImpl::JobController::ResumeMainJob,

[eroman, 2017/02/14 21:18:36]

FTR I didn't review this in detail (i.e. wether there are sharp edges between
this async resumption). Will leave that to main reviewer...

[Ryan Hamilton, 2017/02/14 21:42:37]

*nod* I don't believe I've actually changed any behavior, just pushed code
around. But zhongyi will confirm.

+                 ptr_factory_.GetWeakPtr()),
+      delay);
+}
+
 void HttpStreamFactoryImpl::JobController::ResumeMainJob() {
   main_job_->net_log().AddEvent(
-      NetLogEventType::HTTP_STREAM_JOB_DELAYED,
+      NetLogEventType::HTTP_STREAM_JOB_RESUMED,
       base::Bind(&NetLogHttpStreamJobDelayCallback, main_job_wait_time_));
 
   main_job_->Resume();
   main_job_wait_time_ = base::TimeDelta();
 }
 
 void HttpStreamFactoryImpl::JobController::MaybeResumeMainJob(
     Job* job,
     const base::TimeDelta& delay) {
   DCHECK(job == main_job_.get() || job == alternative_job_.get());
 
   if (!main_job_is_blocked_ || job != alternative_job_.get() || !main_job_)
     return;
 
   main_job_is_blocked_ = false;
 
   if (!main_job_->is_waiting())
     return;
 
-  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
-      FROM_HERE,
-      base::Bind(&HttpStreamFactoryImpl::JobController::ResumeMainJob,
-                 ptr_factory_.GetWeakPtr()),
-      main_job_wait_time_);
+  ResumeMainJobLater(main_job_wait_time_);
 }
 
 void HttpStreamFactoryImpl::JobController::OnConnectionInitialized(Job* job,
                                                                    int rv) {
   if (rv != OK) {
     // Resume the main job as there's an error raised in connection
     // initiation.
     return MaybeResumeMainJob(job, main_job_wait_time_);
   }
 }
 
 bool HttpStreamFactoryImpl::JobController::ShouldWait(Job* job) {
   // The alternative job never waits.
   if (job == alternative_job_.get())
     return false;
 
   if (main_job_is_blocked_)
     return true;
 
   if (main_job_wait_time_.is_zero())
     return false;
 
-  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
-      FROM_HERE,
-      base::Bind(&HttpStreamFactoryImpl::JobController::ResumeMainJob,
-                 ptr_factory_.GetWeakPtr()),
-      main_job_wait_time_);
-
+  ResumeMainJobLater(main_job_wait_time_);
   return true;
 }
 
 void HttpStreamFactoryImpl::JobController::SetSpdySessionKey(
     Job* job,
     const SpdySessionKey& spdy_session_key) {
   if (is_preconnect_ || (job_bound_ && bound_job_ != job))
     return;
 
   DCHECK(request_);
@@ skipping 542 matching lines @@
     return;
   DCHECK(alternative_job_->alternative_proxy_server().is_valid());
   alternative_job_->Start(request_->stream_type());
 }
 
 bool HttpStreamFactoryImpl::JobController::IsJobOrphaned(Job* job) const {
   return !request_ || (job_bound_ && bound_job_ != job);
 }
 
 }  // namespace net