Adding histograms showing fraction of page load times

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"
 
 #if defined(OS_POSIX)
 #include <unistd.h>
@@ skipping 14 matching lines @@
 #include "net/base/load_flags.h"
 #include "net/base/net_errors.h"
 #include "net/base/net_log.h"
 #include "net/base/ssl_cert_request_info.h"
 #include "net/base/ssl_config_service.h"
 #include "net/disk_cache/disk_cache.h"
 #include "net/http/http_network_session.h"
 #include "net/http/http_request_info.h"
 #include "net/http/http_response_headers.h"
 #include "net/http/http_transaction.h"
+#include "net/http/http_transaction_delegate.h"
 #include "net/http/http_util.h"
 #include "net/http/partial_data.h"
 
 using base::Time;
 
 namespace net {
 
 struct HeaderNameAndValue {
   const char* name;
   const char* value;
@@ skipping 47 matching lines @@
     while (v.GetNext()) {
       if (LowerCaseEqualsASCII(v.value_begin(), v.value_end(), search->value))
         return true;
     }
   }
   return false;
 }
 
 //-----------------------------------------------------------------------------
 
-HttpCache::Transaction::Transaction(HttpCache* cache)
+HttpCache::Transaction::Transaction(HttpCache* cache,
+                                    HttpTransactionDelegate* delegate)
     : next_state_(STATE_NONE),
       request_(NULL),
       cache_(cache->AsWeakPtr()),
       entry_(NULL),
       new_entry_(NULL),
       network_trans_(NULL),
       new_response_(NULL),
       mode_(NONE),
       target_state_(STATE_NONE),
       reading_(false),
       invalid_range_(false),
       truncated_(false),
       is_sparse_(false),
       range_requested_(false),
       handling_206_(false),
       cache_pending_(false),
       done_reading_(false),
       read_offset_(0),
       effective_load_flags_(0),
       write_len_(0),
       final_upload_progress_(0),
       ALLOW_THIS_IN_INITIALIZER_LIST(weak_factory_(this)),
       ALLOW_THIS_IN_INITIALIZER_LIST(io_callback_(
           base::Bind(&Transaction::OnIOComplete,
-                     weak_factory_.GetWeakPtr()))) {
+                     weak_factory_.GetWeakPtr()))),
+      delegate_(delegate) {
   COMPILE_ASSERT(HttpCache::Transaction::kNumValidationHeaders ==
                  arraysize(kValidationHeaders),
                  Invalid_number_of_validation_headers);
 }
 
 HttpCache::Transaction::~Transaction() {
   // We may have to issue another IO, but we should never invoke the callback_
   // after this point.
   callback_.Reset();
 
@@ skipping 507 matching lines @@
   if (rv != ERR_IO_PENDING)
     HandleResult(rv);
 
   return rv;
 }
 
 int HttpCache::Transaction::DoGetBackend() {
   cache_pending_ = true;
   next_state_ = STATE_GET_BACKEND_COMPLETE;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_GET_BACKEND);
+  ReportCacheActionStart();
   return cache_->GetBackendForTransaction(this);
 }
 
 int HttpCache::Transaction::DoGetBackendComplete(int result) {
   DCHECK(result == OK || result == ERR_FAILED);
+  ReportCacheActionFinish();
   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) {
       mode_ = READ;
@@ skipping 40 matching lines @@
   range_requested_ = (partial_.get() != NULL);
 
   return OK;
 }
 
 int HttpCache::Transaction::DoSendRequest() {
   DCHECK(mode_ & WRITE || mode_ == NONE);
   DCHECK(!network_trans_.get());
 
   // Create a network transaction.
-  int rv = cache_->network_layer_->CreateTransaction(&network_trans_);
+  int rv = cache_->network_layer_->CreateTransaction(&network_trans_, NULL);

[rvargas (doing something else), 2012/07/23 22:22:36]

It would be interesting to track the network activity too. Of course, not as
part of this CL.

[tburkard, 2012/07/24 01:03:12]

(nothing to do here).

On 2012/07/23 22:22:36, rvargas wrote:

   if (rv != OK)
     return rv;
 
   next_state_ = STATE_SEND_REQUEST_COMPLETE;
   rv = network_trans_->Start(request_, io_callback_, net_log_);
   return rv;
 }
 
 int HttpCache::Transaction::DoSendRequestComplete(int result) {
   if (!cache_)
@@ skipping 107 matching lines @@
 
   next_state_ = STATE_OPEN_ENTRY;
   return OK;
 }
 
 int HttpCache::Transaction::DoOpenEntry() {
   DCHECK(!new_entry_);
   next_state_ = STATE_OPEN_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY);
