[NOT FOR LANDING] Detailed loading traces

content/browser/loader/resource_dispatcher_host_impl.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.
 
 // See http://dev.chromium.org/developers/design-documents/multi-process-resource-loading
 
 #include "content/browser/loader/resource_dispatcher_host_impl.h"
 
 #include <stddef.h>
 #include <algorithm>
@@ skipping 968 matching lines @@
       GetCertID(loader->request(), info->GetChildID()),
       new_url));
   BrowserThread::PostTask(
       BrowserThread::UI, FROM_HERE,
       base::Bind(
           &NotifyRedirectOnUI,
           render_process_id, render_frame_host, base::Passed(&detail)));
 }
 
 void ResourceDispatcherHostImpl::DidReceiveResponse(ResourceLoader* loader) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::DidReceiveResponse");
+
   ResourceRequestInfoImpl* info = loader->GetRequestInfo();
   net::URLRequest* request = loader->request();
   if (request->was_fetched_via_proxy() &&
       request->was_fetched_via_spdy() &&
       request->url().SchemeIs(url::kHttpScheme)) {
     scheduler_->OnReceivedSpdyProxiedHttpResponse(
         info->GetChildID(), info->GetRouteID());
   }
 
   if (request->response_info().async_revalidation_required) {
@@ skipping 16 matching lines @@
   scoped_ptr<ResourceRequestDetails> detail(new ResourceRequestDetails(
       request, GetCertID(request, info->GetChildID())));
   BrowserThread::PostTask(
       BrowserThread::UI, FROM_HERE,
       base::Bind(
           &NotifyResponseOnUI,
           render_process_id, render_frame_host, base::Passed(&detail)));
 }
 
 void ResourceDispatcherHostImpl::DidFinishLoading(ResourceLoader* loader) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::DidFinishLoading");
   ResourceRequestInfoImpl* info = loader->GetRequestInfo();
 
   // Record final result of all resource loads.
   if (info->GetResourceType() == RESOURCE_TYPE_MAIN_FRAME) {
     // This enumeration has "3" appended to its name to distinguish it from
     // older versions.
     UMA_HISTOGRAM_SPARSE_SLOWLY(
         "Net.ErrorCodesForMainFrame3",
         -loader->request()->status().error());
 
@@ skipping 91 matching lines @@
     UMA_HISTOGRAM_SPARSE_SLOWLY(
         "Net.ErrorCodesForSubresources2",
         -loader->request()->status().error());
   }
 
   if (loader->request()->url().SchemeIsCryptographic()) {
     RecordCertificateHistograms(loader->request()->ssl_info(),
                                 info->GetResourceType());
   }
 
-  if (delegate_)
+  if (delegate_) {
+    TRACE_EVENT0("toplevel", "ResourceDispatcherHostDelegate::RequestComplete");
+
     delegate_->RequestComplete(loader->request());
+  }
 
   // Destroy the ResourceLoader.
   RemovePendingRequest(info->GetChildID(), info->GetRequestID());
 }
 
 void ResourceDispatcherHostImpl::OnInit() {
   scheduler_.reset(new ResourceScheduler);
 }
 
 void ResourceDispatcherHostImpl::OnShutdown() {
@@ skipping 62 matching lines @@
   }
 
   filter_ = NULL;
   return handled;
 }
 
 void ResourceDispatcherHostImpl::OnRequestResource(
     int routing_id,
     int request_id,
     const ResourceHostMsg_Request& request_data) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::OnRequestResource");
+
   // TODO(pkasting): Remove ScopedTracker below once crbug.com/477117 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "477117 ResourceDispatcherHostImpl::OnRequestResource"));
   // When logging time-to-network only care about main frame and non-transfer
   // navigations.
   // PlzNavigate: this log happens from NavigationRequest::OnRequestStarted
   // instead.
   if (request_data.resource_type == RESOURCE_TYPE_MAIN_FRAME &&
       request_data.transferred_request_request_id == -1 &&
@@ skipping 124 matching lines @@
 
   // We should have a CrossSiteResourceHandler to finish the transfer.
   DCHECK(info->cross_site_handler());
 }
 
 void ResourceDispatcherHostImpl::BeginRequest(
     int request_id,
     const ResourceHostMsg_Request& request_data,
     IPC::Message* sync_result,  // only valid for sync
     int route_id) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::BeginRequest");
   int process_type = filter_->process_type();
   int child_id = filter_->child_id();
 
   // Reject request id that's currently in use.
   if (IsRequestIDInUse(GlobalRequestID(child_id, request_id))) {
     bad_message::ReceivedBadMessage(filter_,
                                     bad_message::RDH_INVALID_REQUEST_ID);
     return;
   }
 
