From 844c155753d7e42619a437ef6f3036aaf466e140 Mon Sep 17 00:00:00 2001 From: vadimt Date: Tue, 4 Nov 2014 14:55:57 -0800 Subject: 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} --- net/base/network_delegate.cc | 80 ++++++++++++++++++++++++++++++++++++++ net/url_request/url_request.cc | 49 ++++++++++++++++++++--- net/url_request/url_request_job.cc | 54 ++++++++++++++++++++++++- 3 files changed, 177 insertions(+), 6 deletions(-) (limited to 'net') 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 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 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(); } -- cgit v1.1