Switch the TCP reads on Windows to use non-blocking/non-async I/O.

The Overlapped I/O was introducing delays when the networking stack
did not have enough data to fill the receive buffer.

This can be seen when loading pssplayground.com/ksimbili/webp.html
using a DSL connection profile on WebPagetest:
http://www.webpagetest.org/result/120830_MS_414849a6aa055bb853e7e5d51e1b29d8/
and manifests and increasingly long Time to First Byte for requests
further down the waterfall (expected values are < 90ms and it was 
going over 150ms).

It is configured as a 50% field trial and can be forced through the 
command-line for testing:
    --overlapped-reads=on - default/existing behavior
    --overlapped-reads=off - new read implementation

Trial-specific histograms are reported for page load times and
http request times.  Specifically:
    PLT.Abandoned
    PLT.LoadType
    PLT.BeginToFinish_NormalLoad
    PLT.BeginToFinish_LinkLoadNormal
    PLT.BeginToFinish_LinkLoadReload
    PLT.BeginToFinish_LinkLoadStaleOk
    Net.HttpJob.TotalTime
    Net.HttpJob.TotalTimeSuccess
    Net.HttpJob.TotalTimeCancel
    Net.HttpJob.TotalTimeCached
    Net.HttpJob.TotalTimeNotCached

Review URL: https://chromiumcodereview.appspot.com/10916016

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@165170 0039d316-1c4b-4281-b951-d872f2087c98

8 files changed, 261 insertions, 50 deletions

diff --git a/chrome/browser/chrome_browser_field_trials.cc b/chrome/browser/chrome_browser_field_trials.cc
index a41a4ee..aff8b8c 100644
--- a/chrome/browser/chrome_browser_field_trials.cc
+++ b/chrome/browser/chrome_browser_field_trials.cc
@@ -28,6 +28,7 @@
 #include "ui/base/layout.h"
 
 #if defined(OS_WIN)
+#include "net/socket/tcp_client_socket_win.h"
 #include "ui/base/win/dpi.h"  // For DisableNewTabFieldTrialIfNecesssary.
 #endif  // defined(OS_WIN)
 
@@ -59,7 +60,7 @@ void SetupSingleUniformityFieldTrial(
       base::FieldTrialList::FactoryGetFieldTrial(
           trial_name, divisor, kDefaultGroupName, 2015, 1, 1, NULL));
   if (one_time_randomized)
-      trial->UseOneTimeRandomization();
+    trial->UseOneTimeRandomization();
   chrome_variations::AssociateGoogleVariationID(trial_name, kDefaultGroupName,
       trial_base_id);
   // Loop starts with group 1 because the field trial automatically creates a