@@ skipping 53 matching lines @@
   headers.AddHeadersFromString(request_data.headers);
 
   if (is_shutdown_ ||
       !ShouldServiceRequest(process_type, child_id, request_data, headers,
                             filter_, resource_context)) {
     AbortRequestBeforeItStarts(filter_, sync_result, request_id);
     return;
   }
 
   // Allow the observer to block/handle the request.
-  if (delegate_ && !delegate_->ShouldBeginRequest(request_data.method,
-                                                  request_data.url,
-                                                  request_data.resource_type,
-                                                  resource_context)) {
-    AbortRequestBeforeItStarts(filter_, sync_result, request_id);
-    return;
+  {
+    TRACE_EVENT0("toplevel",
+                 "ResourceDispatcherHostDelegate::ShouldBeginRequest");
+
+    if (delegate_ &&
+        !delegate_->ShouldBeginRequest(request_data.method, request_data.url,
+                                       request_data.resource_type,
+                                       resource_context)) {
+      AbortRequestBeforeItStarts(filter_, sync_result, request_id);
+      return;
+    }
   }
-
-  // Construct the request.
   scoped_ptr<net::URLRequest> new_request = request_context->CreateRequest(
       is_navigation_stream_request ? request_data.resource_body_stream_url
                                    : request_data.url,
       request_data.priority, nullptr);
 
   // PlzNavigate: Always set the method to GET when gaining access to the
   // stream that contains the response body of a navigation. Otherwise the data
   // that was already fetched by the browser will not be transmitted to the
   // renderer.
   if (is_navigation_stream_request)
@@ skipping 15 matching lines @@
   if (request_data.resource_type == RESOURCE_TYPE_MAIN_FRAME) {
     new_request->set_first_party_url_policy(
         net::URLRequest::UPDATE_FIRST_PARTY_URL_ON_REDIRECT);
   }
 
   const Referrer referrer(request_data.referrer, request_data.referrer_policy);
   SetReferrerForRequest(new_request.get(), referrer);
 
   new_request->SetExtraRequestHeaders(headers);
 
-  storage::BlobStorageContext* blob_context =
-      GetBlobStorageContext(filter_->blob_storage_context());
+  storage::BlobStorageContext* blob_context;
+  {
+    TRACE_EVENT0("toplevel", "GetBlobStorageContext");
+    blob_context = GetBlobStorageContext(filter_->blob_storage_context());
+  }
   // Resolve elements from request_body and prepare upload data.
   if (request_data.request_body.get()) {
     // |blob_context| could be null when the request is from the plugins because
     // ResourceMessageFilters created in PluginProcessHost don't have the blob
     // context.
     if (blob_context) {
       // Attaches the BlobDataHandles to request_body not to free the blobs and
       // any attached shareable files until upload completion. These data will
       // be used in UploadDataStream and ServiceWorkerURLRequestJob.
+      TRACE_EVENT0("toplevel",
+                   "ResourceDispatcherHostImpl::BeginRequest::"
+                   "AttachRequestBodyBlobDataHandles");
       AttachRequestBodyBlobDataHandles(
           request_data.request_body.get(),
           blob_context);
     }
     new_request->set_upload(UploadDataStreamBuilder::Build(
         request_data.request_body.get(),
         blob_context,
         filter_->file_system_context(),
         BrowserThread::GetMessageLoopProxyForThread(BrowserThread::FILE)
             .get()));
@@ skipping 126 matching lines @@
 }
 
 scoped_ptr<ResourceHandler> ResourceDispatcherHostImpl::CreateResourceHandler(
     net::URLRequest* request,
     const ResourceHostMsg_Request& request_data,
     IPC::Message* sync_result,
     int route_id,
     int process_type,
     int child_id,
     ResourceContext* resource_context) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::CreateResourceHandler");
+
   // TODO(pkasting): Remove ScopedTracker below once crbug.com/456331 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "456331 ResourceDispatcherHostImpl::CreateResourceHandler"));
   // Construct the IPC resource handler.
   scoped_ptr<ResourceHandler> handler;
   if (sync_result) {
     // download_to_file is not supported for synchronous requests.
     if (request_data.download_to_file) {
       bad_message::ReceivedBadMessage(filter_, bad_message::RDH_BAD_DOWNLOAD);
@@ skipping 47 matching lines @@
 }
 
 scoped_ptr<ResourceHandler> ResourceDispatcherHostImpl::AddStandardHandlers(
     net::URLRequest* request,
     ResourceType resource_type,
     ResourceContext* resource_context,
     AppCacheService* appcache_service,
     int child_id,
     int route_id,
     scoped_ptr<ResourceHandler> handler) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::AddStandardHandlers");
   // PlzNavigate: do not add ResourceThrottles for main resource requests from
   // the renderer.  Decisions about the navigation should have been done in the
   // initial request.
   if (IsBrowserSideNavigationEnabled() && IsResourceTypeFrame(resource_type) &&
       child_id != -1) {
     DCHECK(request->url().SchemeIs(url::kBlobScheme));
     return handler;
   }
 
   PluginService* plugin_service = nullptr;
@@ skipping 337 matching lines @@
     }
     for (const GlobalFrameRoutingId& route_id : routing_ids) {
       CancelBlockedRequestsForRoute(route_id);
     }
   }
 }
 
 // Cancels the request and removes it from the list.
 void ResourceDispatcherHostImpl::RemovePendingRequest(int child_id,
                                                       int request_id) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::RemovePendingRequest");