+  ReportCacheActionStart();
   return cache_->OpenEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoOpenEntryComplete(int result) {
   // 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.
+  ReportCacheActionFinish();
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_OPEN_ENTRY, result);
   cache_pending_ = false;
   if (result == OK) {
     next_state_ = STATE_ADD_TO_ENTRY;
     return OK;
   }
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
@@ skipping 23 matching lines @@
   // 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::DoCreateEntry() {
   DCHECK(!new_entry_);
   next_state_ = STATE_CREATE_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY);
+  ReportCacheActionStart();
   return cache_->CreateEntry(cache_key_, &new_entry_, this);
 }
 
 int HttpCache::Transaction::DoCreateEntryComplete(int result) {
   // 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.
+  ReportCacheActionFinish();
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_CREATE_ENTRY,
                                     result);
   cache_pending_ = false;
   next_state_ = STATE_ADD_TO_ENTRY;
 
   if (result == ERR_CACHE_RACE) {
     next_state_ = STATE_INIT_ENTRY;
     return OK;
   }
 
   if (result != OK) {
     // We have a race here: Maybe we failed to open the entry and decided to
     // create one, but by the time we called create, another transaction already
     // created the entry. If we want to eliminate this issue, we need an atomic
     // OpenOrCreate() method exposed by the disk cache.
     DLOG(WARNING) << "Unable to create cache entry";
     mode_ = NONE;
     if (partial_.get())
       partial_->RestoreHeaders(&custom_request_->extra_headers);
     next_state_ = STATE_SEND_REQUEST;
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoDoomEntry() {
   next_state_ = STATE_DOOM_ENTRY_COMPLETE;
   cache_pending_ = true;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_DOOM_ENTRY);
+  ReportCacheActionStart();
   return cache_->DoomEntry(cache_key_, this);
 }
 
 int HttpCache::Transaction::DoDoomEntryComplete(int result) {
+  ReportCacheActionFinish();
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_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::DoAddToEntry() {
   DCHECK(new_entry_);
   cache_pending_ = true;
   next_state_ = STATE_ADD_TO_ENTRY_COMPLETE;
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY);
+  ReportCacheActionStart();

[rvargas (doing something else), 2012/07/23 22:22:36]

We should treat this one some other way. This is not waiting for the disk cache,
it is waiting for the http cache.

[tburkard, 2012/07/24 01:03:12]

Why is the distinction important?  What is the difference?

On 2012/07/23 22:22:36, rvargas wrote:

[rvargas (doing something else), 2012/07/24 03:10:38]

No matter what we change at the disk cache layer, we won't be touching this
number, so the final histogram will not change. It is not important if we only
say "the percentage of time attributed to the cache is x, let's move on", but
otherwise it adds a form of noise.

[tburkard, 2012/07/24 22:23:26]

Done.

   DCHECK(entry_lock_waiting_since_.is_null());
   entry_lock_waiting_since_ = base::TimeTicks::Now();
   return cache_->AddTransactionToEntry(new_entry_, this);
 }
 
 int HttpCache::Transaction::DoAddToEntryComplete(int result) {
+  ReportCacheActionFinish();
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_ADD_TO_ENTRY,
                                     result);
 
   const base::TimeDelta entry_lock_wait =
       base::TimeTicks::Now() - entry_lock_waiting_since_;
   UMA_HISTOGRAM_TIMES("HttpCache.EntryLockWait", entry_lock_wait);
   static const bool prefetching_fieldtrial =
       base::FieldTrialList::TrialExists("Prefetch");
   if (prefetching_fieldtrial) {
     UMA_HISTOGRAM_TIMES(
@@ skipping 161 matching lines @@
                              STATE_CACHE_WRITE_RESPONSE;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedData() {
   next_state_ = STATE_TRUNCATE_CACHED_DATA_COMPLETE;
   if (!entry_)
     return OK;
   if (net_log_.IsLoggingAllEvents())
     net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA);
-
+  ReportCacheActionStart();
   // Truncate the stream.
   return WriteToEntry(kResponseContentIndex, 0, NULL, 0, io_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedDataComplete(int result) {
-  if (net_log_.IsLoggingAllEvents() && entry_) {
-    net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA,
-                                      result);
+  if (entry_) {
+      ReportCacheActionFinish();
+      if (net_log_.IsLoggingAllEvents()) {
+        net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA,
+                                          result);
+      }
   }
 
   next_state_ = STATE_TRUNCATE_CACHED_METADATA;
   return OK;
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadata() {
   next_state_ = STATE_TRUNCATE_CACHED_METADATA_COMPLETE;
   if (!entry_)
     return OK;
 
   if (net_log_.IsLoggingAllEvents())
     net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO);
+  ReportCacheActionStart();
   return WriteToEntry(kMetadataIndex, 0, NULL, 0, io_callback_);
 }
 
 int HttpCache::Transaction::DoTruncateCachedMetadataComplete(int result) {
-  if (net_log_.IsLoggingAllEvents() && entry_) {
-    net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO,
-                                      result);
+  if (entry_) {
+    ReportCacheActionFinish();
+    if (net_log_.IsLoggingAllEvents()) {
+      net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO,
+                                        result);
+    }
   }
 
   // If this response is a redirect, then we can stop writing now.  (We don't
   // need to cache the response body of a redirect.)
   if (response_.headers->IsRedirect(NULL))
     DoneWritingToEntry(true);
   next_state_ = STATE_PARTIAL_HEADERS_RECEIVED;
   return OK;
 }
 
@@ skipping 21 matching lines @@
 }
 
 int 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);
