[NOT FOR LANDING] Detailed loading traces

net/url_request/url_request_http_job.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_http_job.h"
 
+#include "base/trace_event/trace_event.h"
 #include "base/base_switches.h"
 #include "base/bind.h"
 #include "base/bind_helpers.h"
 #include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/file_version_info.h"
 #include "base/location.h"
 #include "base/macros.h"
 #include "base/metrics/field_trial.h"
 #include "base/metrics/histogram_macros.h"
@@ skipping 218 matching lines @@
   DoneWithRequest(ABORTED);
 }
 
 void URLRequestHttpJob::SetPriority(RequestPriority priority) {
   priority_ = priority;
   if (transaction_)
     transaction_->SetPriority(priority_);
 }
 
 void URLRequestHttpJob::Start() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::Start");
   // TODO(mmenke): Remove ScopedTracker below once crbug.com/456327 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION("456327 URLRequestHttpJob::Start"));
 
   DCHECK(!transaction_.get());
 
   // URLRequest::SetReferrer ensures that we do not send username and password
   // fields in the referrer.
   GURL referrer(request_->referrer());
 
@@ skipping 26 matching lines @@
   request_info_.extra_headers.SetHeaderIfMissing(
       HttpRequestHeaders::kUserAgent,
       http_user_agent_settings_ ?
           http_user_agent_settings_->GetUserAgent() : std::string());
 
   AddExtraHeaders();
   AddCookieHeaderAndStart();
 }
 
 void URLRequestHttpJob::Kill() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::Kill");
   weak_factory_.InvalidateWeakPtrs();
   if (transaction_)
     DestroyTransaction();
   URLRequestJob::Kill();
 }
 
 void URLRequestHttpJob::GetConnectionAttempts(ConnectionAttempts* out) const {
   if (transaction_)
     transaction_->GetConnectionAttempts(out);
   else
     out->clear();
 }
 
 void URLRequestHttpJob::NotifyBeforeSendProxyHeadersCallback(
     const ProxyInfo& proxy_info,
     HttpRequestHeaders* request_headers) {
   DCHECK(request_headers);
   DCHECK_NE(URLRequestStatus::CANCELED, GetStatus().status());
   if (network_delegate()) {
     network_delegate()->NotifyBeforeSendProxyHeaders(
         request_,
         proxy_info,
         request_headers);
   }
 }
 
 void URLRequestHttpJob::NotifyBeforeNetworkStart(bool* defer) {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::NotifyBeforeNetworkStart");
   if (!request_)
     return;
   if (backoff_manager_) {
     if ((request_->load_flags() & LOAD_MAYBE_USER_GESTURE) == 0 &&
         backoff_manager_->ShouldRejectRequest(request()->url(),
                                               request()->request_time())) {
       *defer = true;
       base::MessageLoop::current()->PostTask(
           FROM_HERE,
           base::Bind(&URLRequestHttpJob::OnStartCompleted,
                      weak_factory_.GetWeakPtr(), ERR_TEMPORARY_BACKOFF));
       return;
     }
   }
   URLRequestJob::NotifyBeforeNetworkStart(defer);
 }
 
 void URLRequestHttpJob::NotifyHeadersComplete() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::NotifyHeadersComplete");
   DCHECK(!response_info_);
 
   response_info_ = transaction_->GetResponseInfo();
 
   // Save boolean, as we'll need this info at destruction time, and filters may
   // also need this info.
   is_cached_content_ = response_info_->was_cached;
 
   if (!is_cached_content_ && throttling_entry_.get())
     throttling_entry_->UpdateWithResponse(GetResponseCode());
@@ skipping 74 matching lines @@
     // where OnBeforeSendHeaders -> OnSendHeaders -> OnBeforeSendHeaders
     // occurs.
     RestartTransactionWithAuth(AuthCredentials());
     return;
   }
 
   URLRequestJob::NotifyHeadersComplete();
 }
 
 void URLRequestHttpJob::DestroyTransaction() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::DestroyTransaction");
+
   DCHECK(transaction_.get());
 
   DoneWithRequest(ABORTED);
 
   total_received_bytes_from_previous_transactions_ +=
       transaction_->GetTotalReceivedBytes();
   total_sent_bytes_from_previous_transactions_ +=
       transaction_->GetTotalSentBytes();