+
   LoaderMap::iterator i = pending_loaders_.find(
       GlobalRequestID(child_id, request_id));
   if (i == pending_loaders_.end()) {
     NOTREACHED() << "Trying to remove a request that's not here";
     return;
   }
   RemovePendingLoader(i);
 }
 
 void ResourceDispatcherHostImpl::RemovePendingLoader(
     const LoaderMap::iterator& iter) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::RemovePendingLoader");
+
   ResourceRequestInfoImpl* info = iter->second->GetRequestInfo();
 
   // Remove the memory credit that we added when pushing the request onto
   // the pending list.
   IncrementOutstandingRequestsMemory(-1, *info);
-
-  pending_loaders_.erase(iter);
+  {
+    TRACE_EVENT0("toplevel",
+                 "ResourceDispatcherHostImpl::RemovePendingLoader::Erase");
+    pending_loaders_.erase(iter);
+  }
 }
 
 void ResourceDispatcherHostImpl::CancelRequest(int child_id,
                                                int request_id) {
   ResourceLoader* loader = GetLoader(child_id, request_id);
   if (!loader) {
     // We probably want to remove this warning eventually, but I wanted to be
     // able to notice when this happens during initial development since it
     // should be rare and may indicate a bug.
     DVLOG(1) << "Canceling a request that wasn't found";
@@ skipping 20 matching lines @@
   if (stats.memory_cost == 0 && stats.num_requests == 0)
     outstanding_requests_stats_map_.erase(info.GetChildID());
   else
     outstanding_requests_stats_map_[info.GetChildID()] = stats;
 }
 
 ResourceDispatcherHostImpl::OustandingRequestsStats
 ResourceDispatcherHostImpl::IncrementOutstandingRequestsMemory(
     int count,
     const ResourceRequestInfoImpl& info) {
+  TRACE_EVENT0(
+      "toplevel",
+      "ResourceDispatcherHostImpl::IncrementOutstandingRequestsMemory");
+
   DCHECK_EQ(1, abs(count));
 
   // Retrieve the previous value (defaulting to 0 if not found).
   OustandingRequestsStats stats = GetOutstandingRequestsStats(info);
 
   // Insert/update the total; delete entries when their count reaches 0.
   stats.memory_cost += count * info.memory_cost();
   DCHECK_GE(stats.memory_cost, 0);
   UpdateOutstandingRequestsStats(info, stats);
 
@@ skipping 16 matching lines @@
   OustandingRequestsStats stats = GetOutstandingRequestsStats(*info);
   stats.num_requests += count;
   DCHECK_GE(stats.num_requests, 0);
   UpdateOutstandingRequestsStats(*info, stats);
 
   return stats;
 }
 
 bool ResourceDispatcherHostImpl::HasSufficientResourcesForRequest(
     net::URLRequest* request) {
+  TRACE_EVENT0("toplevel",
+               "ResourceDispatcherHostImpl::HasSufficientResourcesForRequest");
+
   ResourceRequestInfoImpl* info = ResourceRequestInfoImpl::ForRequest(request);
   OustandingRequestsStats stats = IncrementOutstandingRequestsCount(1, info);
 
   if (stats.num_requests > max_num_in_flight_requests_per_process_)
     return false;
   if (num_in_flight_requests_ > max_num_in_flight_requests_)
     return false;
 
   return true;
 }
@@ skipping 187 matching lines @@
                      request->method().size();
 
   // Note that this expression will typically be dominated by:
   // |kAvgBytesPerOutstandingRequest|.
   return kAvgBytesPerOutstandingRequest + strings_cost;
 }
 
 void ResourceDispatcherHostImpl::BeginRequestInternal(
     scoped_ptr<net::URLRequest> request,
     scoped_ptr<ResourceHandler> handler) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::BeginRequestInternal");
   DCHECK(!request->is_pending());
   ResourceRequestInfoImpl* info =
       ResourceRequestInfoImpl::ForRequest(request.get());
 
   if ((TimeTicks::Now() - last_user_gesture_time_) <
       TimeDelta::FromMilliseconds(kUserGestureWindowMs)) {
     request->SetLoadFlags(
         request->load_flags() | net::LOAD_MAYBE_USER_GESTURE);
   }
 
