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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::Transaction", this,

[caseq, 2016/10/20 21:23:31]

Not sure if you really want to have flow event here. Looks more like a plain
ASYNC event to me.

Also, can you use a more stable and, perhaps, human readable event name for that
-- e.g. something like HTTPCacheTransaction? The idea is to use the names that
would persist through refactoring.

Another thing is that it would be useful to have some reference to the resource
request that resulted in this transaction -- so I wonder if you can instead move
this to Start and perhaps use netlog's source id instead of `this' as an id?

[xunjieli, 2016/10/20 21:33:11]

I'd actually prefer full function names over humable readable counterparts. The
reason is that for heap profiling, memory infra can reuse these trace events to
construct heap tree.

See
https://docs.google.com/document/d/1L_j3CjtXtCXec4ecFYK3J1BXBkK30ZtfVTEOr0Q43...

[jkarlin, 2016/10/24 17:20:58]

We want the flow arrows on the IO thread. This way we can see what tasks run
between the transaction events quite clearly.
I don't have strong opinions about this. It seems like perhaps, as Helen said,
full names have an advantage? The code here is quite stable, but I can't
guarantee it won't refactor.
Done. Thanks!

+                         TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::~Transaction", this,
+                         TRACE_EVENT_FLAG_FLOW_IN);
   // 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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoInitEntry", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoOpenEntry", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoOpenEntryComplete",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   // 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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoDoomEntry", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoDoomEntryComplete",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCreateEntry", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCreateEntryComplete",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   // 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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoAddToEntry", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoAddToEntryComplete",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCacheReadResponse",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheReadResponseComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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 29 matching lines @@
     // 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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheToggleUnusedSincePrefetch", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   // 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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheToggleUnusedSincePrefetchComplete",
+      this, TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   // 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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheDispatchValidation", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   // 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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoSendRequest", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoSendRequestComplete",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoSuccessfulSendRequest", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net",
+                         "HttpCache::Transaction::DoUpdateCachedResponse", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheWriteUpdatedResponse", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
+
   next_state_ = STATE_CACHE_WRITE_UPDATED_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheWriteUpdatedResponseComplete(int result) {
+  TRACE_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheWriteUpdatedResponseComplete",
+      this, TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   next_state_ = STATE_UPDATE_CACHED_RESPONSE_COMPLETE;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoUpdateCachedResponseComplete(int result) {
+  TRACE_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoUpdateCachedResponseComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoOverwriteCachedResponse", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCacheWriteResponse",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   next_state_ = STATE_CACHE_WRITE_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(truncated_);
 }
 
 int HttpCache::Transaction::DoCacheWriteResponseComplete(int result) {
+  TRACE_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheWriteResponseComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   next_state_ = STATE_TRUNCATE_CACHED_DATA;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoTruncateCachedData() {
+  TRACE_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoTruncateCachedData",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoInitEntry", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoTruncateCachedMetadata", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoTruncateCachedMetadataComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCacheReadMetadata",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheReadMetadataComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoNetworkRead", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoNetworkReadComplete",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCacheReadData", this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheReadDataComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0("net", "HttpCache::Transaction::DoCacheWriteData",
+                         this,
+                         TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheWriteDataComplete", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   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_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheWriteTruncatedResponse", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
   next_state_ = STATE_CACHE_WRITE_TRUNCATED_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(true);
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponseComplete(int result) {
+  TRACE_EVENT_WITH_FLOW0(
+      "net", "HttpCache::Transaction::DoCacheWriteTruncatedResponse", this,
+      TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT);
+
   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 1080 matching lines @@
     default:
       NOTREACHED();
   }
 }
 
 void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
 }  // namespace net