@@ -112,6 +113,7 @@ void ChromeBrowserFieldTrials::SetupFieldTrials(bool proxy_policy_is_set) {
   SetUpSafeBrowsingInterstitialFieldTrial();
   SetUpInfiniteCacheFieldTrial();
   SetUpCacheSensitivityAnalysisFieldTrial();
+  WindowsOverlappedTCPReadsFieldTrial();
 #if defined(ENABLE_ONE_CLICK_SIGNIN)
   OneClickSigninHelper::InitializeFieldTrial();
 #endif
@@ -307,3 +309,27 @@ void ChromeBrowserFieldTrials::SetUpCacheSensitivityAnalysisFieldTrial() {
   trial->AppendGroup("400A", sensitivity_analysis_probability);
   trial->AppendGroup("400B", sensitivity_analysis_probability);
 }
+
+void ChromeBrowserFieldTrials::WindowsOverlappedTCPReadsFieldTrial() {
+#if defined(OS_WIN)
+  if (parsed_command_line_.HasSwitch(switches::kOverlappedRead)) {
+    std::string option =
+        parsed_command_line_.GetSwitchValueASCII(switches::kOverlappedRead);
+    if (LowerCaseEqualsASCII(option, "off"))
+      net::TCPClientSocketWin::DisableOverlappedReads();
+  } else {
+    const base::FieldTrial::Probability kDivisor = 2;  // 1 in 2 chance
+    const base::FieldTrial::Probability kOverlappedReadProbability = 1;
+    scoped_refptr<base::FieldTrial> overlapped_reads_trial(
+        base::FieldTrialList::FactoryGetFieldTrial("OverlappedReadImpact",
+            kDivisor, "OverlappedReadEnabled", 2013, 6, 1, NULL));
+    int overlapped_reads_disabled_group =
+        overlapped_reads_trial->AppendGroup("OverlappedReadDisabled",
+                                            kOverlappedReadProbability);
+    int assigned_group = overlapped_reads_trial->group();
+    if (assigned_group == overlapped_reads_disabled_group)
+      net::TCPClientSocketWin::DisableOverlappedReads();
+  }
+#endif
+}
+
diff --git a/chrome/browser/chrome_browser_field_trials.h b/chrome/browser/chrome_browser_field_trials.h
index 88cf41c..795beeb 100644
--- a/chrome/browser/chrome_browser_field_trials.h
+++ b/chrome/browser/chrome_browser_field_trials.h
@@ -54,6 +54,10 @@ class ChromeBrowserFieldTrials {
   // Sets up field trials for doing Cache Sensitivity Analysis.
   void SetUpCacheSensitivityAnalysisFieldTrial();
 
+  // A field trial to determine the impact of using non-blocking reads for
+  // TCP sockets on Windows instead of overlapped I/O.
+  void WindowsOverlappedTCPReadsFieldTrial();
+
   const CommandLine& parsed_command_line_;
 
   DISALLOW_COPY_AND_ASSIGN(ChromeBrowserFieldTrials);
diff --git a/chrome/common/chrome_switches.cc b/chrome/common/chrome_switches.cc
index 31ccc53..e7418e1 100644
--- a/chrome/common/chrome_switches.cc
+++ b/chrome/common/chrome_switches.cc
@@ -1556,6 +1556,12 @@ const char kForceImmersive[]                 = "force-immersive";
 // Windows 8 and higher.  Used when relaunching metro Chrome.
 const char kForceDesktop[]                   = "force-desktop";
 
+// Allows for disabling the overlapped I/O for TCP reads.
+// Possible values are "on" or "off".
+// The default is "on" which matches the existing behavior.
+// "off" switches to use non-blocking reads and WSAEventSelect.
+const char kOverlappedRead[]                 = "overlapped-reads";
+
 // Relaunches metro Chrome on Windows 8 and higher using a given shortcut.
 const char kRelaunchShortcut[]               = "relaunch-shortcut";
 
diff --git a/chrome/common/chrome_switches.h b/chrome/common/chrome_switches.h
index c5ea74c..598ba0f 100644
--- a/chrome/common/chrome_switches.h
+++ b/chrome/common/chrome_switches.h
@@ -435,6 +435,7 @@ extern const char kDisableDesktopShortcuts[];
 extern const char kEnableSyncCredentialCaching[];
 extern const char kForceImmersive[];
 extern const char kForceDesktop[];
+extern const char kOverlappedRead[];
 extern const char kPrintRaster[];
 extern const char kRelaunchShortcut[];
 extern const char kWaitForMutex[];
diff --git a/chrome/renderer/page_load_histograms.cc b/chrome/renderer/page_load_histograms.cc
index 96dfc5b..39c11ac 100644
--- a/chrome/renderer/page_load_histograms.cc
+++ b/chrome/renderer/page_load_histograms.cc
@@ -754,6 +754,43 @@ void PageLoadHistograms::Dump(WebFrame* frame) {
     }
   }
 
+  // Histograms to determine if disabling overlapped TCP reads
+  // has an impact on PLT.
+  static const bool use_overlapped_read_histogram =
+      base::FieldTrialList::TrialExists("OverlappedReadImpact");
+  if (use_overlapped_read_histogram) {
+    UMA_HISTOGRAM_ENUMERATION(
+        base::FieldTrial::MakeName("PLT.Abandoned", "OverlappedReadImpact"),
+        abandoned_page ? 1 : 0, 2);
+    UMA_HISTOGRAM_ENUMERATION(
+        base::FieldTrial::MakeName("PLT.LoadType", "OverlappedReadImpact"),
+        load_type, DocumentState::kLoadTypeMax);
+    switch (load_type) {
+      case DocumentState::NORMAL_LOAD:
+        PLT_HISTOGRAM(base::FieldTrial::MakeName(
+            "PLT.BeginToFinish_NormalLoad", "OverlappedReadImpact"),
+            begin_to_finish_all_loads);
+        break;
+      case DocumentState::LINK_LOAD_NORMAL:
+        PLT_HISTOGRAM(base::FieldTrial::MakeName(
+            "PLT.BeginToFinish_LinkLoadNormal", "OverlappedReadImpact"),
+            begin_to_finish_all_loads);
+        break;
+      case DocumentState::LINK_LOAD_RELOAD:
+        PLT_HISTOGRAM(base::FieldTrial::MakeName(
+            "PLT.BeginToFinish_LinkLoadReload", "OverlappedReadImpact"),
+            begin_to_finish_all_loads);
+        break;
+      case DocumentState::LINK_LOAD_CACHE_STALE_OK:
+        PLT_HISTOGRAM(base::FieldTrial::MakeName(
+            "PLT.BeginToFinish_LinkLoadStaleOk", "OverlappedReadImpact"),
+            begin_to_finish_all_loads);
+        break;
+      default:
+        break;
+    }
+  }
+
   // Site isolation metrics.
   UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithCrossSiteFrameAccess",
                        cross_origin_access_count_);
