[NOT FOR LANDING] Detailed loading traces

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 <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "base/command_line.h"
 #include "base/location.h"
 #include "base/metrics/histogram.h"
 #include "base/profiler/scoped_tracker.h"
 #include "base/single_thread_task_runner.h"
 #include "base/thread_task_runner_handle.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"
@@ skipping 40 matching lines @@
     const int sct_id(sct_store->Store(iter->sct.get(), process_id));
     sct_ids->push_back(
         SignedCertificateTimestampIDAndStatus(sct_id, iter->status));
   }
 }
 
 void GetSSLStatusForRequest(const GURL& url,
                             const net::SSLInfo& ssl_info,
                             int child_id,
                             SSLStatus* ssl_status) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::GetSSLStatusForRequest");
+
   DCHECK(ssl_info.cert);
 
   int cert_id =
       CertStore::GetInstance()->StoreCert(ssl_info.cert.get(), child_id);
 
   SignedCertificateTimestampIDStatusList signed_certificate_timestamp_ids;
   StoreSignedCertificateTimestamps(ssl_info.signed_certificate_timestamps,
                                    child_id, &signed_certificate_timestamp_ids);
 
   *ssl_status = SSLStatus(SSLPolicy::GetSecurityStyleForResource(
                               url, cert_id, ssl_info.cert_status),
                           cert_id, signed_certificate_timestamp_ids, ssl_info);
 }
 
 void PopulateResourceResponse(ResourceRequestInfoImpl* info,
                               net::URLRequest* request,
                               ResourceResponse* response) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::PopulateResourceResponse");
   response->head.request_time = request->request_time();
   response->head.response_time = request->response_time();
   response->head.headers = request->response_headers();
   request->GetCharset(&response->head.charset);
   response->head.content_length = request->GetExpectedContentSize();
   request->GetMimeType(&response->head.mime_type);
   net::HttpResponseInfo response_info = request->response_info();
   response->head.was_fetched_via_spdy = response_info.was_fetched_via_spdy;
   response->head.was_npn_negotiated = response_info.was_npn_negotiated;
   response->head.npn_negotiated_protocol =
@@ skipping 45 matching lines @@
       is_transferring_(false),
       times_cancelled_before_request_start_(0),
       started_request_(false),
       times_cancelled_after_request_start_(0),
       weak_ptr_factory_(this) {
   request_->set_delegate(this);
   handler_->SetController(this);
 }
 
 ResourceLoader::~ResourceLoader() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::~ResourceLoader");
+
   if (login_delegate_.get())
     login_delegate_->OnRequestCancelled();
   ssl_client_auth_handler_.reset();
 
   // Run ResourceHandler destructor before we tear-down the rest of our state
   // as the ResourceHandler may want to inspect the URLRequest and other state.
-  handler_.reset();
+  {
+    TRACE_EVENT0("toplevel", "ResourceLoader::~ResourceLoader::ResetHandlers");
+    handler_.reset();
+  }
 }
 
 void ResourceLoader::StartRequest() {
-  if (delegate_->HandleExternalProtocol(this, request_->url())) {
-    CancelAndIgnore();
-    return;
+  TRACE_EVENT0("toplevel", "ResourceLoader::StartRequest");
+
+  {
+    TRACE_EVENT0("toplevel", "ResourceLoaderDelegate::HandleExternalProtocol");
+    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;
+  {
+    TRACE_EVENT0("toplevel", "ResourceHandler::OnWillStart");
+    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 41 matching lines @@
   ServiceWorkerRequestHandler* handler =
       ServiceWorkerRequestHandler::GetHandler(request());
   if (handler)
     handler->MaybeCompleteCrossSiteTransferInOldProcess(child_id);
 
   is_transferring_ = false;
   GetRequestInfo()->cross_site_handler()->ResumeResponse();
 }
 
 ResourceRequestInfoImpl* ResourceLoader::GetRequestInfo() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::GetRequestInfo");
   return ResourceRequestInfoImpl::ForRequest(request_.get());
 }
 
 void ResourceLoader::ClearLoginDelegate() {
   login_delegate_ = NULL;
 }
 
 void ResourceLoader::OnReceivedRedirect(net::URLRequest* unused,
                                         const net::RedirectInfo& redirect_info,
                                         bool* defer) {
@@ skipping 87 matching lines @@
   // 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) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::OnResponseStarted");
   DCHECK_EQ(request_.get(), unused);
 
   DVLOG(1) << "OnResponseStarted: " << request_->url().spec();
 
   if (!request_->status().is_success()) {
     ResponseCompleted();
     return;
   }
 
   CompleteResponseStarted();
 
   if (is_deferred())
     return;
 
   if (request_->status().is_success())
     StartReading(false);  // Read the first chunk.
   else
     ResponseCompleted();
 }
 
 void ResourceLoader::OnReadCompleted(net::URLRequest* unused, int bytes_read) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::OnReadCompleted");
   DCHECK_EQ(request_.get(), unused);
   DVLOG(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 100 matching lines @@
                                 weak_ptr_factory_.GetWeakPtr()));
       break;
   }
 }
 
 void ResourceLoader::Cancel() {
   CancelRequest(false);
 }
 
 void ResourceLoader::StartRequestInternal() {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::StartRequestInternal");
   DCHECK(!request_->is_pending());
 
   if (!request_->status().is_success()) {
     return;
   }
 
   started_request_ = true;
   request_->Start();
 
   delegate_->DidStartRequest(this);
@@ skipping 39 matching lines @@
     // If the request isn't in flight, then we won't get an asynchronous
     // notification from the request, so we have to signal ourselves to finish
     // this request.
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(&ResourceLoader::ResponseCompleted,
                               weak_ptr_factory_.GetWeakPtr()));
   }
 }
 
 void ResourceLoader::CompleteResponseStarted() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::CompleteResponseStarted");
   ResourceRequestInfoImpl* info = GetRequestInfo();
   scoped_refptr<ResourceResponse> response(new ResourceResponse());
   PopulateResourceResponse(info, request_.get(), response.get());
 
   delegate_->DidReceiveResponse(this);
 
   // TODO(darin): Remove ScopedTracker below once crbug.com/475761 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION("475761 OnResponseStarted()"));
 
   bool defer = false;
