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.

[mmenke, 2014/11/03 16:19:15]

Do you really mean to keep this in that long?  I'm not expecting an easy fix to
this, and I'm not sure we want to keep all this extra stuff around too long -
seems like we can figure out what's slow, then remove those that track
everything that's fast enough that we don't care.

If that's the actual plan, just say so, no need to update comments to reflect
that.

[vadimt, 2014/11/04 01:04:23]

Yes, it's perfectly OK not not wait till the issue is solved. It's enough to
diagnose it, and then remove all instrumentations, perhaps, except the one
around the slow place.

It's not quite clear what you mean by "no need to update comments". These TODO
comments include the bug number, which lets us to find the instrumentations that
need to be removed for a given bug. This is necessary, since there are several
parallel investigations in progress.

[mmenke, 2014/11/04 19:50:13]

I mean your TODO about when you're going to remove it is inaccurate, per my
question, but updating it to be accurate is probably more effort than it's
worth.

+    tracked_objects::ScopedTracker tracking_profile1(
+        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);
 
+    // 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);
+
+    // 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/11/03 16:19:15]

I'd argue one just above "has_handled_response_ = true;" makes more sense than
one here - SetupFilter is presumably about as heavy weight than the code here,
since this just looks for on header, and converts a string to an integer, while
SetupFilter looks for one header and does some more work on top of that.

More importantly, that subtracts out time from "423948
URLRequestJob::NotifyHeadersComplete 2", so it's clearer just what it
contains...Which is, admittedly, not a whole lot.

[vadimt, 2014/11/04 01:04:23]

Moved the instrumentation up. 

+
     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();
 }