-  transaction_.reset();
+  {
+    TRACE_EVENT0("toplevel",
+                 "URLRequestHttpJob::DestroyTransaction::ResetHttpTransaction");
+    transaction_.reset();
+  }
   response_info_ = NULL;
   receive_headers_end_ = base::TimeTicks();
 }
 
 void URLRequestHttpJob::StartTransaction() {
   // TODO(mmenke): Remove ScopedTracker below once crbug.com/456327 is fixed.
   tracked_objects::ScopedTracker tracking_profile(
       FROM_HERE_WITH_EXPLICIT_FUNCTION(
           "456327 URLRequestHttpJob::StartTransaction"));
 
@@ skipping 30 matching lines @@
     StartTransactionInternal();
   } else {
     std::string source("delegate");
     request_->net_log().AddEvent(NetLog::TYPE_CANCELLED,
                                  NetLog::StringCallback("source", &source));
     NotifyStartError(URLRequestStatus(URLRequestStatus::FAILED, result));
   }
 }
 
 void URLRequestHttpJob::StartTransactionInternal() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::StartTransactionInternal");
   // This should only be called while the request's status is IO_PENDING.
   DCHECK_EQ(URLRequestStatus::IO_PENDING, request_->status().status());
 
   // NOTE: This method assumes that request_info_ is already setup properly.
 
   // If we already have a transaction, then we should restart the transaction
   // with auth provided by auth_credentials_.
 
   bool invalid_header_values_in_rfc7230 = false;
   for (HttpRequestHeaders::Iterator it(request_info_.extra_headers);
@@ skipping 155 matching lines @@
         http_user_agent_settings_->GetAcceptLanguage();
     if (!accept_language.empty()) {
       request_info_.extra_headers.SetHeaderIfMissing(
           HttpRequestHeaders::kAcceptLanguage,
           accept_language);
     }
   }
 }
 
 void URLRequestHttpJob::AddCookieHeaderAndStart() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::AddCookieHeaderAndStart");
+
   // If the request was destroyed, then there is no more work to do.
   if (!request_)
     return;
 
   CookieStore* cookie_store = request_->context()->cookie_store();
   if (cookie_store && !(request_info_.load_flags & LOAD_DO_NOT_SEND_COOKIES)) {
     CookieOptions options;
     options.set_include_httponly();
 
     // TODO(mkwst): If same-site cookies aren't enabled, pretend the request is
@@ skipping 24 matching lines @@
   if (cookie_list.size() && CanGetCookies(cookie_list)) {
     request_info_.extra_headers.SetHeader(
         HttpRequestHeaders::kCookie, CookieStore::BuildCookieLine(cookie_list));
     // Disable privacy mode as we are sending cookies anyway.
     request_info_.privacy_mode = PRIVACY_MODE_DISABLED;
   }
   DoStartTransaction();
 }
 
 void URLRequestHttpJob::DoStartTransaction() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::DoStartTransaction");
   // We may have been canceled while retrieving cookies.
   if (GetStatus().is_success()) {
     StartTransaction();
   } else {
     NotifyCanceled();
   }
 }
 
 void URLRequestHttpJob::SaveCookiesAndNotifyHeadersComplete(int result) {
+  TRACE_EVENT0("toplevel",
+               "URLRequestHttpJob::SaveCookiesAndNotifyHeadersComplete");
   // End of the call started in OnStartCompleted.
   OnCallToDelegateComplete();
 
   if (result != OK) {
     std::string source("delegate");
     request_->net_log().AddEvent(NetLog::TYPE_CANCELLED,
                                  NetLog::StringCallback("source", &source));
     NotifyStartError(URLRequestStatus(URLRequestStatus::FAILED, result));
     return;
   }
@@ skipping 117 matching lines @@
   if (headers->EnumerateHeader(nullptr, "Public-Key-Pins", &value))
     security_state->AddHPKPHeader(request_info_.url.host(), value, ssl_info);
   if (headers->EnumerateHeader(nullptr, "Public-Key-Pins-Report-Only",
                                &value)) {
     security_state->ProcessHPKPReportOnlyHeader(
         value, HostPortPair::FromURL(request_info_.url), ssl_info);
   }
 }
 
 void URLRequestHttpJob::OnStartCompleted(int result) {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::OnStartCompleted");
   RecordTimer();
 
   // If the request was destroyed, then there is no more work to do.
   if (!request_)
     return;
 
   // If the job is done (due to cancellation), can just ignore this
   // notification.
   if (done_)
     return;
@@ skipping 75 matching lines @@
   } else {
     // Even on an error, there may be useful information in the response
     // info (e.g. whether there's a cached copy).
     if (transaction_.get())
       response_info_ = transaction_->GetResponseInfo();
     NotifyStartError(URLRequestStatus(URLRequestStatus::FAILED, result));
   }
 }
 
 void URLRequestHttpJob::OnHeadersReceivedCallback(int result) {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::OnHeadersReceivedCallback");
   awaiting_callback_ = false;
 
   // Check that there are no callbacks to already canceled requests.
   DCHECK_NE(URLRequestStatus::CANCELED, GetStatus().status());
 
   SaveCookiesAndNotifyHeadersComplete(result);
 }
 
 void URLRequestHttpJob::OnReadCompleted(int result) {
   read_in_progress_ = false;
@@ skipping 222 matching lines @@
     proxy_auth_state_ = AUTH_STATE_HAVE_AUTH;
   } else {
     DCHECK_EQ(server_auth_state_, AUTH_STATE_NEED_AUTH);
     server_auth_state_ = AUTH_STATE_HAVE_AUTH;
   }
 
   RestartTransactionWithAuth(credentials);
 }
 
 void URLRequestHttpJob::CancelAuth() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::CancelAuth");
   // Proxy gets set first, then WWW.
   if (proxy_auth_state_ == AUTH_STATE_NEED_AUTH) {
     proxy_auth_state_ = AUTH_STATE_CANCELED;
   } else {
     DCHECK_EQ(server_auth_state_, AUTH_STATE_NEED_AUTH);
     server_auth_state_ = AUTH_STATE_CANCELED;
   }
 
   // These will be reset in OnStartCompleted.
   response_info_ = NULL;
