Add logging for ResourceScheduler events.

content/browser/loader/resource_scheduler.cc

 // Copyright (c) 2012 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 "content/browser/loader/resource_scheduler.h"
 
 #include <stdint.h>
 #include <set>
 #include <string>
 #include <utility>
@@ skipping 33 matching lines @@
 };
 
 // Flags identifying various attributes of the request that are used
 // when making scheduling decisions.
 using RequestAttributes = uint8_t;
 const RequestAttributes kAttributeNone = 0x00;
 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
 // point in time (across all hosts).
 static const size_t kMaxNumDelayableRequestsPerClient = 10;
 
 // The maximum number of requests to allow be in-flight at any point in time per
 // host.
 static const size_t kMaxNumDelayableRequestsPerHostPerClient = 6;
 
@@ skipping 259 matching lines @@
         total_layout_blocking_count_(0),
         priority_requests_delayable_(priority_requests_delayable) {}
 
   ~Client() {}
 
   void ScheduleRequest(net::URLRequest* url_request,
                        ScheduledResourceRequest* request) {
     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);
     }
   }
 
   void RemoveRequest(ScheduledResourceRequest* request) {
     if (pending_requests_.IsQueued(request)) {
       pending_requests_.Erase(request);
       DCHECK(!base::ContainsKey(in_flight_requests_, request));
     } else {
       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);
     }
   }
 
   RequestSet StartAndRemoveAllRequests() {
     // First start any pending requests so that they will be moved into
     // in_flight_requests_. This may exceed the limits
     // kDefaultMaxNumDelayableRequestsPerClient and
     // kMaxNumDelayableRequestsPerHostPerClient, so this method must not do
     // anything that depends on those limits before calling
     // ClearInFlightRequests() below.
     while (!pending_requests_.IsEmpty()) {
       ScheduledResourceRequest* request =
           *pending_requests_.GetNextHighestIterator();
       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();
          it != in_flight_requests_.end(); ++it) {
       unowned_requests.insert(*it);
       (*it)->set_attributes(kAttributeNone);
     }
     ClearInFlightRequests();
     return unowned_requests;
   }
 
   bool is_loaded() const { return is_loaded_; }
 
   void OnLoadingStateChanged(bool is_loaded) {
     is_loaded_ = is_loaded;
   }
 
   void OnNavigate() {
     has_html_body_ = false;
     is_loaded_ = false;
   }
 
   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);
     }
   }
 
   void ReprioritizeRequest(ScheduledResourceRequest* request,
                            RequestPriorityParams old_priority_params,
                            RequestPriorityParams new_priority_params) {
     request->url_request()->SetPriority(new_priority_params.priority);
     request->set_request_priority_params(new_priority_params);
     SetRequestAttributes(request, DetermineRequestAttributes(request));
     if (!pending_requests_.IsQueued(request)) {
       DCHECK(base::ContainsKey(in_flight_requests_, request));
       // Request has already started.
       return;
     }
 
     pending_requests_.Erase(request);
     pending_requests_.Insert(request);
 
     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);
     }
   }
 
  private:
   enum ShouldStartReqResult {
     DO_NOT_START_REQUEST_AND_STOP_SEARCHING,
     DO_NOT_START_REQUEST_AND_KEEP_SEARCHING,
     START_REQUEST,
   };
 
@@ skipping 125 matching lines @@
       if (active_request_host.Equals((*it)->host_port_pair())) {
         same_host_count++;
         if (same_host_count >= kMaxNumDelayableRequestsPerHostPerClient)
           return true;
       }
     }
     return false;
   }
 
   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) {

[mmenke, 2017/01/03 22:24:18]

optional:  Would it be better to check if trigger is RequestStartTrigger::NONE?

[Charlie Harrison, 2017/01/03 22:26:47]

Whichever, DCHECKing that start_mode == START_ASYNC implies RequestStartTrigger
!= NONE would be nice.

[Randy Smith (Not in Mondays), 2017/01/03 22:37:09]

I'd prefer this check, since just conditionalizing on !NONE makes it easier to
dodge doing logging in hypothetical future triggers for starting requests.  We
want to make sure we log a trigger for all async started requests.  Done.

+      request->url_request()->net_log().AddEvent(
+          net::NetLogEventType::RESOURCE_SCHEDULER_REQUEST_STARTED,
+          net::NetLog::StringCallback(
+              "trigger", RequestStartTriggerString(trigger)));
+    }
     InsertInFlightRequest(request);
     request->Start(start_mode);
   }
 
   // ShouldStartRequest is the main scheduling algorithm.
   //
   // Requests are evaluated on five attributes:
   //
   // 1. Non-delayable requests:
   //   * Synchronous requests.
@@ skipping 89 matching lines @@
         // Block the request if at least one request is in flight and the
         // number of in-flight delayable requests has hit the configured
         // limit.
         return DO_NOT_START_REQUEST_AND_STOP_SEARCHING;
       }
     }
 
     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.
     // 2) We do NOT start the request, but ShouldStartRequest() signals us that
     //     there may be room for other requests, so we keep checking and leave
     //     the previous request still in the list.
     // 3) We do not start the request, same as above, but StartRequest() tells
     //     us there's no point in checking any further requests.
     RequestQueue::NetQueue::iterator request_iter =
         pending_requests_.GetNextHighestIterator();
 
     while (request_iter != pending_requests_.End()) {
       ScheduledResourceRequest* request = *request_iter;
       ShouldStartReqResult query_result = ShouldStartRequest(request);
 
       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
         // iterator, which would trigger undefined behavior.
         if (pending_requests_.GetNextHighestIterator() ==
             pending_requests_.End())
           break;
         request_iter = pending_requests_.GetNextHighestIterator();
       } else if (query_result == DO_NOT_START_REQUEST_AND_KEEP_SEARCHING) {
         ++request_iter;
@@ skipping 213 matching lines @@
   client->ReprioritizeRequest(scheduled_resource_request, old_priority_params,
                               new_priority_params);
 }
 
 ResourceScheduler::ClientId ResourceScheduler::MakeClientId(
     int child_id, int route_id) {
   return (static_cast<ResourceScheduler::ClientId>(child_id) << 32) | route_id;
 }
 
 }  // namespace content