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;
 using base::TimeDelta;
 using base::TimeTicks;
 
 namespace net {
 
 struct HeaderNameAndValue {
@@ skipping 49 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);
   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() {
@@ skipping 181 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();
   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