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 "Request completed (pre-body tag)";
+    case RequestStartTrigger::COMPLETION_POST_BODY:
+      return "Request completed (post-body tag)";
+    case RequestStartTrigger::BODY_REACHED:
+      return "Body tag reached";
+    case RequestStartTrigger::CLIENT_KILL:
+      return "Client killed";
+    case RequestStartTrigger::SPDY_PROXY_DETECTED:
+      return "HTTPS proxy detected";

[mmenke, 2016/12/16 16:46:46]

Note that we support non-SPDY HTTPS proxies, too.

[Randy Smith (Not in Mondays), 2016/12/20 16:54:17]

I think this means you think I should change the string "HTTPS proxy detected"
to "SPDY proxy detected"?  (I.e. I'm not sure under what circumstances we get
the OnReceivedSpdyProxiedHttpResponse() notification--the name suggests it's
only for the SPDY case, but I don't understand why we wouldn't shift over to not
throttling mode for any HTTPS proxy.)

Moot since I'm going to go with your suggestion below, but I'm still curious.

[mmenke, 2017/01/03 20:32:29]

Yea, I was thinking SPDY proxy detected (Or H2).

Why would we shift over to not throttling for an HTTP/1.x over HTTPS proxy?  The
reason we don't throttle for H2 proxies is that they have prioritization
themselves, and we defer to that instead of relying on holding back requests to
properly order responses.  HTTPS/1.x proxies don't have that capability, they're
exactly like HTTP/1.x proxies, except they have extra round trips to negotiate a
connection (And traffic to them is encrypted, of course).

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

Arggh, I was typing "HTTPS" and meaning "H2".  Gotcha; thanks for the
explanation.

+    case RequestStartTrigger::REQUEST_REPRIORITIZED:
+      return "Request reprioritized";

[mmenke, 2016/12/16 16:46:46]

Optional nit:  I suggest just matching the enum strings here.  net-internals is
meant to be used for debugging Chrome, and strings you can search the code for
are more useful than strings you search the code for to find the real string you
want to search for.

[Randy Smith (Not in Mondays), 2016/12/20 16:54:17]

Done.

+  }
+  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;
 
 // The maximum number of delayable requests to allow to be in-flight at any
 // point in time while in the layout-blocking phase of loading.
 static const size_t kMaxNumDelayableWhileLayoutBlockingPerClient = 1;
 
 // The priority level above which resources are considered layout-blocking if
 // the html_body has not started.
 static const net::RequestPriority
     kLayoutBlockingPriorityThreshold = net::MEDIUM;
 
 // The priority level below which resources are considered to be delayable.
 static const net::RequestPriority
     kDelayablePriorityThreshold = net::MEDIUM;
 
 // The number of in-flight layout-blocking requests above which all delayable
 // requests should be blocked.
 static const size_t kInFlightNonDelayableRequestCountPerClientThreshold = 1;
 
+// Sets an integer on construction and resets it to its original
+// value on destruction.  Value pointed to must be guaranteed by the caller
+// to remain alive for the lifetime of this class.
+template <class T>
+class ScopedSetter {
+ public:
+  ScopedSetter(T* target, T value) {
+    target_ = target;
+    original_value_ = *target;
+    *target = value;
+  }
+
+  ~ScopedSetter() { *target_ = original_value_; }
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(ScopedSetter);
+
+  T* target_;
+  T original_value_;
+};
+
+using ScopedTrigger = ScopedSetter<RequestStartTrigger>;

[mmenke, 2016/12/16 16:46:46]

This seems like over-engineering to me, and I'm not a fan of this general
pattern (Despite adding something somewhat similar in two of my ResourceLoader
CLs), but I'll defer to Charles on it.

[Randy Smith (Not in Mondays), 2016/12/20 16:54:17]

I dunno if this helps, but I finally tracked down my memory of the equivalent
functionality from base:: and replaced my gasket with that.   Willing to say
something about why you don't like the pattern?  I hate having to remember
(either in coding or maintenance) to reset variables back to earlier values on
exit from functions.

[mmenke, 2017/01/03 20:32:29]

I don't think functions should know or care exactly what's happening above them
on the stack.  I think functions having that sort of information breaks the
contract "This function does X".

[Charlie Harrison, 2017/01/03 21:22:49]

mmenke, I'm guessing you would prefer threading the value down through to each
call to StartRequest? That would be okay with me but I don't have strong
feelings here.

[mmenke, 2017/01/03 21:24:44]

Yes, that's what I'd do (Though, like I said, certainly not going to insist on
it, or even passive-aggressively whine about it whenever someone touches this
code).

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