diff --git a/net/socket/tcp_client_socket_win.cc b/net/socket/tcp_client_socket_win.cc
index fd77a1f..3639581 100644
--- a/net/socket/tcp_client_socket_win.cc
+++ b/net/socket/tcp_client_socket_win.cc
@@ -28,6 +28,7 @@ namespace net {
 namespace {
 
 const int kTCPKeepAliveSeconds = 45;
+bool g_disable_overlapped_reads = false;
 
 bool SetSocketReceiveBufferSize(SOCKET socket, int32 size) {
   int rv = setsockopt(socket, SOL_SOCKET, SO_RCVBUF,
@@ -182,6 +183,16 @@ class TCPClientSocketWin::Core : public base::RefCounted<Core> {
   // The TCPClientSocketWin is going away.
   void Detach() { socket_ = NULL; }
 
+  // Throttle the read size based on our current slow start state.
+  // Returns the throttled read size.
+  int ThrottleReadSize(int size) {
+    if (slow_start_throttle_ < kMaxSlowStartThrottle) {
+      size = std::min(size, slow_start_throttle_);
+      slow_start_throttle_ *= 2;
+    }
+    return size;
+  }
+
   // The separate OVERLAPPED variables for asynchronous operation.
   // |read_overlapped_| is used for both Connect() and Read().
   // |write_overlapped_| is only used for Write();
@@ -191,17 +202,13 @@ class TCPClientSocketWin::Core : public base::RefCounted<Core> {
   // The buffers used in Read() and Write().
   scoped_refptr<IOBuffer> read_iobuffer_;
   scoped_refptr<IOBuffer> write_iobuffer_;
+  int read_buffer_length_;
   int write_buffer_length_;
 
-  // Throttle the read size based on our current slow start state.
-  // Returns the throttled read size.
-  int ThrottleReadSize(int size) {
-    if (slow_start_throttle_ < kMaxSlowStartThrottle) {
-      size = std::min(size, slow_start_throttle_);
-      slow_start_throttle_ *= 2;
-    }
-    return size;
-  }
+  // Remember the state of g_disable_overlapped_reads for the duration of the
+  // socket based on what it was when the socket was created.
+  bool disable_overlapped_reads_;
+  bool non_blocking_reads_initialized_;
 
  private:
   friend class base::RefCounted<Core>;
@@ -257,7 +264,10 @@ class TCPClientSocketWin::Core : public base::RefCounted<Core> {
 
 TCPClientSocketWin::Core::Core(
     TCPClientSocketWin* socket)
-    : write_buffer_length_(0),
+    : read_buffer_length_(0),
+      write_buffer_length_(0),
+      disable_overlapped_reads_(g_disable_overlapped_reads),
+      non_blocking_reads_initialized_(false),
       socket_(socket),
       ALLOW_THIS_IN_INITIALIZER_LIST(reader_(this)),
       ALLOW_THIS_IN_INITIALIZER_LIST(writer_(this)),
@@ -300,6 +310,8 @@ void TCPClientSocketWin::Core::ReadDelegate::OnObjectSignaled(
   if (core_->socket_) {
     if (core_->socket_->waiting_connect()) {
       core_->socket_->DidCompleteConnect();
+    } else if (core_->disable_overlapped_reads_) {
+      core_->socket_->DidSignalRead();
     } else {
       core_->socket_->DidCompleteRead();
     }
@@ -354,7 +366,6 @@ int TCPClientSocketWin::AdoptSocket(SOCKET socket) {
   SetNonBlocking(socket_);
 
   core_ = new Core(this);
-
   current_address_index_ = 0;
   use_history_.set_was_ever_connected();
 
@@ -711,42 +722,7 @@ int TCPClientSocketWin::Read(IOBuffer* buf,
   DCHECK(read_callback_.is_null());
   DCHECK(!core_->read_iobuffer_);
 
-  buf_len = core_->ThrottleReadSize(buf_len);
-
-  WSABUF read_buffer;
-  read_buffer.len = buf_len;
-  read_buffer.buf = buf->data();
-
-  // TODO(wtc): Remove the assertion after enough testing.
-  AssertEventNotSignaled(core_->read_overlapped_.hEvent);
-  DWORD num, flags = 0;
-  int rv = WSARecv(socket_, &read_buffer, 1, &num, &flags,
-                   &core_->read_overlapped_, NULL);
-  if (rv == 0) {
-    if (ResetEventIfSignaled(core_->read_overlapped_.hEvent)) {
-      base::StatsCounter read_bytes("tcp.read_bytes");
-      read_bytes.Add(num);
-      num_bytes_read_ += num;
-      if (num > 0)
-        use_history_.set_was_used_to_convey_data();
-      net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_RECEIVED, num,
-                                    buf->data());
-      return static_cast<int>(num);
-    }
-  } else {
-    int os_error = WSAGetLastError();
-    if (os_error != WSA_IO_PENDING) {
-      int net_error = MapSystemError(os_error);
-      net_log_.AddEvent(NetLog::TYPE_SOCKET_READ_ERROR,
-                        CreateNetLogSocketErrorCallback(net_error, os_error));
-      return net_error;
-    }
-  }
-  core_->WatchForRead();
-  waiting_read_ = true;
-  read_callback_ = callback;
-  core_->read_iobuffer_ = buf;
-  return ERR_IO_PENDING;
+  return DoRead(buf, buf_len, callback);
 }
 
 int TCPClientSocketWin::Write(IOBuffer* buf,
@@ -765,7 +741,6 @@ int TCPClientSocketWin::Write(IOBuffer* buf,
   WSABUF write_buffer;
   write_buffer.len = buf_len;
   write_buffer.buf = buf->data();
-  core_->write_buffer_length_ = buf_len;
 
   // TODO(wtc): Remove the assertion after enough testing.
   AssertEventNotSignaled(core_->write_overlapped_.hEvent);
@@ -799,10 +774,11 @@ int TCPClientSocketWin::Write(IOBuffer* buf,
       return net_error;
     }
   }
-  core_->WatchForWrite();
   waiting_write_ = true;
   write_callback_ = callback;
   core_->write_iobuffer_ = buf;
+  core_->write_buffer_length_ = buf_len;
+  core_->WatchForWrite();
   return ERR_IO_PENDING;
 }
 
@@ -824,6 +800,10 @@ bool TCPClientSocketWin::SetNoDelay(bool no_delay) {
   return DisableNagle(socket_, no_delay);
 }
 
+void TCPClientSocketWin::DisableOverlappedReads() {
+  g_disable_overlapped_reads = true;
+}
+
 void TCPClientSocketWin::LogConnectCompletion(int net_error) {
   if (net_error == OK)
     UpdateConnectionTypeHistograms(CONNECTION_ANY);
@@ -852,6 +832,78 @@ void TCPClientSocketWin::LogConnectCompletion(int net_error) {
           sizeof(source_address)));
 }
 
+int TCPClientSocketWin::DoRead(IOBuffer* buf, int buf_len,
+                               const CompletionCallback& callback) {
+  if (core_->disable_overlapped_reads_) {
+    if (!core_->non_blocking_reads_initialized_) {
+      WSAEventSelect(socket_, core_->read_overlapped_.hEvent,
+                     FD_READ | FD_CLOSE);
+      core_->non_blocking_reads_initialized_ = true;
+    }
+    int rv = recv(socket_, buf->data(), buf_len, 0);
+    if (rv == SOCKET_ERROR) {
+      int os_error = WSAGetLastError();
+      if (os_error != WSAEWOULDBLOCK) {
+        int net_error = MapSystemError(os_error);
+        net_log_.AddEvent(NetLog::TYPE_SOCKET_READ_ERROR,
+            CreateNetLogSocketErrorCallback(net_error, os_error));
+        return net_error;
+      }
+    } else {
+      base::StatsCounter read_bytes("tcp.read_bytes");
+      if (rv > 0) {
+        use_history_.set_was_used_to_convey_data();
+        read_bytes.Add(rv);
+        num_bytes_read_ += rv;
+      }
+      net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_RECEIVED, rv,
+                                    buf->data());
+      return rv;
+    }
+  } else {
+    buf_len = core_->ThrottleReadSize(buf_len);
+
+    WSABUF read_buffer;
+    read_buffer.len = buf_len;
+    read_buffer.buf = buf->data();
+
+    // TODO(wtc): Remove the assertion after enough testing.
+    AssertEventNotSignaled(core_->read_overlapped_.hEvent);
+    DWORD num;
+    DWORD flags = 0;
+    int rv = WSARecv(socket_, &read_buffer, 1, &num, &flags,
+                     &core_->read_overlapped_, NULL);
+    if (rv == 0) {
+      if (ResetEventIfSignaled(core_->read_overlapped_.hEvent)) {
+        base::StatsCounter read_bytes("tcp.read_bytes");
+        if (num > 0) {
+          use_history_.set_was_used_to_convey_data();
+          read_bytes.Add(num);
+          num_bytes_read_ += num;
+        }
+        net_log_.AddByteTransferEvent(NetLog::TYPE_SOCKET_BYTES_RECEIVED, num,
+                                      buf->data());
+        return static_cast<int>(num);
+      }
+    } else {
+      int os_error = WSAGetLastError();
+      if (os_error != WSA_IO_PENDING) {
+        int net_error = MapSystemError(os_error);
+        net_log_.AddEvent(NetLog::TYPE_SOCKET_READ_ERROR,
+            CreateNetLogSocketErrorCallback(net_error, os_error));
+        return net_error;
+      }
+    }
+  }
+
+  waiting_read_ = true;
+  read_callback_ = callback;
+  core_->read_iobuffer_ = buf;
+  core_->read_buffer_length_ = buf_len;
+  core_->WatchForRead();
+  return ERR_IO_PENDING;
+}
+
 void TCPClientSocketWin::DoReadCallback(int rv) {
   DCHECK_NE(rv, ERR_IO_PENDING);
   DCHECK(!read_callback_.is_null());
@@ -924,6 +976,7 @@ void TCPClientSocketWin::DidCompleteRead() {
                       CreateNetLogSocketErrorCallback(rv, os_error));
   }
   core_->read_iobuffer_ = NULL;
+  core_->read_buffer_length_ = 0;
   DoReadCallback(rv);
 }
 
@@ -963,4 +1016,38 @@ void TCPClientSocketWin::DidCompleteWrite() {
   DoWriteCallback(rv);
 }
 
+void TCPClientSocketWin::DidSignalRead() {
+  DCHECK(waiting_read_);
+  int os_error = 0;
+  WSANETWORKEVENTS network_events;
+  int rv = WSAEnumNetworkEvents(socket_, core_->read_overlapped_.hEvent,
+                                &network_events);
+  if (rv == SOCKET_ERROR) {
+    os_error = WSAGetLastError();
+    rv = MapSystemError(os_error);
+  } else if (network_events.lNetworkEvents & FD_READ) {
+    rv = DoRead(core_->read_iobuffer_, core_->read_buffer_length_,
+                read_callback_);
+    if (rv == ERR_IO_PENDING)
+      return;
+  } else if (network_events.lNetworkEvents & FD_CLOSE) {
+    if (network_events.iErrorCode[FD_CLOSE_BIT]) {
+      rv = MapSystemError(network_events.iErrorCode[FD_CLOSE_BIT]);
+      net_log_.AddEvent(NetLog::TYPE_SOCKET_READ_ERROR,
+                        CreateNetLogSocketErrorCallback(rv, os_error));
+    } else {
+      rv = 0;
+    }
+  } else {
+    // This should not happen but I have seen cases where we will get
+    // signaled but the network events flags are all clear (0).
+    core_->WatchForRead();
+    return;
+  }
+  waiting_read_ = false;
+  core_->read_iobuffer_ = NULL;
+  core_->read_buffer_length_ = 0;
+  DoReadCallback(rv);
+}
+
 }  // namespace net
diff --git a/net/socket/tcp_client_socket_win.h b/net/socket/tcp_client_socket_win.h
index 9e95aae..cd7d455 100644
--- a/net/socket/tcp_client_socket_win.h
+++ b/net/socket/tcp_client_socket_win.h
@@ -72,6 +72,10 @@ class NET_EXPORT TCPClientSocketWin : public StreamSocket,
   virtual bool SetKeepAlive(bool enable, int delay);
   virtual bool SetNoDelay(bool no_delay);
 
+  // Perform reads in non-blocking mode instead of overlapped mode.
+  // Used for experiments.
+  static void DisableOverlappedReads();
+
  private:
   // State machine for connecting the socket.
   enum ConnectState {
@@ -99,11 +103,13 @@ class NET_EXPORT TCPClientSocketWin : public StreamSocket,
   // Called after Connect() has completed with |net_error|.
   void LogConnectCompletion(int net_error);
 
+  int DoRead(IOBuffer* buf, int buf_len, const CompletionCallback& callback);
   void DoReadCallback(int rv);
   void DoWriteCallback(int rv);
   void DidCompleteConnect();
   void DidCompleteRead();
   void DidCompleteWrite();
+  void DidSignalRead();
 
   SOCKET socket_;
 
diff --git a/net/url_request/url_request_http_job.cc b/net/url_request/url_request_http_job.cc
index 2860e7e..52972b8 100644
--- a/net/url_request/url_request_http_job.cc
+++ b/net/url_request/url_request_http_job.cc
@@ -1298,6 +1298,15 @@ void URLRequestHttpJob::RecordTimer() {
 
   UMA_HISTOGRAM_MEDIUM_TIMES("Net.HttpTimeToFirstByte", to_start);
 
+  static const bool use_overlapped_read_histogram =
+      base::FieldTrialList::TrialExists("OverlappedReadImpact");
+  if (use_overlapped_read_histogram) {
+    UMA_HISTOGRAM_MEDIUM_TIMES(
+        base::FieldTrial::MakeName("Net.HttpTimeToFirstByte",
+                                   "OverlappedReadImpact"),
+        to_start);
+  }
+
   static const bool use_warm_socket_impact_histogram =
       base::FieldTrialList::TrialExists("WarmSocketImpact");
   if (use_warm_socket_impact_histogram) {
@@ -1491,6 +1500,41 @@ void URLRequestHttpJob::RecordPerfHistograms(CompletionCause reason) {
     }
   }
 
+  static const bool use_overlapped_read_histogram =
+      base::FieldTrialList::TrialExists("OverlappedReadImpact");
+  if (use_overlapped_read_histogram) {
+    UMA_HISTOGRAM_TIMES(
+        base::FieldTrial::MakeName("Net.HttpJob.TotalTime",
+                                   "OverlappedReadImpact"),
+        total_time);
+
+    if (reason == FINISHED) {
+      UMA_HISTOGRAM_TIMES(
+          base::FieldTrial::MakeName("Net.HttpJob.TotalTimeSuccess",
+                                     "OverlappedReadImpact"),
+          total_time);
+    } else {
+      UMA_HISTOGRAM_TIMES(
+          base::FieldTrial::MakeName("Net.HttpJob.TotalTimeCancel",
+                                     "OverlappedReadImpact"),
+          total_time);
+    }
+
+    if (response_info_) {
+      if (response_info_->was_cached) {
+        UMA_HISTOGRAM_TIMES(
+            base::FieldTrial::MakeName("Net.HttpJob.TotalTimeCached",
+                                       "OverlappedReadImpact"),
+            total_time);
+      } else  {
+        UMA_HISTOGRAM_TIMES(
+            base::FieldTrial::MakeName("Net.HttpJob.TotalTimeNotCached",
+                                       "OverlappedReadImpact"),
+            total_time);
+      }
+    }
+  }
+
   start_time_ = base::TimeTicks();
 }