Instrumenting URLRequestJob::NotifyHeadersComplete to locate the source of jankiness

net/url_request/url_request_job.cc

Index: net/url_request/url_request_job.cc
diff --git a/net/url_request/url_request_job.cc b/net/url_request/url_request_job.cc
index 16f7b711478f5d8917ff0da423cb705ca69ae6c0..e82729991285d040a7c920fcf53d502ccbac5f2e 100644
--- a/net/url_request/url_request_job.cc
+++ b/net/url_request/url_request_job.cc
@@ -326,19 +326,45 @@ void URLRequestJob::NotifyHeadersComplete() {
   // survival until we can get out of this method.
   scoped_refptr<URLRequestJob> self_preservation(this);
 
-  if (request_)
+  if (request_) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile1(

[mmenke, 2014/10/31 16:52:15]

Could we get some docs on this class?  I have no idea what it does, or how
results from this show up.  Depending on the answer to that, the arrangement of
some of these may be in need of work.

[vadimt, 2014/10/31 23:38:33]

Done.

+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 1"));
+
     request_->OnHeadersComplete();
+  }
+
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile2(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 URLRequestJob::NotifyHeadersComplete 2"));
 
   GURL new_location;
   int http_status_code;
   if (IsRedirectResponse(&new_location, &http_status_code)) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile3(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 3"));
+
     // Redirect response bodies are not read. Notify the transaction
     // so it does not treat being stopped as an error.
     DoneReadingRedirectResponse();
 
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile4(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 4"));
+
     RedirectInfo redirect_info =
         ComputeRedirectInfo(new_location, http_status_code);

[mmenke, 2014/10/31 16:52:15]

This call is pretty uninteresting.  The NotifyReceivedRedirect is much more
interesting.

 
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile5(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 5"));
+
     bool defer_redirect = false;
     request_->NotifyReceivedRedirect(redirect_info, &defer_redirect);
 
@@ -347,6 +373,11 @@ void URLRequestJob::NotifyHeadersComplete() {
     if (!request_ || !request_->has_delegate())
       return;
 
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile6(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 6"));
+
     // If we were not cancelled, then maybe follow the redirect.
     if (request_->status().is_success()) {
       if (defer_redirect) {
@@ -357,8 +388,19 @@ void URLRequestJob::NotifyHeadersComplete() {
       return;
     }
   } else if (NeedsAuth()) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile7(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 7"));
+
     scoped_refptr<AuthChallengeInfo> auth_info;
     GetAuthChallengeInfo(&auth_info);

[mmenke, 2014/10/31 16:52:15]

Hrm..  AUTH requests are a fairly obscure corner case that I really don't think
we care about.

If we do, though, this function just dereferences a couple pointers, and is
completely irrelevant when it comes to performances.  The call to
request_->NotifyAuthRequired is where you should be looking, if we care (I
maintain we don't, really).

+
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile8(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 8"));
+
     // Need to check for a NULL auth_info because the server may have failed
     // to send a challenge with the 401 response.
     if (auth_info.get()) {
@@ -373,12 +415,22 @@ void URLRequestJob::NotifyHeadersComplete() {
     filter_.reset(SetupFilter());
 
   if (!filter_.get()) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile9(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequestJob::NotifyHeadersComplete 9"));

[mmenke, 2014/10/31 16:52:15]

This seems completely uninteresting - lookup up a single header, and a single
call to StringToInt64.  The SetupFilter() above also isn't terribly interesting,
but if we're concerned about reading a single header or two, makes sense to
cover that one, too (Or cover both with one tracker).

+
     std::string content_length;
     request_->GetResponseHeaderByName("content-length", &content_length);
     if (!content_length.empty())
       base::StringToInt64(content_length, &expected_content_size_);
   }
 
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile10(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 URLRequestJob::NotifyHeadersComplete 10"));
+
   request_->NotifyResponseStarted();
 }