I hear and sympathize with you both, but I think threading the values down would
be a lot of plumbing.  I'll take a swing at it before attempting to whine the
problem away, though.

ETA: As usual, if you actually look closely at a problem, it's not as big as you
think.  Done.

+
 struct ResourceScheduler::RequestPriorityParams {
   RequestPriorityParams()
     : priority(net::DEFAULT_PRIORITY),
       intra_priority(0) {
   }
 
   RequestPriorityParams(net::RequestPriority priority, int intra_priority)
     : priority(priority),
       intra_priority(intra_priority) {
   }
@@ skipping 223 matching lines @@
 
 // Each client represents a tab.
 class ResourceScheduler::Client {
  public:
   explicit Client(bool priority_requests_delayable)
       : is_loaded_(false),
         has_html_body_(false),
         using_spdy_proxy_(false),
         in_flight_delayable_count_(0),
         total_layout_blocking_count_(0),
-        priority_requests_delayable_(priority_requests_delayable) {}
+        priority_requests_delayable_(priority_requests_delayable),
+        request_start_trigger_(RequestStartTrigger::NONE) {}
 
   ~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);
     } else {
+      request->url_request()->net_log().AddEvent(
+          net::NetLogEventType::RESOURCE_SCHEDULER_REQUEST_BLOCKED);
       pending_requests_.Insert(request);
     }
   }
 
   void RemoveRequest(ScheduledResourceRequest* request) {
+    ScopedTrigger scoped_trigger(
+        &request_start_trigger_,
+        has_html_body_ ? RequestStartTrigger::COMPLETION_POST_BODY
+                       : RequestStartTrigger::COMPLETION_PRE_BODY);
+
     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();
     }
   }
 
   RequestSet StartAndRemoveAllRequests() {
+    ScopedTrigger scoped_trigger(&request_start_trigger_,
+                                 RequestStartTrigger::CLIENT_KILL);
+
     // 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);
@@ skipping 16 matching lines @@
   void OnLoadingStateChanged(bool is_loaded) {
     is_loaded_ = is_loaded;
   }
 
   void OnNavigate() {
     has_html_body_ = false;
     is_loaded_ = false;
   }
 
   void OnWillInsertBody() {
+    ScopedTrigger scoped_trigger(&request_start_trigger_,
+                                 RequestStartTrigger::BODY_REACHED);
+
     has_html_body_ = true;
     LoadAnyStartablePendingRequests();
   }
 
   void OnReceivedSpdyProxiedHttpResponse() {
+    ScopedTrigger scoped_trigger(&request_start_trigger_,
+                                 RequestStartTrigger::SPDY_PROXY_DETECTED);
+
     if (!using_spdy_proxy_) {
       using_spdy_proxy_ = true;
       LoadAnyStartablePendingRequests();
     }
   }
 
   void ReprioritizeRequest(ScheduledResourceRequest* request,
                            RequestPriorityParams old_priority_params,
                            RequestPriorityParams new_priority_params) {
+    ScopedTrigger scoped_trigger(&request_start_trigger_,
+                                 RequestStartTrigger::REQUEST_REPRIORITIZED);
+
     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);
@@ skipping 141 matching lines @@
         same_host_count++;
         if (same_host_count >= kMaxNumDelayableRequestsPerHostPerClient)
           return true;
       }
     }
     return false;
   }
 
   void StartRequest(ScheduledResourceRequest* request,
                     StartMode start_mode) {
+    // Only log on requests that were blocked by the ResourceScheduler.
+    if (start_mode == START_ASYNC) {
+      request->url_request()->net_log().AddEvent(
+          net::NetLogEventType::RESOURCE_SCHEDULER_REQUEST_STARTED,
+          net::NetLog::StringCallback(
+              "trigger", RequestStartTriggerString(request_start_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 141 matching lines @@
   RequestQueue pending_requests_;
   RequestSet in_flight_requests_;
   // The number of delayable in-flight requests.
   size_t in_flight_delayable_count_;
   // The number of layout-blocking in-flight requests.
   size_t total_layout_blocking_count_;
 
   // True if requests to servers that support priorities (e.g., H2/QUIC) can
   // be delayed.
   bool priority_requests_delayable_;
+
+  // Current start trigger.
+  RequestStartTrigger request_start_trigger_;
 };
 
 ResourceScheduler::ResourceScheduler()
     : priority_requests_delayable_(
           base::FeatureList::IsEnabled(kPrioritySupportedRequestsDelayable)) {}
 
 ResourceScheduler::~ResourceScheduler() {
   DCHECK(unowned_requests_.empty());
   DCHECK(client_map_.empty());
 }
@@ skipping 180 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