+  ReportCacheActionStart();

[rvargas (doing something else), 2012/07/23 22:22:36]

This is where we start getting confusing results.

Previous times are blocking in that no other request can progress if it is in
the same state (they can make progress in other states). 

States after this one are non blocking so multiple requests can be reading the
response form the cache and all can make progress at the same time.

So a single notification for both things is not appropriate.

[tburkard, 2012/07/24 01:03:12]

That doesn't matter for the purpose of what I'm trying to do.

I only care about how much time is spent in cache actions.  Whether other cache
actions can run in parallel is not important for my metrics.

On 2012/07/23 22:22:36, rvargas wrote:

[rvargas (doing something else), 2012/07/24 03:10:38]

I think it matters.

If we only care about a single request, then fine, because we can say x% of the
time was spent on cache related things.

On the other hand, if we look at 100 requests that are all part of the same
page, it makes a difference what part of the time directly affects the total
time or not. You may end up with total cache time that is 150% the total time
used for loading the page (or any percentage for that matter). And then?

Maybe it doesn't really matter, I'm wondering what we would be able to extract
from the data though.

[tburkard, 2012/07/24 22:23:26]

Per discussion on the phone, we are in agreement on this now.

On 2012/07/24 03:10:38, rvargas wrote:

   return entry_->disk_entry->ReadData(kResponseInfoIndex, 0, read_buf_,
                                       io_buf_len_, io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadResponseComplete(int result) {
+  ReportCacheActionFinish();
   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 24 matching lines @@
       break;
     case WRITE:
     default:
       NOTREACHED();
       result = ERR_FAILED;
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteResponse() {
-  if (net_log_.IsLoggingAllEvents() && entry_)
-    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO);
+  if (entry_) {
+    if (net_log_.IsLoggingAllEvents())
+      net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO);
+    ReportCacheActionStart();
+  }
   return WriteResponseInfoToEntry(false);
 }
 
 int HttpCache::Transaction::DoCacheWriteTruncatedResponse() {
-  if (net_log_.IsLoggingAllEvents() && entry_)
-    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO);
+  if (entry_) {
+    if (net_log_.IsLoggingAllEvents() && entry_)
+      net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_INFO);
+    ReportCacheActionStart();
+  }
   return WriteResponseInfoToEntry(true);
 }
 
 int HttpCache::Transaction::DoCacheWriteResponseComplete(int result) {
   next_state_ = target_state_;
   target_state_ = STATE_NONE;
   if (!entry_)
     return OK;
+  ReportCacheActionFinish();
   if (net_log_.IsLoggingAllEvents()) {
     net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_INFO,
                                       result);
   }
 
   // Balance the AddRef from WriteResponseInfoToEntry.
   if (result != io_buf_len_) {
     DLOG(ERROR) << "failed to write response info to cache";
     DoneWritingToEntry(false);
   }
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheReadMetadata() {
   DCHECK(entry_);
   DCHECK(!response_.metadata);
   next_state_ = STATE_CACHE_READ_METADATA_COMPLETE;
 
   response_.metadata =
       new IOBufferWithSize(entry_->disk_entry->GetDataSize(kMetadataIndex));
 
   net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_INFO);
