Instrumenting URLRequestJob::NotifyHeadersComplete to locate the source of jankiness

net/url_request/url_request_job.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 "net/url_request/url_request_job.h"
 
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/message_loop/message_loop.h"
 #include "base/power_monitor/power_monitor.h"
@@ skipping 308 matching lines @@
   request_->response_info_.response_time = base::Time::Now();
   GetResponseInfo(&request_->response_info_);
 
   // When notifying the delegate, the delegate can release the request
   // (and thus release 'this').  After calling to the delgate, we must
   // check the request pointer to see if it still exists, and return
   // immediately if it has been destroyed.  self_preservation ensures our
   // 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);
 
     // Ensure that the request wasn't detached or destroyed in
     // NotifyReceivedRedirect
     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) {
         deferred_redirect_info_ = redirect_info;
       } else {
         FollowRedirect(redirect_info);
       }
       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()) {
       request_->NotifyAuthRequired(auth_info.get());
       // Wait for SetAuth or CancelAuth to be called.
       return;
     }
   }
 
   has_handled_response_ = true;
   if (request_->status().is_success())
     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();
 }
 
 void URLRequestJob::NotifyReadComplete(int bytes_read) {
   if (!request_ || !request_->has_delegate())
     return;  // The request was destroyed, so there is no more work to do.
 
   // TODO(darin): Bug 1004233. Re-enable this test once all of the chrome
   // unit_tests have been fixed to not trip this.
 #if 0
@@ skipping 409 matching lines @@
       !redirect_info.new_url.SchemeIsSecure()) {
     redirect_info.new_referrer.clear();
   } else {
     redirect_info.new_referrer = request_->referrer();
   }
 
   return redirect_info;
 }
 
 }  // namespace net