Add traces to HttpCache::Transaction to make it easier to follow URLRequests

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>
@@ skipping 10 matching lines @@
 #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.
 #include "base/strings/string_piece.h"
 #include "base/strings/string_util.h"  // For LowerCaseEqualsASCII.
 #include "base/strings/stringprintf.h"
 #include "base/threading/thread_task_runner_handle.h"
 #include "base/time/clock.h"
+#include "base/trace_event/trace_event.h"
 #include "base/values.h"
 #include "net/base/auth.h"
 #include "net/base/load_flags.h"
 #include "net/base/load_timing_info.h"
 #include "net/base/upload_data_stream.h"
 #include "net/cert/cert_status_flags.h"
 #include "net/cert/x509_certificate.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/http_network_session.h"
 #include "net/http/http_request_info.h"
@@ skipping 141 matching lines @@
       io_buf_len_(0),
       read_offset_(0),
       effective_load_flags_(0),
       write_len_(0),
       cache_entry_status_(CacheEntryStatus::ENTRY_UNDEFINED),
       validation_cause_(VALIDATION_CAUSE_UNDEFINED),
       total_received_bytes_(0),
       total_sent_bytes_(0),
       websocket_handshake_stream_base_create_helper_(NULL),
       weak_factory_(this) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::Transaction");
   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("io", "HttpCacheTransaction::~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 739 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("io", "HttpCacheTransaction::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("io", "HttpCacheTransaction::DoOpenEntry");
   DCHECK(!new_entry_);
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLogEventType::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("io", "HttpCacheTransaction::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(NetLogEventType::HTTP_CACHE_OPEN_ENTRY,
                                     result);
   cache_pending_ = false;
   if (result == OK) {
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
@@ skipping 22 matching lines @@
     next_state_ = STATE_SEND_REQUEST;
     return OK;
   }
 
   // The entry does not exist, and we are not permitted to create a new entry,
   // so we must fail.
   return ERR_CACHE_MISS;
 }
 
 int HttpCache::Transaction::DoDoomEntry() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoDoomEntry");
   next_state_ = STATE_DOOM_ENTRY_COMPLETE;
   cache_pending_ = true;
   if (first_cache_access_since_.is_null())
     first_cache_access_since_ = TimeTicks::Now();
   net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_DOOM_ENTRY);
   return cache_->DoomEntry(cache_key_, this);
 }
 
 int HttpCache::Transaction::DoDoomEntryComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoDoomEntryComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_DOOM_ENTRY,
                                     result);
   next_state_ = STATE_CREATE_ENTRY;
   cache_pending_ = false;
   if (result == ERR_CACHE_RACE)
     next_state_ = STATE_INIT_ENTRY;
   return OK;
 }
 
 int HttpCache::Transaction::DoCreateEntry() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCreateEntry");
   DCHECK(!new_entry_);
   next_state_ = STATE_CREATE_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_CREATE_ENTRY);
   return cache_->CreateEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoCreateEntryComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCreateEntryComplete");
   // 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(NetLogEventType::HTTP_CACHE_CREATE_ENTRY,
                                     result);
   cache_pending_ = false;
   switch (result) {
     case OK:
       next_state_ = STATE_ADD_TO_ENTRY;
       break;
@@ skipping 10 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("io", "HttpCacheTransaction::DoAddToEntry");
   DCHECK(new_entry_);
   cache_pending_ = true;
   next_state_ = STATE_ADD_TO_ENTRY_COMPLETE;
   net_log_.BeginEvent(NetLogEventType::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("io", "HttpCacheTransaction::DoAddToEntryComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::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 32 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("io", "HttpCacheTransaction::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(NetLogEventType::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("io", "HttpCacheTransaction::DoCacheReadResponseComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_READ_INFO,
                                     result);
   if (result != io_buf_len_ ||
       !HttpCache::ParseResponseInfo(read_buf_->data(), io_buf_len_, &response_,
                                     &truncated_)) {
     return OnCacheReadError(result, true);
   }
 
   int current_size = entry_->disk_entry->GetDataSize(kResponseContentIndex);
   int64_t full_response_length = response_.headers->GetContentLength();
@@ skipping 27 matching lines @@
     // valid for this transaction but the bit needs to be flipped in storage.
     next_state_ = STATE_TOGGLE_UNUSED_SINCE_PREFETCH;
     return OK;
   }
 
   next_state_ = STATE_CACHE_DISPATCH_VALIDATION;
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetch() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheToggleUnusedSincePrefetch");
   // Write back the toggled value for the next use of this entry.
   response_.unused_since_prefetch = !response_.unused_since_prefetch;
 
   // TODO(jkarlin): If DoUpdateCachedResponse is also called for this
   // transaction then metadata will be written to cache twice. If prefetching
   // becomes more common, consider combining the writes.
 
   next_state_ = STATE_TOGGLE_UNUSED_SINCE_PREFETCH_COMPLETE;
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetchComplete(
     int result) {
+  TRACE_EVENT0(
+      "net", "HttpCacheTransaction::DoCacheToggleUnusedSincePrefetchComplete");
   // Restore the original value for this transaction.
   response_.unused_since_prefetch = !response_.unused_since_prefetch;
   next_state_ = STATE_CACHE_DISPATCH_VALIDATION;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoCacheDispatchValidation() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheDispatchValidation");
   // We now have access to the cache entry.
   //
   //  o if we are a reader for the transaction, then we can start reading the
   //    cache entry.
   //
   //  o if we can read or write, then we should check if the cache entry needs
   //    to be validated and then issue a network request if needed or just read
   //    from the cache if the cache entry is already valid.
   //
   //  o if we are set to UPDATE, then we are handling an externally
@@ skipping 61 matching lines @@
 
   if (reading_ && partial_->IsCurrentRangeCached()) {
     next_state_ = STATE_CACHE_READ_DATA;
     return OK;
   }
 
   return BeginCacheValidation();
 }
 
 int HttpCache::Transaction::DoSendRequest() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoSendRequest");
   DCHECK(mode_ & WRITE || mode_ == NONE);
   DCHECK(!network_trans_.get());
 
   send_request_since_ = TimeTicks::Now();
 
   // Create a network transaction.
   int rv =
       cache_->network_layer_->CreateTransaction(priority_, &network_trans_);
   if (rv != OK)
     return rv;
   network_trans_->SetBeforeNetworkStartCallback(before_network_start_callback_);
   network_trans_->SetBeforeHeadersSentCallback(before_headers_sent_callback_);
 
   // Old load timing information, if any, is now obsolete.
   old_network_trans_load_timing_.reset();
   old_remote_endpoint_ = IPEndPoint();
 
   if (websocket_handshake_stream_base_create_helper_)
     network_trans_->SetWebSocketHandshakeStreamCreateHelper(
         websocket_handshake_stream_base_create_helper_);
 
   next_state_ = STATE_SEND_REQUEST_COMPLETE;
   rv = network_trans_->Start(request_, io_callback_, net_log_);
   return rv;
 }
 
 int HttpCache::Transaction::DoSendRequestComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoSendRequestComplete");
   if (!cache_.get())
     return ERR_UNEXPECTED;
 
   // If we tried to conditionalize the request and failed, we know
   // we won't be reading from the cache after this point.
   if (couldnt_conditionalize_request_)
     mode_ = WRITE;
 
   if (result == OK) {
     next_state_ = STATE_SUCCESSFUL_SEND_REQUEST;
@@ skipping 15 matching lines @@
     response_.cert_request_info = response->cert_request_info;
   } else if (response_.was_cached) {
     DoneWritingToEntry(true);
   }
 
   return result;
 }
 
 // We received the response headers and there is no error.
 int HttpCache::Transaction::DoSuccessfulSendRequest() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoSuccessfulSendRequest");
   DCHECK(!new_response_);
   const HttpResponseInfo* new_response = network_trans_->GetResponseInfo();
 
   if (new_response->headers->response_code() == 401 ||
       new_response->headers->response_code() == 407) {
     SetAuthResponse(*new_response);
     if (!reading_)
       return OK;
 
     // We initiated a second request the caller doesn't know about. We should be
@@ skipping 85 matching lines @@
     UpdateCacheEntryStatus(CacheEntryStatus::ENTRY_UPDATED);
     mode_ = WRITE;
   }
 
   next_state_ = STATE_OVERWRITE_CACHED_RESPONSE;
   return OK;
 }
 
 // We received 304 or 206 and we want to update the cached response headers.
 int HttpCache::Transaction::DoUpdateCachedResponse() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoUpdateCachedResponse");
   next_state_ = STATE_UPDATE_CACHED_RESPONSE_COMPLETE;
   int rv = OK;
   // Update the cached response based on the headers and properties of
   // new_response_.
   response_.headers->Update(*new_response_->headers.get());
   response_.response_time = new_response_->response_time;
   response_.request_time = new_response_->request_time;
   response_.network_accessed = new_response_->network_accessed;
   response_.unused_since_prefetch = new_response_->unused_since_prefetch;
   response_.ssl_info = new_response_->ssl_info;
