net: Return LoadTiming information in the case of a cache hit

chrome/browser/net/load_timing_browsertest.cc

 // Copyright (c) 2013 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 <string>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/compiler_specific.h"
 #include "base/files/file_path.h"
@@ skipping 71 matching lines @@
   // Must be 0 when |is_null| is true.
   base::TimeDelta delta_;
 
   // This class is copyable and assignable.
 };
 
 // Structure used for both setting the LoadTimingInfo used by mock requests
 // and for times retrieved from the renderer process.
 //
 // Times used for mock requests are all expressed as TimeDeltas relative to
-// request_start.  Null RelativeTimes correspond to null TimeTicks().
+// when the Job starts.  Null RelativeTimes correspond to null TimeTicks().
 //
 // Times read from the renderer are expressed relative to fetchStart (Which is
 // not the same as request_start).  Null RelativeTimes correspond to times that
 // either cannot be retrieved (proxy times, send end) or times that are 0 (SSL
 // time when no new SSL connection was established).
 struct TimingDeltas {
   RelativeTime proxy_resolve_start;
   RelativeTime proxy_resolve_end;
   RelativeTime dns_start;
   RelativeTime dns_end;
@@ skipping 17 matching lines @@
                               const base::FilePath& path,
                               const TimingDeltas& load_timing_deltas)
       : net::URLRequestFileJob(request, network_delegate, path),
         load_timing_deltas_(load_timing_deltas),
         weak_factory_(this) {
   }
 
   // net::URLRequestFileJob implementation:
   virtual void Start() OVERRIDE {
     base::TimeDelta time_to_wait;
+    start_time_ = base::TimeTicks::Now();
     if (!load_timing_deltas_.receive_headers_end.is_null()) {
       // Need to delay starting until the largest of the times has elapsed.
       // Wait a little longer than necessary, to be on the safe side.
       time_to_wait = load_timing_deltas_.receive_headers_end.GetDelta() +
                          base::TimeDelta::FromMilliseconds(100);
     }
 
     MessageLoop::current()->PostDelayedTask(
         FROM_HERE,
         base::Bind(&MockUrlRequestJobWithTiming::DelayedStart,
                    weak_factory_.GetWeakPtr()),
         time_to_wait);
   }
 
   virtual void GetLoadTimingInfo(
       net::LoadTimingInfo* load_timing_info) const OVERRIDE {
-    // This should have been set by the URLRequest.
-    base::TimeTicks request_start = load_timing_info->request_start;
-    ASSERT_FALSE(request_start.is_null());
-
     // Make sure enough time has elapsed since start was called.  If this
     // fails, the test fixture itself is flaky.
     if (!load_timing_deltas_.receive_headers_end.is_null()) {
       EXPECT_LE(
-          request_start + load_timing_deltas_.receive_headers_end.GetDelta(),
+          start_time_ + load_timing_deltas_.receive_headers_end.GetDelta(),
           base::TimeTicks::Now());
     }
 
     // If there are no connect times, but there is a receive headers end time,
     // then assume the socket is reused.  This shouldn't affect the load timing
     // information the test checks, just done for completeness.
     load_timing_info->socket_reused = false;
     if (load_timing_deltas_.connect_start.is_null() &&
         !load_timing_deltas_.receive_headers_end.is_null()) {
       load_timing_info->socket_reused = true;
     }
 
     load_timing_info->proxy_resolve_start =
-        load_timing_deltas_.proxy_resolve_start.ToTimeTicks(request_start);
+        load_timing_deltas_.proxy_resolve_start.ToTimeTicks(start_time_);
     load_timing_info->proxy_resolve_end =
-        load_timing_deltas_.proxy_resolve_end.ToTimeTicks(request_start);
+        load_timing_deltas_.proxy_resolve_end.ToTimeTicks(start_time_);
 
     load_timing_info->connect_timing.dns_start =
-        load_timing_deltas_.dns_start.ToTimeTicks(request_start);
+        load_timing_deltas_.dns_start.ToTimeTicks(start_time_);
     load_timing_info->connect_timing.dns_end =
-        load_timing_deltas_.dns_end.ToTimeTicks(request_start);
+        load_timing_deltas_.dns_end.ToTimeTicks(start_time_);
     load_timing_info->connect_timing.connect_start =
-        load_timing_deltas_.connect_start.ToTimeTicks(request_start);
+        load_timing_deltas_.connect_start.ToTimeTicks(start_time_);
     load_timing_info->connect_timing.ssl_start =
-        load_timing_deltas_.ssl_start.ToTimeTicks(request_start);
+        load_timing_deltas_.ssl_start.ToTimeTicks(start_time_);
     load_timing_info->connect_timing.connect_end =
-        load_timing_deltas_.connect_end.ToTimeTicks(request_start);
+        load_timing_deltas_.connect_end.ToTimeTicks(start_time_);
 
     // If there's an SSL start time, use connect end as the SSL end time.
     // The NavigationTiming API does not have a corresponding field, and there's
     // no need to test the case when the values are both non-NULL and different.
     if (!load_timing_deltas_.ssl_start.is_null()) {
       load_timing_info->connect_timing.ssl_end =
           load_timing_info->connect_timing.connect_end;
     }
 
     load_timing_info->send_start =
-        load_timing_deltas_.send_start.ToTimeTicks(request_start);
+        load_timing_deltas_.send_start.ToTimeTicks(start_time_);
     load_timing_info->send_end=
-        load_timing_deltas_.send_end.ToTimeTicks(request_start);
+        load_timing_deltas_.send_end.ToTimeTicks(start_time_);
     load_timing_info->receive_headers_end =
-        load_timing_deltas_.receive_headers_end.ToTimeTicks(request_start);
+        load_timing_deltas_.receive_headers_end.ToTimeTicks(start_time_);
   }
 
  private:
   // Parent class is reference counted, so need to have a private destructor.
   virtual ~MockUrlRequestJobWithTiming() {}
 
   void DelayedStart() {
     net::URLRequestFileJob::Start();
   }
 
