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

net/http/http_cache_transaction.cc

Index: net/http/http_cache_transaction.cc
diff --git a/net/http/http_cache_transaction.cc b/net/http/http_cache_transaction.cc
index 3ab072787cf9d9f73c8d8cde49919c60ec027424..657c8e332673f5828b43fdc56f9a063933f147e5 100644
--- a/net/http/http_cache_transaction.cc
+++ b/net/http/http_cache_transaction.cc
@@ -28,6 +28,7 @@
 #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"
@@ -189,6 +190,7 @@ HttpCache::Transaction::Transaction(RequestPriority priority, HttpCache* cache)
       total_sent_bytes_(0),
       websocket_handshake_stream_base_create_helper_(NULL),
       weak_factory_(this) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::Transaction");

[caseq, 2016/11/10 21:37:43]

Hmm... This does not look quite what I thought we discussed. I think we care
more for the wall duration of the transaction in general, rather than the CPU
overhead of different stages of it, isn't this so?

So my idea was that this should rather be TRACE_EVENT_NESTABLE_ASYNC_xxx() and
use common id to bind the different stages of transaction together.

   static_assert(HttpCache::Transaction::kNumValidationHeaders ==
                     arraysize(kValidationHeaders),
                 "invalid number of validation headers");
@@ -198,6 +200,7 @@ HttpCache::Transaction::Transaction(RequestPriority priority, HttpCache* cache)
 }
 
 HttpCache::Transaction::~Transaction() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::~Transaction");
   // We may have to issue another IO, but we should never invoke the callback_
   // after this point.
   callback_.Reset();
@@ -957,6 +960,7 @@ int HttpCache::Transaction::DoGetBackendComplete(int result) {
 }
 
 int HttpCache::Transaction::DoInitEntry() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoInitEntry");
   DCHECK(!new_entry_);
 
   if (!cache_.get())