@@ skipping 17 matching lines @@
     // request; doing it again will change Content-Length.
     if (!reading_) {
       next_state_ = STATE_CACHE_WRITE_UPDATED_RESPONSE;
       rv = OK;
     }
   }
   return rv;
 }
 
 int HttpCache::Transaction::DoCacheWriteUpdatedResponse() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteUpdatedResponse");
+
   next_state_ = STATE_CACHE_WRITE_UPDATED_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheWriteUpdatedResponseComplete(int result) {
+  TRACE_EVENT0("io",
+               "HttpCacheTransaction::DoCacheWriteUpdatedResponseComplete");
   next_state_ = STATE_UPDATE_CACHED_RESPONSE_COMPLETE;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoUpdateCachedResponseComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoUpdateCachedResponseComplete");
   if (mode_ == UPDATE) {
     DCHECK(!handling_206_);
     // We got a "not modified" response and already updated the corresponding
     // cache entry above.
     //
     // By closing the cached entry now, we make sure that the 304 rather than
     // the cached 200 response, is what will be returned to the user.
     DoneWritingToEntry(true);
   } else if (entry_ && !handling_206_) {
     DCHECK_EQ(READ_WRITE, mode_);
@@ skipping 12 matching lines @@
     new_response_ = NULL;
     next_state_ = STATE_START_PARTIAL_CACHE_VALIDATION;
     partial_->SetRangeToStartDownload();
     return OK;
   }
   next_state_ = STATE_OVERWRITE_CACHED_RESPONSE;
   return OK;
 }
 
 int HttpCache::Transaction::DoOverwriteCachedResponse() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoOverwriteCachedResponse");
   if (mode_ & READ) {
     next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
     return OK;
   }
 
   // We change the value of Content-Length for partial content.
   if (handling_206_ && partial_)
     partial_->FixContentLength(new_response_->headers.get());
 
   SetResponse(*new_response_);
