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 370862d49f90e73a6561ce1931f7d32c51d65b5f..0441945eb59c95d87ea310da7126285e2bd02878 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,8 @@ HttpCache::Transaction::Transaction(RequestPriority priority, HttpCache* cache)
       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");
@@ -198,6 +201,8 @@ HttpCache::Transaction::Transaction(RequestPriority priority, HttpCache* cache)
 }
 
 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();
@@ -957,6 +962,8 @@ int HttpCache::Transaction::DoGetBackendComplete(int result) {
 }
 
 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())
@@ -972,6 +979,8 @@ int HttpCache::Transaction::DoInitEntry() {
 }
 
 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;
@@ -981,6 +990,9 @@ int HttpCache::Transaction::DoOpenEntry() {
 }
 
 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.
@@ -1023,6 +1035,8 @@ int HttpCache::Transaction::DoOpenEntryComplete(int result) {
 }
 
 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())
@@ -1032,6 +1046,9 @@ int HttpCache::Transaction::DoDoomEntry() {
 }
 
 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;
@@ -1042,6 +1059,8 @@ int HttpCache::Transaction::DoDoomEntryComplete(int result) {
 }
 
 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;
@@ -1050,6 +1069,9 @@ int HttpCache::Transaction::DoCreateEntry() {
 }
 
 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.
@@ -1080,6 +1102,8 @@ int HttpCache::Transaction::DoCreateEntryComplete(int result) {
 }
 
 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;
@@ -1121,6 +1145,9 @@ int HttpCache::Transaction::DoAddToEntry() {
 }
 
 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 =
@@ -1173,6 +1200,9 @@ int HttpCache::Transaction::DoAddToEntryComplete(int result) {
 }
 
 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;
 
@@ -1185,6 +1215,9 @@ int HttpCache::Transaction::DoCacheReadResponse() {
 }
 
 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_ ||
@@ -1234,6 +1267,9 @@ int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
 }
 
 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;
 
@@ -1247,6 +1283,9 @@ int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetch() {
 
 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;
@@ -1254,6 +1293,9 @@ int HttpCache::Transaction::DoCacheToggleUnusedSincePrefetchComplete(
 }
 
 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
@@ -1335,6 +1377,8 @@ int HttpCache::Transaction::DoCompletePartialCacheValidation(int result) {
 }
 
 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());
 
@@ -1362,6 +1406,9 @@ int HttpCache::Transaction::DoSendRequest() {
 }
 
 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;
 
@@ -1397,6 +1444,9 @@ int HttpCache::Transaction::DoSendRequestComplete(int 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();
 
@@ -1502,6 +1552,9 @@ int HttpCache::Transaction::DoSuccessfulSendRequest() {
 
 // 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
@@ -1539,16 +1592,26 @@ int HttpCache::Transaction::DoUpdateCachedResponse() {
 }
 
 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
@@ -1581,6 +1644,9 @@ int HttpCache::Transaction::DoUpdateCachedResponseComplete(int result) {
 }
 
 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;
@@ -1615,16 +1681,25 @@ int HttpCache::Transaction::DoOverwriteCachedResponse() {
 }
 
 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;
@@ -1635,6 +1710,8 @@ int HttpCache::Transaction::DoTruncateCachedData() {
 }
 
 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,
@@ -1647,6 +1724,9 @@ int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
 }
 
 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;
@@ -1657,6 +1737,9 @@ int HttpCache::Transaction::DoTruncateCachedMetadata() {
 }
 
 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,
@@ -1691,6 +1774,9 @@ int HttpCache::Transaction::DoPartialHeadersReceived() {
 }
 
 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;
@@ -1706,6 +1792,9 @@ int HttpCache::Transaction::DoCacheReadMetadata() {
 }
 
 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())
@@ -1714,11 +1803,16 @@ int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
 }
 
 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())
@@ -1734,6 +1828,8 @@ int HttpCache::Transaction::DoNetworkReadComplete(int 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;
 
@@ -1753,6 +1849,9 @@ int HttpCache::Transaction::DoCacheReadData() {
 }
 
 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);
@@ -1781,6 +1880,9 @@ int HttpCache::Transaction::DoCacheReadDataComplete(int 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_) {
@@ -1797,6 +1899,9 @@ int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
 }
 
 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,
@@ -1841,11 +1946,18 @@ int HttpCache::Transaction::DoCacheWriteDataComplete(int 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);
 }