[NOT FOR LANDING] Detailed loading traces

content/browser/loader/resource_loader.cc

Index: content/browser/loader/resource_loader.cc
diff --git a/content/browser/loader/resource_loader.cc b/content/browser/loader/resource_loader.cc
index eee044c6aaf87a0119371de0a8722a239657692f..07df183cf030ca5a7411406c0ba2e37abcdcc4b6 100644
--- a/content/browser/loader/resource_loader.cc
+++ b/content/browser/loader/resource_loader.cc
@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "base/command_line.h"
 #include "base/location.h"
 #include "base/metrics/histogram.h"
@@ -66,6 +67,8 @@ 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 =
@@ -83,6 +86,7 @@ void GetSSLStatusForRequest(const GURL& url,
 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();
@@ -148,26 +152,39 @@ ResourceLoader::ResourceLoader(scoped_ptr<net::URLRequest> request,
 }
 
 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) {
@@ -229,6 +246,7 @@ void ResourceLoader::CompleteTransfer() {
 }
 
 ResourceRequestInfoImpl* ResourceLoader::GetRequestInfo() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::GetRequestInfo");
   return ResourceRequestInfoImpl::ForRequest(request_.get());
 }
 
@@ -336,6 +354,7 @@ void ResourceLoader::OnBeforeNetworkStart(net::URLRequest* unused,
 }
 
 void ResourceLoader::OnResponseStarted(net::URLRequest* unused) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::OnResponseStarted");
   DCHECK_EQ(request_.get(), unused);
 
   DVLOG(1) << "OnResponseStarted: " << request_->url().spec();
@@ -357,6 +376,7 @@ void ResourceLoader::OnResponseStarted(net::URLRequest* unused) {
 }
 
 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;
@@ -477,6 +497,7 @@ void ResourceLoader::Cancel() {
 }
 
 void ResourceLoader::StartRequestInternal() {
+  TRACE_EVENT0("toplevel", "ResourceDispatcherHostImpl::StartRequestInternal");
   DCHECK(!request_->is_pending());
 
   if (!request_->status().is_success()) {
@@ -536,6 +557,7 @@ void ResourceLoader::CancelRequestInternal(int error, bool from_renderer) {
 }
 
 void ResourceLoader::CompleteResponseStarted() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::CompleteResponseStarted");
   ResourceRequestInfoImpl* info = GetRequestInfo();
   scoped_refptr<ResourceResponse> response(new ResourceResponse());
   PopulateResourceResponse(info, request_.get(), response.get());
@@ -547,7 +569,12 @@ void ResourceLoader::CompleteResponseStarted() {
       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();
@@ -556,6 +583,7 @@ void ResourceLoader::CompleteResponseStarted() {
 }
 
 void ResourceLoader::StartReading(bool is_continuation) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::StartReading");
   int bytes_read = 0;
   ReadMore(&bytes_read);
 
@@ -591,6 +619,8 @@ void ResourceLoader::ResumeReading() {
 }
 
 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
@@ -603,9 +633,13 @@ void ResourceLoader::ReadMore(int* bytes_read) {
     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;
+      }
     }
   }
 
@@ -619,6 +653,7 @@ void ResourceLoader::ReadMore(int* bytes_read) {
 }
 
 void ResourceLoader::CompleteRead(int bytes_read) {
+  TRACE_EVENT0("toplevel", "ResourceLoader::CompleteRead");
   DCHECK(bytes_read >= 0);
   DCHECK(request_->status().is_success());
 
@@ -641,6 +676,7 @@ void ResourceLoader::CompleteRead(int bytes_read) {
 }
 
 void ResourceLoader::ResponseCompleted() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::ResponseCompleted");
   DVLOG(1) << "ResponseCompleted: " << request_->url().spec();
   RecordHistograms();
   ResourceRequestInfoImpl* info = GetRequestInfo();
@@ -661,7 +697,10 @@ void ResourceLoader::ResponseCompleted() {
     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
@@ -674,6 +713,7 @@ void ResourceLoader::ResponseCompleted() {
 }
 
 void ResourceLoader::CallDidFinishLoading() {
+  TRACE_EVENT0("toplevel", "ResourceLoader::CallDidFinishLoading");
   delegate_->DidFinishLoading(this);
 }