@@ skipping 14 matching lines @@
       partial_->FixResponseHeaders(response_.headers.get(), true);
     next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
     return OK;
   }
 
   next_state_ = STATE_CACHE_WRITE_RESPONSE;
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheWriteResponse() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteResponse");
   next_state_ = STATE_CACHE_WRITE_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(truncated_);
 }
 
 int HttpCache::Transaction::DoCacheWriteResponseComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteResponseComplete");
   next_state_ = STATE_TRUNCATE_CACHED_DATA;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoTruncateCachedData() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoTruncateCachedData");
   next_state_ = STATE_TRUNCATE_CACHED_DATA_COMPLETE;
   if (!entry_)
     return OK;
   if (net_log_.IsCapturing())
     net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_WRITE_DATA);
   // Truncate the stream.
   return WriteToEntry(kResponseContentIndex, 0, NULL, 0, io_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoInitEntry");
   if (entry_) {
     if (net_log_.IsCapturing()) {
       net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_WRITE_DATA,
                                         result);
     }
   }
 
   next_state_ = STATE_TRUNCATE_CACHED_METADATA;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadata() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoTruncateCachedMetadata");
   next_state_ = STATE_TRUNCATE_CACHED_METADATA_COMPLETE;
   if (!entry_)
     return OK;
 
   if (net_log_.IsCapturing())
     net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_WRITE_INFO);
   return WriteToEntry(kMetadataIndex, 0, NULL, 0, io_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadataComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoTruncateCachedMetadataComplete");
   if (entry_) {
     if (net_log_.IsCapturing()) {
       net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_WRITE_INFO,
                                         result);
     }
   }
 
   next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
   return OK;
 }