+  ReportCacheActionStart();
   return entry_->disk_entry->ReadData(kMetadataIndex, 0, response_.metadata,
                                       response_.metadata->size(),
                                       io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadMetadataComplete(int result) {
+  ReportCacheActionFinish();
   net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_READ_INFO, result);
   if (result != response_.metadata->size())
     return OnCacheReadError(result, false);
 
   return OK;
 }
 
 int HttpCache::Transaction::DoCacheQueryData() {
   next_state_ = STATE_CACHE_QUERY_DATA_COMPLETE;
 
   // Balanced in DoCacheQueryDataComplete.
   return entry_->disk_entry->ReadyForSparseIO(io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheQueryDataComplete(int result) {
   DCHECK_EQ(OK, result);
   if (!cache_)
     return ERR_UNEXPECTED;
 
   return ValidateEntryHeadersAndContinue();
 }
 
 int HttpCache::Transaction::DoCacheReadData() {
   DCHECK(entry_);
   next_state_ = STATE_CACHE_READ_DATA_COMPLETE;
 
   if (net_log_.IsLoggingAllEvents())
     net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_READ_DATA);
+  ReportCacheActionStart();
   if (partial_.get()) {
     return partial_->CacheRead(entry_->disk_entry, read_buf_, io_buf_len_,
                                io_callback_);
   }
 
   return entry_->disk_entry->ReadData(kResponseContentIndex, read_offset_,
                                       read_buf_, io_buf_len_, io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheReadDataComplete(int result) {
+  ReportCacheActionFinish();
   if (net_log_.IsLoggingAllEvents()) {
     net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_READ_DATA,
                                       result);
   }
 
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (partial_.get())
     return DoPartialCacheReadCompleted(result);
 
   if (result > 0) {
     read_offset_ += result;
   } else if (result == 0) {  // End of file.
     cache_->DoneReadingFromEntry(entry_, this);
     entry_ = NULL;
   } else {
     return OnCacheReadError(result, false);
   }
   return result;
 }
 
 int HttpCache::Transaction::DoCacheWriteData(int num_bytes) {
   next_state_ = STATE_CACHE_WRITE_DATA_COMPLETE;
   write_len_ = num_bytes;
-  if (net_log_.IsLoggingAllEvents() && entry_)
-    net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA);
+  if (entry_) {
+    if (net_log_.IsLoggingAllEvents())
+      net_log_.BeginEvent(NetLog::TYPE_HTTP_CACHE_WRITE_DATA);
+    ReportCacheActionStart();
+  }
 
   return AppendResponseDataToEntry(read_buf_, num_bytes, io_callback_);
 }
 
 int HttpCache::Transaction::DoCacheWriteDataComplete(int result) {
-  if (net_log_.IsLoggingAllEvents() && entry_) {
-    net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA,
-                                      result);
+  if (entry_) {
+    ReportCacheActionFinish();
+    if (net_log_.IsLoggingAllEvents()) {
+      net_log_.EndEventWithNetErrorCode(NetLog::TYPE_HTTP_CACHE_WRITE_DATA,
+                                        result);
+    }
   }
   // Balance the AddRef from DoCacheWriteData.
   if (!cache_)
     return ERR_UNEXPECTED;
 
   if (result != write_len_) {
     DLOG(ERROR) << "failed to write response data to cache";
     DoneWritingToEntry(false);
 
     // We want to ignore errors writing to disk and just keep reading from
@@ skipping 719 matching lines @@
       !response_.headers->HasStrongValidators())
     return false;
 
   return true;
 }
 
 void HttpCache::Transaction::OnIOComplete(int result) {
   DoLoop(result);
 }
 
+void HttpCache::Transaction::ReportCacheActionStart() {
+  if (delegate_)
+    delegate_->OnCacheActionStart();
+}
+
+void HttpCache::Transaction::ReportCacheActionFinish() {
+  if (delegate_)
+    delegate_->OnCacheActionFinish();
+}
+
 }  // namespace net