[NOT FOR LANDING] Detailed loading traces

net/http/http_cache_transaction.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/http/http_cache_transaction.h"
 
 #include "build/build_config.h"  // For OS_POSIX
 
 #if defined(OS_POSIX)
 #include <unistd.h>
 #endif
 
 #include <algorithm>
 #include <string>
 
+#include "base/trace_event/trace_event.h"
 #include "base/bind.h"
 #include "base/callback_helpers.h"
 #include "base/compiler_specific.h"
 #include "base/format_macros.h"
 #include "base/location.h"
 #include "base/macros.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/metrics/sparse_histogram.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/string_number_conversions.h"  // For HexEncode.
@@ skipping 146 matching lines @@
       weak_factory_(this) {
   static_assert(HttpCache::Transaction::kNumValidationHeaders ==
                     arraysize(kValidationHeaders),
                 "invalid number of validation headers");
 
   io_callback_ = base::Bind(&Transaction::OnIOComplete,
                               weak_factory_.GetWeakPtr());
 }
 
 HttpCache::Transaction::~Transaction() {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::~Transaction");
+
   // We may have to issue another IO, but we should never invoke the callback_
   // after this point.
   callback_.Reset();
 
   if (cache_) {
     if (entry_) {
       bool cancel_request = reading_ && response_.headers.get();
       if (cancel_request) {
         if (partial_) {
           entry_->disk_entry->CancelSparseIO();
@@ skipping 668 matching lines @@
 
   if (rv != ERR_IO_PENDING && !callback_.is_null()) {
     read_buf_ = NULL;  // Release the buffer before invoking the callback.
     base::ResetAndReturn(&callback_).Run(rv);
   }
 
   return rv;
 }
 
 int HttpCache::Transaction::DoGetBackend() {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoGetBackend");
   cache_pending_ = true;
   next_state_ = STATE_GET_BACKEND_COMPLETE;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_GET_BACKEND);
   return cache_->GetBackendForTransaction(this);
 }
 
 int HttpCache::Transaction::DoGetBackendComplete(int result) {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoGetBackendComplete");
   DCHECK(result == OK || result == ERR_FAILED);
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_GET_BACKEND,
                                     result);
   cache_pending_ = false;
 
   if (!ShouldPassThrough()) {
     cache_key_ = cache_->GenerateCacheKey(request_);
 
     // Requested cache access mode.
     if (effective_load_flags_ & LOAD_ONLY_FROM_CACHE) {
@@ skipping 45 matching lines @@
     next_state_ = STATE_INIT_ENTRY;
   }
 
   // This is only set if we have something to do with the response.
   range_requested_ = (partial_.get() != NULL);
 
   return OK;
 }
 
 int HttpCache::Transaction::DoInitEntry() {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoInitEntry");
   DCHECK(!new_entry_);
 
   if (!cache_.get())
     return ERR_UNEXPECTED;
 
   if (mode_ == WRITE) {
     next_state_ = STATE_DOOM_ENTRY;
     return OK;
   }
 
   next_state_ = STATE_OPEN_ENTRY;
   return OK;
 }
 
 int HttpCache::Transaction::DoOpenEntry() {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoOpenEntry");
   DCHECK(!new_entry_);
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY);
   first_cache_access_since_ = TimeTicks::Now();
   return cache_->OpenEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoOpenEntryComplete(int result) {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoOpenEntryComplete");
   // It is important that we go to STATE_ADD_TO_ENTRY whenever the result is
   // OK, otherwise the cache will end up with an active entry without any
   // transaction attached.
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, result);
   cache_pending_ = false;
   if (result == OK) {
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
 
@@ skipping 77 matching lines @@
       DLOG(WARNING) << "Unable to create cache entry";
       mode_ = NONE;
       if (partial_)
         partial_->RestoreHeaders(&custom_request_->extra_headers);
       next_state_ = STATE_SEND_REQUEST;
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoAddToEntry() {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoAddToEntry");
   DCHECK(new_entry_);
   cache_pending_ = true;
   next_state_ = STATE_ADD_TO_ENTRY_COMPLETE;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY);
   DCHECK(entry_lock_waiting_since_.is_null());
   entry_lock_waiting_since_ = TimeTicks::Now();
   int rv = cache_->AddTransactionToEntry(new_entry_, this);
   if (rv == ERR_IO_PENDING) {
     if (bypass_lock_for_test_) {
       OnAddToEntryTimeout(entry_lock_waiting_since_);
@@ skipping 21 matching lines @@
           FROM_HERE,
           base::Bind(&HttpCache::Transaction::OnAddToEntryTimeout,
                      weak_factory_.GetWeakPtr(), entry_lock_waiting_since_),
           TimeDelta::FromMilliseconds(timeout_milliseconds));
     }
   }
   return rv;
 }
 
 int HttpCache::Transaction::DoAddToEntryComplete(int result) {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoAddToEntryComplete");
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY,
                                     result);
   const TimeDelta entry_lock_wait =
       TimeTicks::Now() - entry_lock_waiting_since_;
   UMA_HISTOGRAM_TIMES("HttpCache.EntryLockWait", entry_lock_wait);
 
   entry_lock_waiting_since_ = TimeTicks();
   DCHECK(new_entry_);
   cache_pending_ = false;
 
@@ skipping 30 matching lines @@
     next_state_ = STATE_SEND_REQUEST;
   } else {
     // We have to read the headers from the cached entry.
     DCHECK(mode_ & READ_META);
     next_state_ = STATE_CACHE_READ_RESPONSE;
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheReadResponse() {
+  TRACE_EVENT0("toplevel", "HttpCache::Transaction::DoCacheReadResponse");
   DCHECK(entry_);
   next_state_ = STATE_CACHE_READ_RESPONSE_COMPLETE;
 
   io_buf_len_ = entry_->disk_entry->GetDataSize(kResponseInfoIndex);
   read_buf_ = new IOBuffer(io_buf_len_);
 
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO);
   return entry_->disk_entry->ReadData(kResponseInfoIndex, 0, read_buf_.get(),
                                       io_buf_len_, io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
+  TRACE_EVENT0("toplevel",
+               "HttpCache::Transaction::DoCacheReadResponseComplete");
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != io_buf_len_ ||
       !HttpCache::ParseResponseInfo(read_buf_->data(), io_buf_len_, &response_,
                                     &truncated_)) {
     return OnCacheReadError(result, true);
   }
 
   // Some resources may have slipped in as truncated when they're not.
   int current_size = entry_->disk_entry->GetDataSize(kResponseContentIndex);
   if (response_.headers->GetContentLength() == current_size)
@@ skipping 1598 matching lines @@
     default:
       NOTREACHED();
   }
 }
 
 void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
 }  // namespace net