@@ skipping 10 matching lines @@
   // We have to do this via InvokeLater to avoid "recursing" the consumer.
   //
   base::ThreadTaskRunnerHandle::Get()->PostTask(
       FROM_HERE, base::Bind(&URLRequestHttpJob::OnStartCompleted,
                             weak_factory_.GetWeakPtr(), OK));
 }
 
 void URLRequestHttpJob::ContinueWithCertificate(
     X509Certificate* client_cert,
     SSLPrivateKey* client_private_key) {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::ContinueWithCertificate");
   DCHECK(transaction_.get());
 
   DCHECK(!response_info_) << "should not have a response yet";
   receive_headers_end_ = base::TimeTicks();
 
   ResetTimer();
 
   int rv = transaction_->RestartWithCertificate(client_cert, client_private_key,
                                                 start_callback_);
   if (rv == ERR_IO_PENDING)
     return;
 
   // The transaction started synchronously, but we need to notify the
   // URLRequest delegate via the message loop.
   base::ThreadTaskRunnerHandle::Get()->PostTask(
       FROM_HERE, base::Bind(&URLRequestHttpJob::OnStartCompleted,
                             weak_factory_.GetWeakPtr(), rv));
 }
 
 void URLRequestHttpJob::ContinueDespiteLastError() {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::ContinueDespiteLastError");
   // If the transaction was destroyed, then the job was cancelled.
   if (!transaction_.get())
     return;
 
   DCHECK(!response_info_) << "should not have a response yet";
   receive_headers_end_ = base::TimeTicks();
 
   ResetTimer();
 
   int rv = transaction_->RestartIgnoringLastError(start_callback_);
@@ skipping 241 matching lines @@
   }
 
   if (request_info_.load_flags & LOAD_PREFETCH && !request_->was_cached())
     UMA_HISTOGRAM_COUNTS("Net.Prefetch.PrefilterBytesReadFromNetwork",
                          prefilter_bytes_read());
 
   start_time_ = base::TimeTicks();
 }
 
 void URLRequestHttpJob::DoneWithRequest(CompletionCause reason) {
+  TRACE_EVENT0("toplevel", "URLRequestHttpJob::DoneWithRequest");
   if (done_)
     return;
   done_ = true;
 
   // Notify NetworkQualityEstimator.
   if (request() && (reason == FINISHED || reason == ABORTED)) {
     NetworkQualityEstimator* network_quality_estimator =
         request()->context()->network_quality_estimator();
     if (network_quality_estimator)
       network_quality_estimator->NotifyRequestCompleted(*request());
@@ skipping 10 matching lines @@
   return override_response_headers_.get() ?
              override_response_headers_.get() :
              transaction_->GetResponseInfo()->headers.get();
 }
 
 void URLRequestHttpJob::NotifyURLRequestDestroyed() {
   awaiting_callback_ = false;
 }
 
 }  // namespace net