[DO NOT SUBMIT, PATCH on commit 7fa349e632a44c152b05ca6a66ade5f2e5b3f139]

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 56 matching lines @@
                                  NetLogSourceType::HTTP_STREAM_JOB_CONTROLLER)),
       ptr_factory_(this) {
   DCHECK(factory);
   net_log_.BeginEvent(NetLogEventType::HTTP_STREAM_JOB_CONTROLLER,
                       base::Bind(&NetLogJobControllerCallback,
                                  &request_info.url, is_preconnect));
 }
 
 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);
 }
 
 bool HttpStreamFactoryImpl::JobController::for_websockets() {
   return factory_->for_websockets_;
 }
 
 HttpStreamFactoryImpl::Request* HttpStreamFactoryImpl::JobController::Start(
@@ skipping 83 matching lines @@
   request_ = nullptr;
   if (bound_job_) {
     if (bound_job_->job_type() == MAIN) {
       main_job_.reset();
       // |alternative_job_| can be non-null if |main_job_| is resumed after
       // |main_job_wait_time_| has elapsed. Allow |alternative_job_| to run to
       // completion, rather than resetting it. OnOrphanedJobComplete() will
       // 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;
   }
   MaybeNotifyFactoryOfCompletion();
 }
 
 int HttpStreamFactoryImpl::JobController::RestartTunnelWithProxyAuth() {
   DCHECK(bound_job_);
   return bound_job_->RestartTunnelWithProxyAuth();
@@ skipping 80 matching lines @@
 
   OnJobSucceeded(job);
   request_->OnWebSocketHandshakeStreamReady(used_ssl_config, used_proxy_info,
                                             stream);
 }
 
 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);
   }
 
   MaybeResumeMainJob(job, base::TimeDelta());
 
   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);
 
   if (!bound_job_) {
     if (main_job_ && alternative_job_) {
       // Hey, we've got other jobs! Maybe one of them will succeed, let's just
       // ignore this failure.
       factory_->request_map_.erase(job);
       if (job->job_type() == MAIN) {
         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);
     }
   }
 
   request_->OnStreamFailed(status, used_ssl_config);
+  net_log_.EndEvent(NetLogEventType::HTTP_STREAM_JOB_ON_STREAM_FAILED);
 }
 
 void HttpStreamFactoryImpl::JobController::OnCertificateError(
     Job* job,
     int status,
     const SSLConfig& used_ssl_config,
     const SSLInfo& ssl_info) {
   MaybeResumeMainJob(job, base::TimeDelta());
 
   if (IsJobOrphaned(job)) {
@@ skipping 192 matching lines @@
   MaybeNotifyFactoryOfCompletion();
 }
 
 void HttpStreamFactoryImpl::JobController::OnOrphanedJobComplete(
     const Job* job) {
   if (job->job_type() == MAIN) {
     DCHECK_EQ(main_job_.get(), job);
     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();
   }
 
   MaybeNotifyFactoryOfCompletion();
 }
 
 void HttpStreamFactoryImpl::JobController::AddConnectionAttemptsToRequest(
     Job* job,
     const ConnectionAttempts& attempts) {
   if (is_preconnect_ || (job_bound_ && bound_job_ != job))
@@ skipping 119 matching lines @@
 
 const NetLogWithSource* HttpStreamFactoryImpl::JobController::GetNetLog(
     Job* job) const {
   return &net_log_;
 }
 
 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".

   }
 }
 
 bool HttpStreamFactoryImpl::JobController::HasPendingMainJob() const {
   return main_job_.get() != nullptr;
 }
 
 bool HttpStreamFactoryImpl::JobController::HasPendingAltJob() const {
   return alternative_job_.get() != nullptr;
 }
@@ skipping 88 matching lines @@
   OrphanUnboundJob();
 }
 
 void HttpStreamFactoryImpl::JobController::CancelJobs() {
   DCHECK(request_);
   RemoveRequestFromSpdySessionRequestMap();
   if (job_bound_)
     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_) {
     factory_->request_map_.erase(main_job_.get());
     main_job_.reset();
   }
 }
 
 void HttpStreamFactoryImpl::JobController::OrphanUnboundJob() {
   DCHECK(request_);
@@ skipping 382 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