@@ skipping 14 matching lines @@
     }
   } else if (mode_ != NONE) {
     // We are about to return the headers for a byte-range request to the user,
     // so let's fix them.
     partial_->FixResponseHeaders(response_.headers.get(), true);
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheReadMetadata() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheReadMetadata");
   DCHECK(entry_);
   DCHECK(!response_.metadata.get());
   next_state_ = STATE_CACHE_READ_METADATA_COMPLETE;
 
   response_.metadata =
       new IOBufferWithSize(entry_->disk_entry->GetDataSize(kMetadataIndex));
 
   net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_READ_INFO);
   return entry_->disk_entry->ReadData(kMetadataIndex, 0,
                                       response_.metadata.get(),
                                       response_.metadata->size(),
                                       io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheReadMetadataComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_READ_INFO,
                                     result);
   if (result != response_.metadata->size())
     return OnCacheReadError(result, false);
   return OK;
 }
 
 int HttpCache::Transaction::DoNetworkRead() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoNetworkRead");
   next_state_ = STATE_NETWORK_READ_COMPLETE;
   return network_trans_->Read(read_buf_.get(), io_buf_len_, io_callback_);
 }
 
 int HttpCache::Transaction::DoNetworkReadComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoNetworkReadComplete");
   DCHECK(mode_ & WRITE || mode_ == NONE);
 
   if (!cache_.get())
     return ERR_UNEXPECTED;
 
   // If there is an error or we aren't saving the data, we are done; just wait
   // until the destructor runs to see if we can keep the data.
   if (mode_ == NONE || result < 0)
     return result;
 
   next_state_ = STATE_CACHE_WRITE_DATA;
   return result;
 }
 
 int HttpCache::Transaction::DoCacheReadData() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheReadData");
   if (request_->method == "HEAD")
     return 0;
 
   DCHECK(entry_);
   next_state_ = STATE_CACHE_READ_DATA_COMPLETE;
 
   if (net_log_.IsCapturing())
     net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_READ_DATA);
   if (partial_) {
     return partial_->CacheRead(entry_->disk_entry, read_buf_.get(), io_buf_len_,
                                io_callback_);
   }
 
   return entry_->disk_entry->ReadData(kResponseContentIndex, read_offset_,
                                       read_buf_.get(), io_buf_len_,
                                       io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheReadDataComplete");
   if (net_log_.IsCapturing()) {
     net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_READ_DATA,
                                       result);
   }
 
   if (!cache_.get())
     return ERR_UNEXPECTED;
 
   if (partial_) {
     // Partial requests are confusing to report in histograms because they may
     // have multiple underlying requests.
     UpdateCacheEntryStatus(CacheEntryStatus::ENTRY_OTHER);
     return DoPartialCacheReadCompleted(result);
   }
 
   if (result > 0) {
     read_offset_ += result;
   } else if (result == 0) {  // End of file.
     RecordHistograms();
     cache_->DoneReadingFromEntry(entry_, this);
     entry_ = NULL;
   } else {
     return OnCacheReadError(result, false);
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteData");
   next_state_ = STATE_CACHE_WRITE_DATA_COMPLETE;
   write_len_ = num_bytes;
   if (entry_) {
     if (net_log_.IsCapturing())
       net_log_.BeginEvent(NetLogEventType::HTTP_CACHE_WRITE_DATA);
   }
 
   if (!entry_ || !num_bytes)
     return num_bytes;
 
   int current_size = entry_->disk_entry->GetDataSize(kResponseContentIndex);
   return WriteToEntry(kResponseContentIndex, current_size, read_buf_.get(),
                       num_bytes, io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheWriteDataComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteDataComplete");
   if (entry_) {
     if (net_log_.IsCapturing()) {
       net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_WRITE_DATA,
                                         result);
     }
   }
   if (!cache_.get())
     return ERR_UNEXPECTED;
 
   if (result != write_len_) {
@@ skipping 24 matching lines @@
     if (done_reading_ || !entry_ || partial_ ||
         response_.headers->GetContentLength() <= 0) {
       DoneWritingToEntry(true);
     }
   }
 
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponse() {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteTruncatedResponse");
   next_state_ = STATE_CACHE_WRITE_TRUNCATED_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(true);
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponseComplete(int result) {
+  TRACE_EVENT0("io", "HttpCacheTransaction::DoCacheWriteTruncatedResponse");
+
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 //-----------------------------------------------------------------------------
 
 void HttpCache::Transaction::SetRequest(const NetLogWithSource& net_log,
                                         const HttpRequestInfo* request) {
   net_log_ = net_log;
   request_ = request;
   effective_load_flags_ = request_->load_flags;
@@ skipping 1083 matching lines @@
     default:
       NOTREACHED();
   }
 }
 
 void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
 }  // namespace net