@@ skipping 32 matching lines @@
     iter->second->push_back(std::move(loader));
     return;
   }
 
   StartLoading(info, std::move(loader));
 }
 
 void ResourceDispatcherHostImpl::StartLoading(
     ResourceRequestInfoImpl* info,
     scoped_ptr<ResourceLoader> loader) {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::StartLoading");
   // TODO(pkasting): Remove ScopedTracker below once crbug.com/456331 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "456331 ResourceDispatcherHostImpl::StartLoading"));
 
   ResourceLoader* loader_ptr = loader.get();
   pending_loaders_[info->GetGlobalRequestID()] = std::move(loader);
 
   loader_ptr->StartRequest();
 }
@@ skipping 210 matching lines @@
   if (!it->second->might_have_observers()) {
     delete it->second;
     delegate_map_.erase(it);
   }
 }
 
 int ResourceDispatcherHostImpl::BuildLoadFlagsForRequest(
     const ResourceHostMsg_Request& request_data,
     int child_id,
     bool is_sync_load) {
+  TRACE_EVENT0(
+      "toplevel",
+      "ResourceDispatcherHostImpl::BeginRequest::BuildLoadFlagsForRequest");
   int load_flags = request_data.load_flags;
 
   // Although EV status is irrelevant to sub-frames and sub-resources, we have
   // to perform EV certificate verification on all resources because an HTTP
   // keep-alive connection created to load a sub-frame or a sub-resource could
   // be reused to load a main frame.
   load_flags |= net::LOAD_VERIFY_EV_CERT;
   if (request_data.resource_type == RESOURCE_TYPE_MAIN_FRAME) {
     load_flags |= net::LOAD_MAIN_FRAME;
   } else if (request_data.resource_type == RESOURCE_TYPE_PREFETCH) {
     load_flags |= net::LOAD_PREFETCH;
   }
 
   if (is_sync_load)
     load_flags |= net::LOAD_IGNORE_LIMITS;
 
   return load_flags;
 }
 
 }  // namespace content