-  // Load times to use, relative to request_start from the URLRequest.
+  // Load times to use, relative to |start_time_|.
   const TimingDeltas load_timing_deltas_;
+  base::TimeTicks start_time_;
 
   base::WeakPtrFactory<MockUrlRequestJobWithTiming> weak_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(MockUrlRequestJobWithTiming);
 };
 
 // A protocol handler that returns mock URLRequestJobs that return the specified
 // file with the given timings.  Constructed on the UI thread, but after that,
 // lives and is destroyed on the IO thread.
 class TestProtocolHandler : public net::URLRequestJobFactory::ProtocolHandler {
@@ skipping 31 matching lines @@
     EXPECT_TRUE(BrowserThread::CurrentlyOn(BrowserThread::IO));
 
     return new MockUrlRequestJobWithTiming(request, network_delegate, path_,
                                            load_timing_deltas_);
   }
 
  private:
   // Path of the file to use as the response body.
   const base::FilePath path_;
 
-  // Load times for each request to use, relative to their request_start times.
+  // Load times for each request to use, relative to when the Job starts.
   const TimingDeltas load_timing_deltas_;
 
   DISALLOW_COPY_AND_ASSIGN(TestProtocolHandler);
 };
 
 class LoadTimingBrowserTest : public InProcessBrowserTest {
  public:
   LoadTimingBrowserTest() {
   }
 
@@ skipping 225 matching lines @@
 
   EXPECT_LT(navigation_deltas.send_start.GetDelta(),
             navigation_deltas.receive_headers_end.GetDelta());
 
   EXPECT_TRUE(navigation_deltas.ssl_start.is_null());
 }
 
 // Preconnect case.  Connect times are all before the request was started.
 IN_PROC_BROWSER_TEST_F(LoadTimingBrowserTest, Preconnect) {
   TimingDeltas load_timing_deltas;
-  load_timing_deltas.dns_start = RelativeTime(-100300);
-  load_timing_deltas.dns_end = RelativeTime(-100200);
-  load_timing_deltas.connect_start = RelativeTime(-100100);
-  load_timing_deltas.connect_end = RelativeTime(-100000);
+  load_timing_deltas.dns_start = RelativeTime(-1000300);

[eroman, 2013/05/15 01:11:50]

what is the significance of changing these times?

[mmenke, 2013/05/15 01:52:38]

Paranoia.  It used to be that request_start was time 0, so these were guaranteed
to be less than request_start just by being negative.  That's no longer the
case, now that we no longer can base all times off of request_start.

The old value of 100 seconds should be completely safe, but I'm paranoid, and
using a debugger or a hosed system can do odd things to timings.

The other test used just 100 milliseconds, which wouldn't have made the test
flaky, because they just need to be less than proxy_end, but I wanted them less
than request_start as well.


Other than the stuff up above, the only change in this file that was needed was
the EXPECT_EQ -> EXPECT_LE.  I wasn't able to get a failure before I made that
change, but it could well have caused flake, since it was an incorrect assertion
with the new code.

+  load_timing_deltas.dns_end = RelativeTime(-1000200);
+  load_timing_deltas.connect_start = RelativeTime(-1000100);
+  load_timing_deltas.connect_end = RelativeTime(-1000000);
   load_timing_deltas.send_start = RelativeTime(0);
   load_timing_deltas.send_end = RelativeTime(100);
   load_timing_deltas.receive_headers_end = RelativeTime(200);
 
   TimingDeltas navigation_deltas;
   RunTest(load_timing_deltas, &navigation_deltas);
 
-  // Connect times should all be the same as request_start, which is also the
-  // same as send_start (Since send_start is 0).
+  // Connect times should all be the same as request_start.
   EXPECT_EQ(navigation_deltas.dns_start.GetDelta(),
             navigation_deltas.dns_end.GetDelta());
   EXPECT_EQ(navigation_deltas.dns_start.GetDelta(),
             navigation_deltas.connect_start.GetDelta());
   EXPECT_EQ(navigation_deltas.dns_start.GetDelta(),
             navigation_deltas.connect_end.GetDelta());
-  EXPECT_EQ(navigation_deltas.dns_start.GetDelta(),
+
+  EXPECT_LE(navigation_deltas.dns_start.GetDelta(),
             navigation_deltas.send_start.GetDelta());
 
   EXPECT_LT(navigation_deltas.send_start.GetDelta(),
             navigation_deltas.receive_headers_end.GetDelta());
   EXPECT_LT(navigation_deltas.send_start.GetDelta(),
             navigation_deltas.receive_headers_end.GetDelta());
 
   EXPECT_TRUE(navigation_deltas.ssl_start.is_null());
 }
 
 // Preconnect case with a proxy.  Connect times are all before the proxy lookup
 // finished (Or at the same time).
 IN_PROC_BROWSER_TEST_F(LoadTimingBrowserTest, PreconnectProxySsl) {
   TimingDeltas load_timing_deltas;
   load_timing_deltas.proxy_resolve_start = RelativeTime(0);
   load_timing_deltas.proxy_resolve_end = RelativeTime(100);
-  load_timing_deltas.dns_start = RelativeTime(-300);
-  load_timing_deltas.dns_end = RelativeTime(-200);
-  load_timing_deltas.connect_start = RelativeTime(-100);
+  load_timing_deltas.dns_start = RelativeTime(-3000000);
+  load_timing_deltas.dns_end = RelativeTime(-2000000);
+  load_timing_deltas.connect_start = RelativeTime(-1000000);
   load_timing_deltas.ssl_start = RelativeTime(0);
   load_timing_deltas.connect_end = RelativeTime(100);
   load_timing_deltas.send_start = RelativeTime(100);
   load_timing_deltas.send_end = RelativeTime(200);
   load_timing_deltas.receive_headers_end = RelativeTime(300);
 
   TimingDeltas navigation_deltas;
   RunTest(load_timing_deltas, &navigation_deltas);
 
   // Connect times should all be the same as proxy_end, which is also the
@@ skipping 25 matching lines @@
   // Due to potential roundoff issues, never check exact differences.
   EXPECT_LE(navigation_deltas.dns_start.GetDelta(),
             navigation_deltas.dns_end.GetDelta());
   EXPECT_LE(navigation_deltas.dns_end.GetDelta(),
             navigation_deltas.connect_start.GetDelta());
   EXPECT_LE(navigation_deltas.connect_start.GetDelta(),
             navigation_deltas.connect_end.GetDelta());
   EXPECT_LE(navigation_deltas.connect_end.GetDelta(),
             navigation_deltas.send_start.GetDelta());
   // The only times that are guaranteed to be distinct are send_start and
-  // received_headers end.
+  // received_headers_end.
   EXPECT_LT(navigation_deltas.send_start.GetDelta(),
             navigation_deltas.receive_headers_end.GetDelta());
 
   EXPECT_TRUE(navigation_deltas.ssl_start.is_null());
 }
 
 }  // namespace