Adding instrumentation to locate the source of jankiness.

content/browser/loader/resource_loader.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 "content/browser/loader/resource_loader.h"
 
 #include "base/command_line.h"
 #include "base/message_loop/message_loop.h"
 #include "base/metrics/histogram.h"
+#include "base/profiler/scoped_tracker.h"
 #include "base/time/time.h"
 #include "content/browser/appcache/appcache_interceptor.h"
 #include "content/browser/child_process_security_policy_impl.h"
 #include "content/browser/loader/cross_site_resource_handler.h"
 #include "content/browser/loader/detachable_resource_handler.h"
 #include "content/browser/loader/resource_loader_delegate.h"
 #include "content/browser/loader/resource_request_info_impl.h"
 #include "content/browser/service_worker/service_worker_request_handler.h"
 #include "content/browser/ssl/ssl_client_auth_handler.h"
 #include "content/browser/ssl/ssl_manager.h"
@@ skipping 84 matching lines @@
 }
 
 void ResourceLoader::StartRequest() {
   if (delegate_->HandleExternalProtocol(this, request_->url())) {
     CancelAndIgnore();
     return;
   }
 
   // Give the handler a chance to delay the URLRequest from being started.
   bool defer_start = false;
-  if (!handler_->OnWillStart(request_->url(), &defer_start)) {
-    Cancel();
-    return;
+  {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 ResourceLoader::StartRequest"));
+
+    if (!handler_->OnWillStart(request_->url(), &defer_start)) {
+      Cancel();
+      return;
+    }
   }
 
   if (defer_start) {
     deferred_stage_ = DEFERRED_START;
   } else {
     StartRequestInternal();
   }
 }
 
 void ResourceLoader::CancelRequest(bool from_renderer) {
@@ skipping 28 matching lines @@
   TimeDelta time_since_last = TimeTicks::Now() - last_upload_ticks_;
 
   bool is_finished = (progress.size() == progress.position());
   bool enough_new_progress =
       (amt_since_last > (progress.size() / kHalfPercentIncrements));
   bool too_much_time_passed = time_since_last > kOneSecond;
 
   if (is_finished || enough_new_progress || too_much_time_passed) {
     ResourceRequestInfoImpl* info = GetRequestInfo();
     if (info->is_upload_progress_enabled()) {
+      // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is
+      // fixed.
+      tracked_objects::ScopedTracker tracking_profile(
+          FROM_HERE_WITH_EXPLICIT_FUNCTION(
+              "423948 ResourceLoader::ReportUploadProgress"));
+
       handler_->OnUploadProgress(progress.position(), progress.size());
       waiting_for_upload_progress_ack_ = true;
     }
     last_upload_ticks_ = TimeTicks::Now();
     last_upload_position_ = progress.position();
   }
 }
 
 void ResourceLoader::MarkAsTransferring() {
   CHECK(IsResourceTypeFrame(GetRequestInfo()->GetResourceType()))
@@ skipping 50 matching lines @@
 
   if (delegate_->HandleExternalProtocol(this, redirect_info.new_url)) {
     // The request is complete so we can remove it.
     CancelAndIgnore();
     return;
   }
 
   scoped_refptr<ResourceResponse> response(new ResourceResponse());
   PopulateResourceResponse(info, request_.get(), response.get());
 
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 ResourceLoader::OnReceivedRedirect"));
+
   if (!handler_->OnRequestRedirected(redirect_info, response.get(), defer)) {
     Cancel();
   } else if (*defer) {
     deferred_stage_ = DEFERRED_REDIRECT;  // Follow redirect when resumed.
   }
 }
 
 void ResourceLoader::OnAuthRequired(net::URLRequest* unused,
                                     net::AuthChallengeInfo* auth_info) {
   DCHECK_EQ(request_.get(), unused);
@@ skipping 51 matching lines @@
       render_process_id,
       render_frame_id,
       ssl_info,
       fatal);
 }
 
 void ResourceLoader::OnBeforeNetworkStart(net::URLRequest* unused,
                                           bool* defer) {
   DCHECK_EQ(request_.get(), unused);
 
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 ResourceLoader::OnBeforeNetworkStart"));
+
   // Give the handler a chance to delay the URLRequest from using the network.
   if (!handler_->OnBeforeNetworkStart(request_->url(), defer)) {
     Cancel();
     return;
   } else if (*defer) {
     deferred_stage_ = DEFERRED_NETWORK_START;
   }
 }
 
 void ResourceLoader::OnResponseStarted(net::URLRequest* unused) {
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 ResourceLoader::OnResponseStarted"));
+
   DCHECK_EQ(request_.get(), unused);
 
   VLOG(1) << "OnResponseStarted: " << request_->url().spec();
 
   // The CanLoadPage check should take place after any server redirects have
   // finished, at the point in time that we know a page will commit in the
   // renderer process.
   ResourceRequestInfoImpl* info = GetRequestInfo();
   ChildProcessSecurityPolicyImpl* policy =
       ChildProcessSecurityPolicyImpl::GetInstance();
@@ skipping 21 matching lines @@
     return;
 
   if (request_->status().is_success()) {
     StartReading(false);  // Read the first chunk.
   } else {
     ResponseCompleted();
   }
 }
 
 void ResourceLoader::OnReadCompleted(net::URLRequest* unused, int bytes_read) {
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 ResourceLoader::OnReadCompleted"));
+
   DCHECK_EQ(request_.get(), unused);
   VLOG(1) << "OnReadCompleted: \"" << request_->url().spec() << "\""
           << " bytes_read = " << bytes_read;
 
   // bytes_read == -1 always implies an error.
   if (bytes_read == -1 || !request_->status().is_success()) {
     ResponseCompleted();
     return;
   }
 
@@ skipping 179 matching lines @@
         signed_certificate_timestamp_ids);
   } else {
     // We should not have any SSL state.
     DCHECK(!request_->ssl_info().cert_status &&
            request_->ssl_info().security_bits == -1 &&
            !request_->ssl_info().connection_status);
   }
 
   delegate_->DidReceiveResponse(this);
 
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION(
+          "423948 ResourceLoader::CompleteResponseStarted"));
+
   bool defer = false;
   if (!handler_->OnResponseStarted(response.get(), &defer)) {
     Cancel();
   } else if (defer) {
     read_deferral_start_time_ = base::TimeTicks::Now();
     deferred_stage_ = DEFERRED_READ;  // Read first chunk when resumed.
   }
 }
 
 void ResourceLoader::StartReading(bool is_continuation) {
@@ skipping 34 matching lines @@
 }
 
 void ResourceLoader::ReadMore(int* bytes_read) {
   DCHECK(!is_deferred());
 
   // Make sure we track the buffer in at least one place.  This ensures it gets
   // deleted even in the case the request has already finished its job and
   // doesn't use the buffer.
   scoped_refptr<net::IOBuffer> buf;
   int buf_size;
-  if (!handler_->OnWillRead(&buf, &buf_size, -1)) {
-    Cancel();
-    return;
+  {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 ResourceLoader::ReadMore"));
+
+    if (!handler_->OnWillRead(&buf, &buf_size, -1)) {
+      Cancel();
+      return;
+    }
   }
 
   DCHECK(buf.get());
   DCHECK(buf_size > 0);
 
   request_->Read(buf.get(), buf_size, bytes_read);
 
   // No need to check the return value here as we'll detect errors by
   // inspecting the URLRequest's status.
 }
 
 void ResourceLoader::CompleteRead(int bytes_read) {
   DCHECK(bytes_read >= 0);
   DCHECK(request_->status().is_success());
 
+  // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+  tracked_objects::ScopedTracker tracking_profile(
+      FROM_HERE_WITH_EXPLICIT_FUNCTION("423948 ResourceLoader::CompleteRead"));
+
   bool defer = false;
   if (!handler_->OnReadCompleted(bytes_read, &defer)) {
     Cancel();
   } else if (defer) {
     deferred_stage_ =
         bytes_read > 0 ? DEFERRED_READ : DEFERRED_RESPONSE_COMPLETE;
   }
 
   // Note: the request may still have been cancelled while OnReadCompleted
   // returns true if OnReadCompleted caused request to get cancelled
@@ skipping 15 matching lines @@
     StoreSignedCertificateTimestamps(ssl_info.signed_certificate_timestamps,
                                      info->GetChildID(),
                                      &signed_certificate_timestamp_ids);
 
     security_info = SerializeSecurityInfo(
         cert_id, ssl_info.cert_status, ssl_info.security_bits,
         ssl_info.connection_status, signed_certificate_timestamp_ids);
   }
 
   bool defer = false;
-  handler_->OnResponseCompleted(request_->status(), security_info, &defer);
+  {
+    // TODO(vadimt): Remove ScopedTracker below once crbug.com/423948 is fixed.
+    tracked_objects::ScopedTracker tracking_profile(
+        FROM_HERE_WITH_EXPLICIT_FUNCTION(
+            "423948 ResourceLoader::ResponseCompleted"));
+
+    handler_->OnResponseCompleted(request_->status(), security_info, &defer);
+  }
   if (defer) {
     // The handler is not ready to die yet.  We will call DidFinishLoading when
     // we resume.
     deferred_stage_ = DEFERRED_FINISH;
   } else {
     // This will result in our destruction.
     CallDidFinishLoading();
   }
 }
 
@@ skipping 33 matching lines @@
     UMA_HISTOGRAM_ENUMERATION("Net.Prefetch.Pattern", status, STATUS_MAX);
   }
 }
 
 void ResourceLoader::ContinueWithCertificate(net::X509Certificate* cert) {
   ssl_client_auth_handler_.reset();
   request_->ContinueWithCertificate(cert);
 }
 
 }  // namespace content