-  if (!handler_->OnResponseStarted(response.get(), &defer)) {
+  bool ok;
+  {
+    TRACE_EVENT0("toplevel", "ResourceHandler::OnResponseStarted");
+    ok = handler_->OnResponseStarted(response.get(), &defer);
+  }
+  if (!ok) {
     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) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::StartReading");
   int bytes_read = 0;
   ReadMore(&bytes_read);
 
   // If IO is pending, wait for the URLRequest to call OnReadCompleted.
   if (request_->status().is_io_pending())
     return;
 
   if (!is_continuation || bytes_read <= 0) {
     OnReadCompleted(request_.get(), bytes_read);
   } else {
@@ skipping 15 matching lines @@
     read_deferral_start_time_ = base::TimeTicks();
   }
   if (request_->status().is_success()) {
     StartReading(false);  // Read the next chunk (OK to complete synchronously).
   } else {
     ResponseCompleted();
   }
 }
 
 void ResourceLoader::ReadMore(int* bytes_read) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::ReadMore");
+
   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;
   {
     // TODO(darin): Remove ScopedTracker below once crbug.com/475761 is fixed.
     tracked_objects::ScopedTracker tracking_profile2(
         FROM_HERE_WITH_EXPLICIT_FUNCTION("475761 OnWillRead()"));
 
-    if (!handler_->OnWillRead(&buf, &buf_size, -1)) {
-      Cancel();
-      return;
+    {
+      TRACE_EVENT0("toplevel", "ResourceHandler::OnWillRead");
+
+      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) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::CompleteRead");
   DCHECK(bytes_read >= 0);
   DCHECK(request_->status().is_success());
 
   // TODO(darin): Remove ScopedTracker below once crbug.com/475761 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION("475761 OnReadCompleted()"));
 
   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
   // out-of-band. (In AwResourceDispatcherHostDelegate::DownloadStarting, for
   // instance.)
 }
 
 void ResourceLoader::ResponseCompleted() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::ResponseCompleted");
   DVLOG(1) << "ResponseCompleted: " << request_->url().spec();
   RecordHistograms();
   ResourceRequestInfoImpl* info = GetRequestInfo();
 
   std::string security_info;
   const net::SSLInfo& ssl_info = request_->ssl_info();
   if (ssl_info.cert.get() != NULL) {
     SSLStatus ssl_status;
     GetSSLStatusForRequest(request_->url(), ssl_info, info->GetChildID(),
                            &ssl_status);
 
     security_info = SerializeSecurityInfo(ssl_status);
   }
 
   bool defer = false;
   {
     // TODO(darin): Remove ScopedTracker below once crbug.com/475761 is fixed.
     tracked_objects::ScopedTracker tracking_profile(
         FROM_HERE_WITH_EXPLICIT_FUNCTION("475761 OnResponseCompleted()"));
 
-    handler_->OnResponseCompleted(request_->status(), security_info, &defer);
+    {
+      TRACE_EVENT0("toplevel", "ResourceHandler::OnResponseCompleted");
+      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();
   }
 }
 
 void ResourceLoader::CallDidFinishLoading() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::CallDidFinishLoading");
   delegate_->DidFinishLoading(this);
 }
 
 void ResourceLoader::RecordHistograms() {
   if (request_->response_info().network_accessed) {
     UMA_HISTOGRAM_ENUMERATION("Net.HttpResponseInfo.ConnectionInfo",
                               request_->response_info().connection_info,
                               net::HttpResponseInfo::NUM_OF_CONNECTION_INFOS);
   }
 
@@ skipping 23 matching lines @@
       case net::URLRequestStatus::FAILED:
         status = STATUS_UNDEFINED;
         break;
     }
 
     UMA_HISTOGRAM_ENUMERATION("Net.Prefetch.Pattern", status, STATUS_MAX);
   }
 }
 
 }  // namespace content