Add logging for ResourceScheduler events.

content/browser/loader/resource_scheduler.cc

Index: content/browser/loader/resource_scheduler.cc
diff --git a/content/browser/loader/resource_scheduler.cc b/content/browser/loader/resource_scheduler.cc
index 39ef40aca97d3af827eebe15d7bde36be91fb7ae..0b80b79bcd49215dfd4a438e54199a3b34ca2616 100644
--- a/content/browser/loader/resource_scheduler.cc
+++ b/content/browser/loader/resource_scheduler.cc
@@ -51,6 +51,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 "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
@@ -78,6 +110,29 @@ static const net::RequestPriority
 // 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),
@@ -321,7 +376,8 @@ class ResourceScheduler::Client {
         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() {}
 
@@ -332,11 +388,18 @@ class ResourceScheduler::Client {
       // 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));
@@ -349,6 +412,9 @@ class ResourceScheduler::Client {
   }
 
   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
@@ -385,11 +451,17 @@ class ResourceScheduler::Client {
   }
 
   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();
@@ -399,6 +471,9 @@ class ResourceScheduler::Client {
   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));
@@ -560,6 +635,13 @@ class ResourceScheduler::Client {
 
   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);
   }
@@ -721,6 +803,9 @@ class ResourceScheduler::Client {
   // 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()