@@ -972,6 +976,7 @@ int HttpCache::Transaction::DoInitEntry() {
 }
 
 int HttpCache::Transaction::DoOpenEntry() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoOpenEntry");
   DCHECK(!new_entry_);
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
@@ -981,6 +986,7 @@ int HttpCache::Transaction::DoOpenEntry() {
 }
 
 int HttpCache::Transaction::DoOpenEntryComplete(int result) {
+  TRACE_EVENT0("net", "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.
@@ -1023,6 +1029,7 @@ int HttpCache::Transaction::DoOpenEntryComplete(int result) {
 }
 
 int HttpCache::Transaction::DoDoomEntry() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoDoomEntry");
   next_state_ = STATE_DOOM_ENTRY_COMPLETE;
   cache_pending_ = true;
   if (first_cache_access_since_.is_null())
@@ -1032,6 +1039,7 @@ int HttpCache::Transaction::DoDoomEntry() {
 }
 
 int HttpCache::Transaction::DoDoomEntryComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoDoomEntryComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_DOOM_ENTRY,
                                     result);
   next_state_ = STATE_CREATE_ENTRY;
@@ -1042,6 +1050,7 @@ int HttpCache::Transaction::DoDoomEntryComplete(int result) {
 }
 
 int HttpCache::Transaction::DoCreateEntry() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCreateEntry");
   DCHECK(!new_entry_);
   next_state_ = STATE_CREATE_ENTRY_COMPLETE;
   cache_pending_ = true;
@@ -1050,6 +1059,7 @@ int HttpCache::Transaction::DoCreateEntry() {
 }
 
 int HttpCache::Transaction::DoCreateEntryComplete(int result) {
+  TRACE_EVENT0("net", "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.
@@ -1080,6 +1090,7 @@ int HttpCache::Transaction::DoCreateEntryComplete(int result) {
 }
 
 int HttpCache::Transaction::DoAddToEntry() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoAddToEntry");
   DCHECK(new_entry_);
   cache_pending_ = true;
   next_state_ = STATE_ADD_TO_ENTRY_COMPLETE;
@@ -1121,6 +1132,7 @@ int HttpCache::Transaction::DoAddToEntry() {
 }
 
 int HttpCache::Transaction::DoAddToEntryComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoAddToEntryComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_ADD_TO_ENTRY,
                                     result);
   const TimeDelta entry_lock_wait =
@@ -1173,6 +1185,7 @@ int HttpCache::Transaction::DoAddToEntryComplete(int result) {
 }
 
 int HttpCache::Transaction::DoCacheReadResponse() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheReadResponse");
   DCHECK(entry_);
   next_state_ = STATE_CACHE_READ_RESPONSE_COMPLETE;
 
@@ -1185,6 +1198,7 @@ int HttpCache::Transaction::DoCacheReadResponse() {
 }
 
 int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheReadResponseComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_READ_INFO,
                                     result);
   if (result != io_buf_len_ ||
@@ -1232,6 +1246,7 @@ int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
 }
 
 int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetch() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheToggleUnusedSincePrefetch");
   // Write back the toggled value for the next use of this entry.
   response_.unused_since_prefetch = !response_.unused_since_prefetch;
 
@@ -1245,6 +1260,8 @@ int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetch() {
 
 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;
@@ -1252,6 +1269,7 @@ int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetchComplete(
 }
 
 int HttpCache::Transaction::DoCacheDispatchValidation() {
+  TRACE_EVENT0("net", "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
@@ -1333,6 +1351,7 @@ int HttpCache::Transaction::DoCompletePartialCacheValidation(int result) {
 }
 
 int HttpCache::Transaction::DoSendRequest() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoSendRequest");
   DCHECK(mode_ & WRITE || mode_ == NONE);
   DCHECK(!network_trans_.get());
 
@@ -1360,6 +1379,7 @@ int HttpCache::Transaction::DoSendRequest() {
 }
 
 int HttpCache::Transaction::DoSendRequestComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoSendRequestComplete");
   if (!cache_.get())
     return ERR_UNEXPECTED;
 
@@ -1395,6 +1415,7 @@ int HttpCache::Transaction::DoSendRequestComplete(int result) {
 
 // We received the response headers and there is no error.
 int HttpCache::Transaction::DoSuccessfulSendRequest() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoSuccessfulSendRequest");
   DCHECK(!new_response_);
   const HttpResponseInfo* new_response = network_trans_->GetResponseInfo();
 
@@ -1500,6 +1521,7 @@ int HttpCache::Transaction::DoSuccessfulSendRequest() {
 
 // We received 304 or 206 and we want to update the cached response headers.
 int HttpCache::Transaction::DoUpdateCachedResponse() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoUpdateCachedResponse");
   next_state_ = STATE_UPDATE_CACHED_RESPONSE_COMPLETE;
   int rv = OK;
   // Update the cached response based on the headers and properties of
@@ -1537,16 +1559,21 @@ int HttpCache::Transaction::DoUpdateCachedResponse() {
 }
 
 int HttpCache::Transaction::DoCacheWriteUpdatedResponse() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteUpdatedResponse");
+
   next_state_ = STATE_CACHE_WRITE_UPDATED_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheWriteUpdatedResponseComplete(int result) {
+  TRACE_EVENT0("net",
+               "HttpCacheTransaction::DoCacheWriteUpdatedResponseComplete");
   next_state_ = STATE_UPDATE_CACHED_RESPONSE_COMPLETE;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoUpdateCachedResponseComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoUpdateCachedResponseComplete");
   if (mode_ == UPDATE) {
     DCHECK(!handling_206_);
     // We got a "not modified" response and already updated the corresponding
@@ -1579,6 +1606,7 @@ int HttpCache::Transaction::DoUpdateCachedResponseComplete(int result) {
 }
 
 int HttpCache::Transaction::DoOverwriteCachedResponse() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoOverwriteCachedResponse");
   if (mode_ & READ) {
     next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
     return OK;
@@ -1613,16 +1641,19 @@ int HttpCache::Transaction::DoOverwriteCachedResponse() {
 }
 
 int HttpCache::Transaction::DoCacheWriteResponse() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteResponse");
   next_state_ = STATE_CACHE_WRITE_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(truncated_);
 }
 
 int HttpCache::Transaction::DoCacheWriteResponseComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteResponseComplete");
   next_state_ = STATE_TRUNCATE_CACHED_DATA;
   return OnWriteResponseInfoToEntryComplete(result);
 }
 
 int HttpCache::Transaction::DoTruncateCachedData() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoTruncateCachedData");
   next_state_ = STATE_TRUNCATE_CACHED_DATA_COMPLETE;
   if (!entry_)
     return OK;
@@ -1633,6 +1664,7 @@ int HttpCache::Transaction::DoTruncateCachedData() {
 }
 
 int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoInitEntry");
   if (entry_) {
     if (net_log_.IsCapturing()) {
       net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_WRITE_DATA,
@@ -1645,6 +1677,7 @@ int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadata() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoTruncateCachedMetadata");
   next_state_ = STATE_TRUNCATE_CACHED_METADATA_COMPLETE;
   if (!entry_)
     return OK;
@@ -1655,6 +1688,7 @@ int HttpCache::Transaction::DoTruncateCachedMetadata() {
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadataComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoTruncateCachedMetadataComplete");
   if (entry_) {
     if (net_log_.IsCapturing()) {
       net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_WRITE_INFO,
@@ -1689,6 +1723,7 @@ int HttpCache::Transaction::DoPartialHeadersReceived() {
 }
 
 int HttpCache::Transaction::DoCacheReadMetadata() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheReadMetadata");
   DCHECK(entry_);
   DCHECK(!response_.metadata.get());
   next_state_ = STATE_CACHE_READ_METADATA_COMPLETE;
@@ -1704,6 +1739,7 @@ int HttpCache::Transaction::DoCacheReadMetadata() {
 }
 
 int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheReadMetadataComplete");
   net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_READ_INFO,
                                     result);
   if (result != response_.metadata->size())
@@ -1712,11 +1748,13 @@ int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
 }
 
 int HttpCache::Transaction::DoNetworkRead() {
+  TRACE_EVENT0("net", "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("net", "HttpCacheTransaction::DoNetworkReadComplete");
   DCHECK(mode_ & WRITE || mode_ == NONE);
 
   if (!cache_.get())
@@ -1732,6 +1770,7 @@ int HttpCache::Transaction::DoNetworkReadComplete(int result) {
 }
 
 int HttpCache::Transaction::DoCacheReadData() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheReadData");
   if (request_->method == "HEAD")
     return 0;
 
@@ -1751,6 +1790,7 @@ int HttpCache::Transaction::DoCacheReadData() {
 }
 
 int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheReadDataComplete");
   if (net_log_.IsCapturing()) {
     net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_READ_DATA,
                                       result);
@@ -1779,6 +1819,7 @@ int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
 }
 
 int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteData");
   next_state_ = STATE_CACHE_WRITE_DATA_COMPLETE;
   write_len_ = num_bytes;
   if (entry_) {
@@ -1795,6 +1836,7 @@ int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
 }
 
 int HttpCache::Transaction::DoCacheWriteDataComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteDataComplete");
   if (entry_) {
     if (net_log_.IsCapturing()) {
       net_log_.EndEventWithNetErrorCode(NetLogEventType::HTTP_CACHE_WRITE_DATA,
@@ -1839,11 +1881,14 @@ int HttpCache::Transaction::DoCacheWriteDataComplete(int result) {
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponse() {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteTruncatedResponse");
   next_state_ = STATE_CACHE_WRITE_TRUNCATED_RESPONSE_COMPLETE;
   return WriteResponseInfoToEntry(true);
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponseComplete(int result) {
+  TRACE_EVENT0("net", "HttpCacheTransaction::DoCacheWriteTruncatedResponse");
+
   return OnWriteResponseInfoToEntryComplete(result);
 }