[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

net/http/http_stream_factory_impl_job_controller.cc

Index: net/http/http_stream_factory_impl_job_controller.cc
diff --git a/net/http/http_stream_factory_impl_job_controller.cc b/net/http/http_stream_factory_impl_job_controller.cc
index aa2a95ca1f3621a5c009b9a1b5492b9aa1db78b7..367e756ca105b3e169e5eab05f3fc023555eaf85 100644
--- a/net/http/http_stream_factory_impl_job_controller.cc
+++ b/net/http/http_stream_factory_impl_job_controller.cc
@@ -74,6 +74,8 @@ HttpStreamFactoryImpl::JobController::JobController(
 
 HttpStreamFactoryImpl::JobController::~JobController() {
   main_job_.reset();
+  net_log_.AddEvent(
+      NetLogEventType::ALT_JOB_DELETED_ON_DESTRUCT_JOB_CONTROLLER);

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

Instead of having multiple different event types (ALT_JOB_DELETED_ON_XXXX), how
about using a single event?

Here is the pattern I would suggest:

void ResetAlternativeJob(const char* function_name) {
  net_log_.AddEvent(
      NetLogEventType::JOB_CONTROLLER_RESET_ALT_JOB,
      NetLog::StringCallback("location", function_name));

  alternative_job_.reset();
}

Then replace each callsite of alternative_job_.reset() with:

    ResetAlternativeJob(__func__);

(if you prefer, can use __FILE__ and __LINE__, but __func__ is more stable IMO).

   alternative_job_.reset();
   bound_job_ = nullptr;
   net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER);
@@ -177,6 +179,8 @@ void HttpStreamFactoryImpl::JobController::OnRequestComplete() {
       // clean up |this| when the job completes.
     } else {
       DCHECK(bound_job_->job_type() == ALTERNATIVE);
+      net_log_.AddEvent(
+          NetLogEventType::ALT_JOB_DELETED_ON_REQUEST_COMPLETE_AND_BOUND);
       alternative_job_.reset();
     }
     bound_job_ = nullptr;
@@ -277,6 +281,8 @@ void HttpStreamFactoryImpl::JobController::OnStreamFailed(
     Job* job,
     int status,
     const SSLConfig& used_ssl_config) {
+  net_log_.BeginEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED,
+                      NetLog::BoolCallback("is_orphaned", IsJobOrphaned(job)));
   if (job->job_type() == ALTERNATIVE) {
     DCHECK_EQ(alternative_job_.get(), job);
     OnAlternativeJobFailed(status);
@@ -287,11 +293,14 @@ void HttpStreamFactoryImpl::JobController::OnStreamFailed(
   if (IsJobOrphaned(job)) {
     // We have bound a job to the associated Request, |job| has been orphaned.
     OnOrphanedJobComplete(job);
+    net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);

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

The begin/end measured by this event is entire synchronous. Just to confirm,
this is because you are interested in seeing if anything interesting happens
while within this stack frame?

[Optional] Instead of preceding each "return" with an EndEvent can use RAII. I
would be fine with throwing something like this into src/net/log:

class ScopedNetLogEndEvent {
 public:
  ScopedNetLogEndEvent(const NetLogWithSource& net_log, NetLogEventType event)
    : net_log_(net_log), event_(event) {}

  ~ScopedNetLogEndEvent() {
    net_log_.EndEvent(event);
  }

private:
  NetLogWithSource net_log_;
  NetLogEventType event;
};

     return;
   }
 
-  if (!request_)
+  if (!request_) {
+    net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);
     return;
+  }
   DCHECK_NE(OK, status);
   DCHECK(job);
 
@@ -304,8 +313,10 @@ void HttpStreamFactoryImpl::JobController::OnStreamFailed(
         main_job_.reset();
       } else {
         DCHECK(job->job_type() == ALTERNATIVE);
+        net_log_.AddEvent(NetLogEventType::ALT_JOB_DELETED_ON_STREAM_FAILED);
         alternative_job_.reset();
       }
+      net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);
       return;
     } else {
       BindJob(job);
@@ -313,6 +324,7 @@ void HttpStreamFactoryImpl::JobController::OnStreamFailed(
   }
 
   request_->OnStreamFailed(status, used_ssl_config);
+  net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);
 }
 
 void HttpStreamFactoryImpl::JobController::OnCertificateError(
@@ -525,6 +537,8 @@ void HttpStreamFactoryImpl::JobController::OnOrphanedJobComplete(
     main_job_.reset();
   } else {
     DCHECK_EQ(alternative_job_.get(), job);
+    net_log_.AddEvent(
+        NetLogEventType::ALT_JOB_DELETED_IN_ON_ORPHANED_JOB_COMPLETE);
     alternative_job_.reset();
   }
 
@@ -664,7 +678,7 @@ void HttpStreamFactoryImpl::JobController::MaybeSetWaitTimeForMainJob(
     const base::TimeDelta& delay) {
   if (main_job_is_blocked_) {
     main_job_wait_time_ = std::min(
-        delay, base::TimeDelta::FromSeconds(kMaxDelayTimeForMainJobSecs));
+        delay, base::TimeDelta::FromMilliseconds(kMaxDelayTimeForMainJobSecs));

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

Why this change? The variable is named "ForSecs".

   }
 }
 
@@ -773,6 +787,7 @@ void HttpStreamFactoryImpl::JobController::CancelJobs() {
     return;
   if (alternative_job_) {
     factory_->request_map_.erase(alternative_job_.get());
+    net_log_.AddEvent(NetLogEventType::ALT_JOB_DELETED_ON_CANCEL_JOBS);
     alternative_job_.reset();
   }
   if (main_job_) {