[NOT FOR LANDING] Detailed loading traces

net/url_request/url_request.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 "net/url_request/url_request.h"
 
 #include <utility>
-
+#include "base/trace_event/trace_event.h"
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/callback.h"
 #include "base/compiler_specific.h"
 #include "base/debug/stack_trace.h"
 #include "base/lazy_instance.h"
 #include "base/memory/singleton.h"
 #include "base/message_loop/message_loop.h"
 #include "base/profiler/scoped_tracker.h"
 #include "base/rand_util.h"
@@ skipping 143 matching lines @@
 }
 
 void URLRequest::Delegate::OnBeforeNetworkStart(URLRequest* request,
                                                 bool* defer) {
 }
 
 ///////////////////////////////////////////////////////////////////////////////
 // URLRequest
 
 URLRequest::~URLRequest() {
+  TRACE_EVENT0("toplevel", "URLRequest::~URLRequest");
   Cancel();
 
   if (network_delegate_) {
+    TRACE_EVENT0("toplevel", "NetworkDelegate::NotifyURLRequestDestroyed");
     network_delegate_->NotifyURLRequestDestroyed(this);
     if (job_.get())
       job_->NotifyURLRequestDestroyed();
   }
 
   if (job_.get())
     OrphanJob();
 
   int deleted = context_->url_requests()->erase(this);
   CHECK_EQ(1, deleted);
@@ skipping 312 matching lines @@
   referrer_policy_ = referrer_policy;
 }
 
 void URLRequest::set_delegate(Delegate* delegate) {
   DCHECK(!delegate_);
   DCHECK(delegate);
   delegate_ = delegate;
 }
 
 void URLRequest::Start() {
+  TRACE_EVENT0("toplevel", "URLRequest::Start");
   DCHECK(delegate_);
 
   // TODO(pkasting): Remove ScopedTracker below once crbug.com/456327 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION("456327 URLRequest::Start"));
 
   // Some values can be NULL, but the job factory must not be.
   DCHECK(context_->job_factory());
 
   // Anything that sets |blocked_by_| before start should have cleaned up after
   // itself.
   DCHECK(blocked_by_.empty());
 
   g_url_requests_started = true;
   response_info_.request_time = base::Time::Now();
 
   load_timing_info_ = LoadTimingInfo();
   load_timing_info_.request_start_time = response_info_.request_time;
   load_timing_info_.request_start = base::TimeTicks::Now();
 
   // Only notify the delegate for the initial request.
   if (network_delegate_) {
     // TODO(mmenke): Remove ScopedTracker below once crbug.com/456327 is fixed.
     tracked_objects::ScopedTracker tracking_profile25(
         FROM_HERE_WITH_EXPLICIT_FUNCTION("456327 URLRequest::Start 2.5"));
 
     OnCallToDelegate();
-    int error = network_delegate_->NotifyBeforeURLRequest(
-        this, before_request_callback_, &delegate_redirect_url_);
+    int error;
+    {
+      TRACE_EVENT0("toplevel", "NetworkDelegate::NotifyBeforeURLRequest");
+      error = network_delegate_->NotifyBeforeURLRequest(
+          this, before_request_callback_, &delegate_redirect_url_);
+    }
     // If ERR_IO_PENDING is returned, the delegate will invoke
     // |before_request_callback_| later.
     if (error != ERR_IO_PENDING)
       BeforeRequestComplete(error);
     return;
   }
 
   // TODO(mmenke): Remove ScopedTracker below once crbug.com/456327 is fixed.
   tracked_objects::ScopedTracker tracking_profile2(
       FROM_HERE_WITH_EXPLICIT_FUNCTION("456327 URLRequest::Start 2"));
@@ skipping 35 matching lines @@
       notified_before_network_start_(false) {
   // Sanity check out environment.
   DCHECK(base::MessageLoop::current())
       << "The current base::MessageLoop must exist";
 
   context->url_requests()->insert(this);
   net_log_.BeginEvent(NetLog::TYPE_REQUEST_ALIVE);
 }
 
 void URLRequest::BeforeRequestComplete(int error) {
+  TRACE_EVENT0("toplevel", "NetworkDelegate::BeforeRequestComplete");
   DCHECK(!job_.get());
   DCHECK_NE(ERR_IO_PENDING, error);
 
   // Check that there are no callbacks to already canceled requests.
   DCHECK_NE(URLRequestStatus::CANCELED, status_.status());
 
   OnCallToDelegateComplete();
 
   if (error != OK) {
     std::string source("delegate");
     net_log_.AddEvent(NetLog::TYPE_CANCELLED,
                       NetLog::StringCallback("source", &source));
     StartJob(new URLRequestErrorJob(this, network_delegate_, error));
   } else if (!delegate_redirect_url_.is_empty()) {
     GURL new_url;
     new_url.Swap(&delegate_redirect_url_);
 
     URLRequestRedirectJob* job = new URLRequestRedirectJob(
         this, network_delegate_, new_url,
         // Use status code 307 to preserve the method, so POST requests work.
         URLRequestRedirectJob::REDIRECT_307_TEMPORARY_REDIRECT, "Delegate");
     StartJob(job);
   } else {
     StartJob(URLRequestJobManager::GetInstance()->CreateJob(
         this, network_delegate_));
   }
 }
 
 void URLRequest::StartJob(URLRequestJob* job) {
+  TRACE_EVENT0("toplevel", "URLRequest::StartJob");
   // TODO(mmenke): Remove ScopedTracker below once crbug.com/456327 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION("456327 URLRequest::StartJob"));
 
   DCHECK(!is_pending_);
   DCHECK(!job_.get());
 
   net_log_.BeginEvent(
       NetLog::TYPE_URL_REQUEST_START_JOB,
       base::Bind(&NetLogURLRequestStartCallback,
@@ skipping 100 matching lines @@
   // Job sends an asynchronous notification but by the time this is processed,
   // our |context_| is NULL.
   NotifyRequestCompleted();
 
   // The Job will call our NotifyDone method asynchronously.  This is done so
   // that the Delegate implementation can call Cancel without having to worry
   // about being called recursively.
 }
 
 bool URLRequest::Read(IOBuffer* dest, int dest_size, int* bytes_read) {
+  TRACE_EVENT0("toplevel", "URLRequest::Read");
+
   DCHECK(job_.get());
   DCHECK(bytes_read);
   *bytes_read = 0;
 
   // If this is the first read, end the delegate call that may have started in
   // OnResponseStarted.
   OnCallToDelegateComplete();
 
   // This handles a cancel that happens while paused.
   // TODO(ahendrickson): DCHECK() that it is not done after
@@ skipping 55 matching lines @@
 
 void URLRequest::ResumeNetworkStart() {
   DCHECK(job_.get());
   DCHECK(notified_before_network_start_);
 
   OnCallToDelegateComplete();
   job_->ResumeNetworkStart();
 }
 
 void URLRequest::NotifyResponseStarted() {
+  TRACE_EVENT0("toplevel", "URLRequest::NotifyResponseStarted");
   int net_error = OK;
   if (!status_.is_success())
     net_error = status_.error();
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_URL_REQUEST_START_JOB,
                                     net_error);
 
   URLRequestJob* job =
       URLRequestJobManager::GetInstance()->MaybeInterceptResponse(
           this, network_delegate_);
   if (job) {
@@ skipping 71 matching lines @@
   load_timing_info_ = LoadTimingInfo();
   load_timing_info_.request_start_time = response_info_.request_time;
   load_timing_info_.request_start = base::TimeTicks::Now();
 
   status_ = URLRequestStatus();
   is_pending_ = false;
   proxy_server_ = HostPortPair();
 }
 
 void URLRequest::OrphanJob() {
+  TRACE_EVENT0("toplevel", "URLRequest::OrphanJob");
   // When calling this function, please check that URLRequestHttpJob is
   // not in between calling NetworkDelegate::NotifyHeadersReceived receiving
   // the call back. This is currently guaranteed by the following strategies:
   // - OrphanJob is called on JobRestart, in this case the URLRequestJob cannot
   //   be receiving any headers at that time.
   // - OrphanJob is called in ~URLRequest, in this case
   //   NetworkDelegate::NotifyURLRequestDestroyed notifies the NetworkDelegate
   //   that the callback becomes invalid.
   job_->Kill();
   job_ = NULL;
@@ skipping 192 matching lines @@
   delegate_->OnCertificateRequested(this, cert_request_info);
 }
 
 void URLRequest::NotifySSLCertificateError(const SSLInfo& ssl_info,
                                            bool fatal) {
   status_ = URLRequestStatus();
   delegate_->OnSSLCertificateError(this, ssl_info, fatal);
 }
 
 bool URLRequest::CanGetCookies(const CookieList& cookie_list) const {
+  TRACE_EVENT0("toplevel", "URLRequest::CanGetCookies");
   DCHECK(!(load_flags_ & LOAD_DO_NOT_SEND_COOKIES));
   if (network_delegate_) {
     return network_delegate_->CanGetCookies(*this, cookie_list);
   }
   return g_default_can_use_cookies;
 }
 
 bool URLRequest::CanSetCookie(const std::string& cookie_line,
                               CookieOptions* options) const {
   DCHECK(!(load_flags_ & LOAD_DO_NOT_SAVE_COOKIES));
@@ skipping 44 matching lines @@
     job_->GetLoadTimingInfo(&load_timing_info_);
 
     load_timing_info_.request_start = request_start;
     load_timing_info_.request_start_time = request_start_time;
 
     ConvertRealLoadTimesToBlockingTimes(&load_timing_info_);
   }
 }
 
 void URLRequest::NotifyRequestCompleted() {
+  TRACE_EVENT0("toplevel", "URLRequest::NotifyRequestCompleted");
   // TODO(battre): Get rid of this check, according to willchan it should
   // not be needed.
   if (has_notified_completion_)
     return;
 
   is_pending_ = false;
   is_redirecting_ = false;
   has_notified_completion_ = true;
   if (network_delegate_)
     network_delegate_->NotifyCompleted(this, job_.get() != NULL);
@@ skipping 24 matching lines @@
 }
 
 void URLRequest::GetConnectionAttempts(ConnectionAttempts* out) const {
   if (job_)
     job_->GetConnectionAttempts(out);
   else
     out->clear();
 }
 
 }  // namespace net