Instrumenting URLRequestJob::NotifyHeadersComplete to locate the source of jankiness

Previous instrumentations showed that URLRequestJob::NotifyHeadersComplete
alone is responsible for ~57.1 janks per hour in IO thread. I need to instrument
the code inside it to find out which part causes jank.

This is a mechanical change that adds instrumentation required to locate the
source of jankiness (i.e. a long-running fragment of code executed as a part of
the task that causes jank) in the code. See the bug for details on what kind of
jank we are after.
A number of similar CLs were landed, and none of them caused issues. They've
helped to find and fix janky code. The code of the instrumentation is highly
optimized and is not expected to affect performance. The code simply creates a
diagnostic task which is identical to ones created by PostTask or IPC message
handlers. The task gets created only in developer build and in Canary channel.

BUG=423948

Review URL: https://codereview.chromium.org/696483002

Cr-Commit-Position: refs/heads/master@{#302694}

3 files changed, 177 insertions, 6 deletions

diff --git a/net/base/network_delegate.cc b/net/base/network_delegate.cc
index 1c315ec..9cad50a 100644
--- a/net/base/network_delegate.cc
+++ b/net/base/network_delegate.cc
@@ -5,6 +5,7 @@
 #include "net/base/network_delegate.h"
 
 #include "base/logging.h"
+#include "base/profiler/scoped_tracker.h"
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/proxy/proxy_info.h"
@@ -18,6 +19,10 @@ int NetworkDelegate::NotifyBeforeURLRequest(
   DCHECK(CalledOnValidThread());
   DCHECK(request);
   DCHECK(!callback.is_null());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnBeforeURLRequest"));
   return OnBeforeURLRequest(request, callback, new_url);
 }
 
@@ -28,6 +33,10 @@ void NetworkDelegate::NotifyResolveProxy(
     ProxyInfo* result) {
   DCHECK(CalledOnValidThread());
   DCHECK(result);
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnResolveProxy"));
   OnResolveProxy(url, load_flags, proxy_service, result);
 }
 
@@ -35,6 +44,10 @@ void NetworkDelegate::NotifyProxyFallback(
     const ProxyServer& bad_proxy,
     int net_error) {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnProxyFallback"));
   OnProxyFallback(bad_proxy, net_error);
 }
 
@@ -44,6 +57,10 @@ int NetworkDelegate::NotifyBeforeSendHeaders(
   DCHECK(CalledOnValidThread());
   DCHECK(headers);
   DCHECK(!callback.is_null());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnBeforeSendHeaders"));
   return OnBeforeSendHeaders(request, callback, headers);
 }
 
@@ -53,12 +70,20 @@ void NetworkDelegate::NotifyBeforeSendProxyHeaders(
     HttpRequestHeaders* headers) {
   DCHECK(CalledOnValidThread());
   DCHECK(headers);
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnBeforeSendProxyHeaders"));
   OnBeforeSendProxyHeaders(request, proxy_info, headers);
 }
 
 void NetworkDelegate::NotifySendHeaders(URLRequest* request,
                                         const HttpRequestHeaders& headers) {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnSendHeaders"));
   OnSendHeaders(request, headers);
 }
 
@@ -71,6 +96,10 @@ int NetworkDelegate::NotifyHeadersReceived(
   DCHECK(CalledOnValidThread());
   DCHECK(original_response_headers);
   DCHECK(!callback.is_null());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnHeadersReceived"));
   return OnHeadersReceived(request,
                            callback,
                            original_response_headers,
@@ -81,12 +110,20 @@ int NetworkDelegate::NotifyHeadersReceived(
 void NetworkDelegate::NotifyResponseStarted(URLRequest* request) {
   DCHECK(CalledOnValidThread());
   DCHECK(request);
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnResponseStarted"));
   OnResponseStarted(request);
 }
 
 void NetworkDelegate::NotifyRawBytesRead(const URLRequest& request,
                                          int bytes_read) {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnRawBytesRead"));
   OnRawBytesRead(request, bytes_read);
 }
 
@@ -94,24 +131,39 @@ void NetworkDelegate::NotifyBeforeRedirect(URLRequest* request,
                                            const GURL& new_location) {
   DCHECK(CalledOnValidThread());
   DCHECK(request);
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnBeforeRedirect"));
   OnBeforeRedirect(request, new_location);
 }
 
 void NetworkDelegate::NotifyCompleted(URLRequest* request, bool started) {
   DCHECK(CalledOnValidThread());
   DCHECK(request);
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 NetworkDelegate::OnCompleted"));
   OnCompleted(request, started);
 }
 
 void NetworkDelegate::NotifyURLRequestDestroyed(URLRequest* request) {
   DCHECK(CalledOnValidThread());
   DCHECK(request);
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnURLRequestDestroyed"));
   OnURLRequestDestroyed(request);
 }
 
 void NetworkDelegate::NotifyPACScriptError(int line_number,
                                            const base::string16& error) {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnPACScriptError"));
   OnPACScriptError(line_number, error);
 }
 
@@ -130,6 +182,10 @@ int NetworkDelegate::NotifyBeforeSocketStreamConnect(
   DCHECK(CalledOnValidThread());
   DCHECK(socket);
   DCHECK(!callback.is_null());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnBeforeSocketStreamConnect"));
   return OnBeforeSocketStreamConnect(socket, callback);
 }
 
@@ -137,6 +193,10 @@ bool NetworkDelegate::CanGetCookies(const URLRequest& request,
                                     const CookieList& cookie_list) {
   DCHECK(CalledOnValidThread());
   DCHECK(!(request.load_flags() & net::LOAD_DO_NOT_SEND_COOKIES));
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnCanGetCookies"));
   return OnCanGetCookies(request, cookie_list);
 }
 
@@ -145,17 +205,29 @@ bool NetworkDelegate::CanSetCookie(const URLRequest& request,
                                    CookieOptions* options) {
   DCHECK(CalledOnValidThread());
   DCHECK(!(request.load_flags() & net::LOAD_DO_NOT_SAVE_COOKIES));
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnCanSetCookie"));
   return OnCanSetCookie(request, cookie_line, options);
 }
 
 bool NetworkDelegate::CanAccessFile(const URLRequest& request,
                                     const base::FilePath& path) const {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnCanAccessFile"));
   return OnCanAccessFile(request, path);
 }
 
 bool NetworkDelegate::CanThrottleRequest(const URLRequest& request) const {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnCanThrottleRequest"));
   return OnCanThrottleRequest(request);
 }
 
@@ -163,6 +235,10 @@ bool NetworkDelegate::CanEnablePrivacyMode(
     const GURL& url,
     const GURL& first_party_for_cookies) const {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnCanEnablePrivacyMode"));
   return OnCanEnablePrivacyMode(url, first_party_for_cookies);
 }
 
@@ -171,6 +247,10 @@ bool NetworkDelegate::CancelURLRequestWithPolicyViolatingReferrerHeader(
     const GURL& target_url,
     const GURL& referrer_url) const {
   DCHECK(CalledOnValidThread());
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 NetworkDelegate::OnCancelURLRequestWithPolicy..."));
   return OnCancelURLRequestWithPolicyViolatingReferrerHeader(
       request, target_url, referrer_url);
 }
diff --git a/net/url_request/url_request.cc b/net/url_request/url_request.cc
index 7ae48e8..613d9bb 100644
--- a/net/url_request/url_request.cc
+++ b/net/url_request/url_request.cc
@@ -13,6 +13,7 @@
 #include "base/memory/singleton.h"
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/stats_counters.h"
+#include "base/profiler/scoped_tracker.h"
 #include "base/stl_util.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/synchronization/lock.h"
@@ -832,6 +833,11 @@ void URLRequest::NotifyReceivedRedirect(const RedirectInfo& redirect_info,
     RestartWithJob(job);
   } else if (delegate_) {
     OnCallToDelegate();
+
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequest::Delegate::OnReceivedRedirect"));
     delegate_->OnReceivedRedirect(this, redirect_info, defer_redirect);
     // |this| may be have been destroyed here.
   }
@@ -840,7 +846,14 @@ void URLRequest::NotifyReceivedRedirect(const RedirectInfo& redirect_info,
 void URLRequest::NotifyBeforeNetworkStart(bool* defer) {
   if (delegate_ && !notified_before_network_start_) {
     OnCallToDelegate();
-    delegate_->OnBeforeNetworkStart(this, defer);
+    {
+      // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is
+      // fixed.
+      tracked_objects::ScopedTracker tracking_profile(
+          FROM_HERE_WITH_EXPLICIT_FUNCTION(
+              "423948 URLRequest::Delegate::OnBeforeNetworkStart"));
+      delegate_->OnBeforeNetworkStart(this, defer);
+    }
     if (!*defer)
       OnCallToDelegateComplete();
     notified_before_network_start_ = true;
@@ -881,6 +894,11 @@ void URLRequest::NotifyResponseStarted() {
         NotifyRequestCompleted();
 
       OnCallToDelegate();
+      // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is
+      // fixed.
+      tracked_objects::ScopedTracker tracking_profile(
+          FROM_HERE_WITH_EXPLICIT_FUNCTION(
+              "423948 URLRequest::Delegate::OnResponseStarted"));
       delegate_->OnResponseStarted(this);
       // Nothing may appear below this line as OnResponseStarted may delete
       // |this|.
@@ -1097,8 +1115,14 @@ void URLRequest::NotifyAuthRequiredComplete(
     case NetworkDelegate::AUTH_REQUIRED_RESPONSE_NO_ACTION:
       // Defer to the URLRequest::Delegate, since the NetworkDelegate
       // didn't take an action.
-      if (delegate_)
+      if (delegate_) {
+        // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is
+        // fixed.
+        tracked_objects::ScopedTracker tracking_profile(
+            FROM_HERE_WITH_EXPLICIT_FUNCTION(
+                "423948 URLRequest::Delegate::OnAuthRequired"));
         delegate_->OnAuthRequired(this, auth_info.get());
+      }
       break;
 
     case NetworkDelegate::AUTH_REQUIRED_RESPONSE_SET_AUTH:
@@ -1117,14 +1141,24 @@ void URLRequest::NotifyAuthRequiredComplete(
 
 void URLRequest::NotifyCertificateRequested(
     SSLCertRequestInfo* cert_request_info) {
-  if (delegate_)
+  if (delegate_) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequest::Delegate::OnCertificateRequested"));
     delegate_->OnCertificateRequested(this, cert_request_info);
+  }
 }
 
 void URLRequest::NotifySSLCertificateError(const SSLInfo& ssl_info,
                                            bool fatal) {
-  if (delegate_)
+  if (delegate_) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequest::Delegate::OnSSLCertificateError"));
     delegate_->OnSSLCertificateError(this, ssl_info, fatal);
+  }
 }
 
 bool URLRequest::CanGetCookies(const CookieList& cookie_list) const {
@@ -1165,8 +1199,13 @@ void URLRequest::NotifyReadCompleted(int bytes_read) {
   if (bytes_read > 0 && !was_cached())
     NetworkChangeNotifier::NotifyDataReceived(*this, bytes_read);
 
-  if (delegate_)
+  if (delegate_) {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 URLRequest::Delegate::OnReadCompleted"));
     delegate_->OnReadCompleted(this, bytes_read);
+  }
 
   // Nothing below this line as OnReadCompleted may delete |this|.
 }
diff --git a/net/url_request/url_request_job.cc b/net/url_request/url_request_job.cc
index 16f7b71..3610195 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(
+        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()) {
@@ -368,6 +410,11 @@ void URLRequestJob::NotifyHeadersComplete() {
     }
   }
 
+  // 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"));
+
   has_handled_response_ = true;
   if (request_->status().is_success())
     filter_.reset(SetupFilter());
@@ -379,6 +426,11 @@ void URLRequestJob::NotifyHeadersComplete() {
       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();
 }