Add logging for ResourceScheduler events.

Specifically, log the ResourceScheduler throttling a request, and starting
a throttled requests.

This CL  also includes modifying some aspects of URLRequest logging:
* Log priority and url at URLRequest creation time (so if the ResourceScheduler
  blocks it, there will be some identifier for the request).
* Remove priority from URLRequest::StartJob logging (redundant with logging
  in the constructor and SetPriority method).
* Always log SetPriority (it's relevant to the ResourceScheduler even if there's
  no job attached to the URLRequest).

BUG=None
R=mmenke@chromium.org
R=csharrison@chromium.org
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.linux:closure_compilation

Review-Url: https://codereview.chromium.org/2579933002
Cr-Commit-Position: refs/heads/master@{#441259}

chrome/browser/resources/net_internals/source_entry.js

@@ -186,8 +186,10 @@ var SourceEntry = (function() {
     /**
      * Returns the starting entry for this source. Conceptually this is the
      * first entry that was logged to this source. However, we skip over the
-     * TYPE_REQUEST_ALIVE entries which wrap TYPE_URL_REQUEST_START_JOB
-     * entries.
+     * TYPE_REQUEST_ALIVE entries without parameters which wrap
+     * TYPE_URL_REQUEST_START_JOB entries.  (TYPE_REQUEST_ALIVE may or may not
+     * have parameters depending on what version of Chromium they were
+     * generated from.)
      */
     getStartEntry_: function() {
       if (this.entries_.length < 1)

content/browser/loader/resource_scheduler.cc

@@ -52,6 +52,38 @@ const RequestAttributes kAttributeInFlight = 0x01;
 const RequestAttributes kAttributeDelayable = 0x02;
 const RequestAttributes kAttributeLayoutBlocking = 0x04;
 
+// Reasons why pending requests may be started.  For logging only.
+enum class RequestStartTrigger {
+  NONE,
+  COMPLETION_PRE_BODY,
+  COMPLETION_POST_BODY,
+  BODY_REACHED,
+  CLIENT_KILL,
+  SPDY_PROXY_DETECTED,
+  REQUEST_REPRIORITIZED,
+};
+
+const char* RequestStartTriggerString(RequestStartTrigger trigger) {
+  switch (trigger) {
+    case RequestStartTrigger::NONE:
+      return "NONE";
+    case RequestStartTrigger::COMPLETION_PRE_BODY:
+      return "COMPLETION_PRE_BODY";
+    case RequestStartTrigger::COMPLETION_POST_BODY:
+      return "COMPLETION_POST_BODY";
+    case RequestStartTrigger::BODY_REACHED:
+      return "BODY_REACHED";
+    case RequestStartTrigger::CLIENT_KILL:
+      return "CLIENT_KILL";
+    case RequestStartTrigger::SPDY_PROXY_DETECTED:
+      return "SPDY_PROXY_DETECTED";
+    case RequestStartTrigger::REQUEST_REPRIORITIZED:
+      return "REQUEST_REPRIORITIZED";
+  }
+  NOTREACHED();
+  return "Unknown";
+}
+
 }  // namespace
 
 // The maximum number of delayable requests to allow to be in-flight at any
@@ -331,7 +363,7 @@ class ResourceScheduler::Client {
     SetRequestAttributes(request, DetermineRequestAttributes(request));
     if (ShouldStartRequest(request) == START_REQUEST) {
       // New requests can be started synchronously without issue.
-      StartRequest(request, START_SYNC);
+      StartRequest(request, START_SYNC, RequestStartTrigger::NONE);
     } else {
       pending_requests_.Insert(request);
     }
@@ -345,7 +377,10 @@ class ResourceScheduler::Client {
       EraseInFlightRequest(request);
 
       // Removing this request may have freed up another to load.
-      LoadAnyStartablePendingRequests();
+      LoadAnyStartablePendingRequests(
+          has_html_body_
+          ? RequestStartTrigger::COMPLETION_POST_BODY
+          : RequestStartTrigger::COMPLETION_PRE_BODY);
     }
   }
 
@@ -362,7 +397,7 @@ class ResourceScheduler::Client {
       pending_requests_.Erase(request);
       // Starting requests asynchronously ensures no side effects, and avoids
       // starting a bunch of requests that may be about to be deleted.
-      StartRequest(request, START_ASYNC);
+      StartRequest(request, START_ASYNC, RequestStartTrigger::CLIENT_KILL);
     }
     RequestSet unowned_requests;
     for (RequestSet::iterator it = in_flight_requests_.begin();
@@ -387,13 +422,13 @@ class ResourceScheduler::Client {
 
   void OnWillInsertBody() {
     has_html_body_ = true;
-    LoadAnyStartablePendingRequests();
+    LoadAnyStartablePendingRequests(RequestStartTrigger::BODY_REACHED);
   }
 
   void OnReceivedSpdyProxiedHttpResponse() {
     if (!using_spdy_proxy_) {
       using_spdy_proxy_ = true;
-      LoadAnyStartablePendingRequests();
+      LoadAnyStartablePendingRequests(RequestStartTrigger::SPDY_PROXY_DETECTED);
     }
   }
 
@@ -414,7 +449,8 @@ class ResourceScheduler::Client {
 
     if (new_priority_params.priority > old_priority_params.priority) {
       // Check if this request is now able to load at its new priority.
-      LoadAnyStartablePendingRequests();
+      LoadAnyStartablePendingRequests(
+          RequestStartTrigger::REQUEST_REPRIORITIZED);
     }
   }
 
@@ -560,7 +596,16 @@ class ResourceScheduler::Client {
   }
 
   void StartRequest(ScheduledResourceRequest* request,
-                    StartMode start_mode) {
+                    StartMode start_mode,
+                    RequestStartTrigger trigger) {
+    // Only log on requests that were blocked by the ResourceScheduler.
+    if (start_mode == START_ASYNC) {
+      DCHECK_NE(RequestStartTrigger::NONE, trigger);
+      request->url_request()->net_log().AddEvent(
+          net::NetLogEventType::RESOURCE_SCHEDULER_REQUEST_STARTED,
+          net::NetLog::StringCallback(
+              "trigger", RequestStartTriggerString(trigger)));
+    }
     InsertInFlightRequest(request);
     request->Start(start_mode);
   }
@@ -670,7 +715,7 @@ class ResourceScheduler::Client {
     return START_REQUEST;
   }
 
-  void LoadAnyStartablePendingRequests() {
+  void LoadAnyStartablePendingRequests(RequestStartTrigger trigger) {
     // We iterate through all the pending requests, starting with the highest
     // priority one. For each entry, one of three things can happen:
     // 1) We start the request, remove it from the list, and keep checking.
@@ -688,7 +733,7 @@ class ResourceScheduler::Client {
 
       if (query_result == START_REQUEST) {
         pending_requests_.Erase(request);
-        StartRequest(request, START_ASYNC);
+        StartRequest(request, START_ASYNC, trigger);
 
         // StartRequest can modify the pending list, so we (re)start evaluation
         // from the currently highest priority request. Avoid copying a singular

net/log/net_log_event_type_list.h

@@ -850,7 +850,7 @@ EVENT_TYPE(URL_REQUEST_DELEGATE)
 // Logged when a delegate informs the URL_REQUEST of what's currently blocking
 // the request. The parameters attached to the begin event are:
 //   {
-//     "delegate_info": <Information about what's blocking the request>,
+//     "delegate_blocked_by": <Information about what's blocking the request>,
 //   }
 EVENT_TYPE(DELEGATE_INFO)
 
@@ -3030,3 +3030,13 @@ EVENT_TYPE(UPLOAD_DATA_STREAM_INIT)
 //              the end of file. Result < 0 means an error.>
 // }
 EVENT_TYPE(UPLOAD_DATA_STREAM_READ)
+
+// -----------------------------------------------------------------------------
+// ResourceScheduler related events
+// -----------------------------------------------------------------------------
+
+// The ResourceScheduler has started a previously blocked request.  Parameters:
+// {
+//   "trigger": <Trigger for evaluation that caused request start>
+// }
+EVENT_TYPE(RESOURCE_SCHEDULER_REQUEST_STARTED)

net/url_request/url_request.cc

@@ -294,7 +294,7 @@ std::unique_ptr<base::Value> URLRequest::GetStateAsValue() const {
   if (!load_state.param.empty())
     dict->SetString("load_state_param", load_state.param);
   if (!blocked_by_.empty())
-    dict->SetString("delegate_info", blocked_by_);
+    dict->SetString("delegate_blocked_by", blocked_by_);
 
   dict->SetString("method", method_);
   dict->SetBoolean("has_upload", has_upload());
@@ -335,8 +335,9 @@ void URLRequest::LogBlockedBy(const char* blocked_by) {
   blocked_by_ = blocked_by;
   use_blocked_by_as_load_param_ = false;
 
-  net_log_.BeginEvent(NetLogEventType::DELEGATE_INFO,
-                      NetLog::StringCallback("delegate_info", &blocked_by_));
+  net_log_.BeginEvent(
+      NetLogEventType::DELEGATE_INFO,
+      NetLog::StringCallback("delegate_blocked_by", &blocked_by_));
 }
 
 void URLRequest::LogAndReportBlockedBy(const char* source) {
@@ -584,7 +585,9 @@ URLRequest::URLRequest(const GURL& url,
   DCHECK(base::ThreadTaskRunnerHandle::IsSet());
 
   context->url_requests()->insert(this);
-  net_log_.BeginEvent(NetLogEventType::REQUEST_ALIVE);
+  net_log_.BeginEvent(
+      NetLogEventType::REQUEST_ALIVE,
+      base::Bind(&NetLogURLRequestConstructorCallback, &url, priority_));
 }
 
 void URLRequest::BeforeRequestComplete(int error) {
@@ -627,7 +630,6 @@ void URLRequest::StartJob(URLRequestJob* job) {
   net_log_.BeginEvent(
       NetLogEventType::URL_REQUEST_START_JOB,
       base::Bind(&NetLogURLRequestStartCallback, &url(), &method_, load_flags_,
-                 priority_,
                  upload_data_stream_ ? upload_data_stream_->identifier() : -1));
 
   job_.reset(job);
@@ -1024,12 +1026,11 @@ void URLRequest::SetPriority(RequestPriority priority) {
     return;
 
   priority_ = priority;
-  if (job_.get()) {
-    net_log_.AddEvent(
-        NetLogEventType::URL_REQUEST_SET_PRIORITY,
-        NetLog::StringCallback("priority", RequestPriorityToString(priority_)));
+  net_log_.AddEvent(
+      NetLogEventType::URL_REQUEST_SET_PRIORITY,
+      NetLog::StringCallback("priority", RequestPriorityToString(priority_)));
+  if (job_.get())
     job_->SetPriority(priority_);
-  }
 }
 
 void URLRequest::NotifyAuthRequired(AuthChallengeInfo* auth_info) {

net/url_request/url_request_netlog_params.cc

@@ -13,18 +13,26 @@
 
 namespace net {
 
+std::unique_ptr<base::Value> NetLogURLRequestConstructorCallback(
+    const GURL* url,
+    RequestPriority priority,
+    NetLogCaptureMode /* capture_mode */) {
+  std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
+  dict->SetString("url", url->possibly_invalid_spec());
+  dict->SetString("priority", RequestPriorityToString(priority));
+  return std::move(dict);
+}
+
 std::unique_ptr<base::Value> NetLogURLRequestStartCallback(
     const GURL* url,
     const std::string* method,
     int load_flags,
-    RequestPriority priority,
     int64_t upload_id,
     NetLogCaptureMode /* capture_mode */) {
   std::unique_ptr<base::DictionaryValue> dict(new base::DictionaryValue());
   dict->SetString("url", url->possibly_invalid_spec());
   dict->SetString("method", *method);
   dict->SetInteger("load_flags", load_flags);
-  dict->SetString("priority", RequestPriorityToString(priority));
   if (upload_id > -1)
     dict->SetString("upload_id", base::Int64ToString(upload_id));
   return std::move(dict);

net/url_request/url_request_netlog_params.h

@@ -23,12 +23,17 @@ namespace net {
 
 class NetLogCaptureMode;
 
+// Returns a Value containing NetLog parameters for constructing a URLRequest.
+NET_EXPORT std::unique_ptr<base::Value> NetLogURLRequestConstructorCallback(
+    const GURL* url,
+    RequestPriority priority,
+    NetLogCaptureMode /* capture_mode */);
+
 // Returns a Value containing NetLog parameters for starting a URLRequest.
 NET_EXPORT std::unique_ptr<base::Value> NetLogURLRequestStartCallback(
     const GURL* url,
     const std::string* method,
     int load_flags,
-    RequestPriority priority,
     int64_t upload_id,
     NetLogCaptureMode /* capture_mode */);
 

net/url_request/url_request_unittest.cc

@@ -4861,7 +4861,7 @@ class AsyncDelegateLogger : public base::RefCounted<AsyncDelegateLogger> {
     std::string delegate_info;
     EXPECT_EQ(NetLogEventType::DELEGATE_INFO, entries[log_position].type);
     EXPECT_EQ(NetLogEventPhase::BEGIN, entries[log_position].phase);
-    EXPECT_TRUE(entries[log_position].GetStringValue("delegate_info",
+    EXPECT_TRUE(entries[log_position].GetStringValue("delegate_blocked_by",
                                                      &delegate_info));
     EXPECT_EQ(kFirstDelegateInfo, delegate_info);
 
@@ -4872,7 +4872,7 @@ class AsyncDelegateLogger : public base::RefCounted<AsyncDelegateLogger> {
     ++log_position;
     EXPECT_EQ(NetLogEventType::DELEGATE_INFO, entries[log_position].type);
     EXPECT_EQ(NetLogEventPhase::BEGIN, entries[log_position].phase);
-    EXPECT_TRUE(entries[log_position].GetStringValue("delegate_info",
+    EXPECT_TRUE(entries[log_position].GetStringValue("delegate_blocked_by",
                                                      &delegate_info));
     EXPECT_EQ(kSecondDelegateInfo, delegate_info);