Use a monotonic clock (TimeTicks) to report network times to WebCore.

webkit/glue/weburlloader_impl.cc

Index: webkit/glue/weburlloader_impl.cc
diff --git a/webkit/glue/weburlloader_impl.cc b/webkit/glue/weburlloader_impl.cc
index ad28f41c5bcd7392aa054ca950e2b151e24d6a99..6dcd1aaea1a727307133fea96f771c57454565e6 100644
--- a/webkit/glue/weburlloader_impl.cc
+++ b/webkit/glue/weburlloader_impl.cc
@@ -34,6 +34,7 @@
 
 using base::Time;
 using base::TimeDelta;
+using base::TimeTicks;
 using WebKit::WebData;
 using WebKit::WebHTTPBody;
 using WebKit::WebHTTPHeaderVisitor;
@@ -112,7 +113,8 @@ class HeaderFlattener : public WebHTTPHeaderVisitor {
 bool GetInfoFromDataURL(const GURL& url,
                         ResourceResponseInfo* info,
                         std::string* data,
-                        net::URLRequestStatus* status) {
+                        net::URLRequestStatus* status,
+                        TimeTicks* response_time) {
   std::string mime_type;
   std::string charset;
   if (net::DataURL::Parse(url, &mime_type, &charset, data)) {
@@ -120,6 +122,7 @@ bool GetInfoFromDataURL(const GURL& url,
     // Assure same time for all time fields of data: URLs.
     Time now = Time::Now();
     info->load_timing.base_time = now;
+    info->load_timing.base_ticks = *response_time = TimeTicks::Now();
     info->request_time = now;
     info->response_time = now;
     info->headers = NULL;
@@ -142,6 +145,10 @@ typedef ResourceDevToolsInfo::HeadersVector HeadersVector;
 void PopulateURLResponse(
     const GURL& url,
     const ResourceResponseInfo& info,
+    const TimeTicks& initiation_time,
+    const TimeTicks& start_time,
+    const TimeTicks& end_time,
+    const TimeTicks& callback_time,
     WebURLResponse* response) {
   response->setURL(url);
   response->setResponseTime(info.response_time.ToDoubleT());
@@ -167,20 +174,8 @@ void PopulateURLResponse(
 
   const ResourceLoadTimingInfo& timing_info = info.load_timing;
   if (!timing_info.base_time.is_null()) {
-    WebURLLoadTiming timing;
-    timing.initialize();
-    timing.setRequestTime(timing_info.base_time.ToDoubleT());
-    timing.setProxyStart(timing_info.proxy_start);
-    timing.setProxyEnd(timing_info.proxy_end);
-    timing.setDNSStart(timing_info.dns_start);
-    timing.setDNSEnd(timing_info.dns_end);
-    timing.setConnectStart(timing_info.connect_start);
-    timing.setConnectEnd(timing_info.connect_end);
-    timing.setSSLStart(timing_info.ssl_start);
-    timing.setSSLEnd(timing_info.ssl_end);
-    timing.setSendStart(timing_info.send_start);
-    timing.setSendEnd(timing_info.send_end);
-    timing.setReceiveHeadersEnd(timing_info.receive_headers_end);
+    WebURLLoadTiming timing = PopulateWebURLLoadTiming(
+        timing_info, initiation_time, start_time, end_time, callback_time);
     response->setLoadTiming(timing);
   }
 
@@ -269,9 +264,13 @@ class WebURLLoaderImpl::Context : public base::RefCounted<Context>,
   virtual bool OnReceivedRedirect(
       const GURL& new_url,
       const ResourceResponseInfo& info,
+      const TimeTicks& start_time,
+      const TimeTicks& end_time,
       bool* has_new_first_party_for_cookies,
       GURL* new_first_party_for_cookies);
-  virtual void OnReceivedResponse(const ResourceResponseInfo& info);
+  virtual void OnReceivedResponse(const ResourceResponseInfo& info,
+                                  const TimeTicks& start_time,
+                                  const TimeTicks& end_time);
   virtual void OnDownloadedData(int len);
   virtual void OnReceivedData(const char* data,
                               int data_length,
@@ -279,7 +278,7 @@ class WebURLLoaderImpl::Context : public base::RefCounted<Context>,
   virtual void OnReceivedCachedMetadata(const char* data, int len);
   virtual void OnCompletedRequest(const net::URLRequestStatus& status,
                                   const std::string& security_info,
-                                  const base::Time& completion_time);
+                                  const TimeTicks& completion_time);
 
  private:
   friend class base::RefCounted<Context>;
@@ -292,6 +291,7 @@ class WebURLLoaderImpl::Context : public base::RefCounted<Context>,
   WebURLLoaderImpl* loader_;
   WebURLRequest request_;
   WebURLLoaderClient* client_;
+  TimeTicks initiation_time_;
   scoped_ptr<ResourceLoaderBridge> bridge_;
   scoped_ptr<FtpDirectoryListingResponseDelegate> ftp_listing_delegate_;
   scoped_ptr<MultipartResponseDelegate> multipart_delegate_;
@@ -342,9 +342,12 @@ void WebURLLoaderImpl::Context::Start(
       // This is a sync load. Do the work now.
       sync_load_response->url = url;
       std::string data;
+      TimeTicks response_time;
       GetInfoFromDataURL(sync_load_response->url, sync_load_response,
                          &sync_load_response->data,
-                         &sync_load_response->status);
+                         &sync_load_response->status, &response_time);
+      sync_load_response->start_time = response_time;
+      sync_load_response->end_time = response_time;
     } else {
       AddRef();  // Balanced in OnCompletedRequest
       MessageLoop::current()->PostTask(FROM_HERE,
@@ -452,6 +455,7 @@ void WebURLLoaderImpl::Context::Start(
     bridge_->SetUploadIdentifier(request.httpBody().identifier());
   }
 
+  initiation_time_ = TimeTicks::Now();
   if (sync_load_response) {
     bridge_->SyncLoad(sync_load_response);
     return;
@@ -472,14 +476,18 @@ void WebURLLoaderImpl::Context::OnUploadProgress(uint64 position, uint64 size) {
 bool WebURLLoaderImpl::Context::OnReceivedRedirect(
     const GURL& new_url,
     const ResourceResponseInfo& info,
+    const TimeTicks& start_time,
+    const TimeTicks& end_time,
     bool* has_new_first_party_for_cookies,
     GURL* new_first_party_for_cookies) {
   if (!client_)
     return false;
 
+  TimeTicks callback_time = TimeTicks::Now();
   WebURLResponse response;
   response.initialize();
-  PopulateURLResponse(request_.url(), info, &response);
+  PopulateURLResponse(request_.url(), info, initiation_time_, start_time,
+                      end_time, callback_time, &response);
 
   // TODO(darin): We lack sufficient information to construct the actual
   // request that resulted from the redirect.
@@ -511,13 +519,17 @@ bool WebURLLoaderImpl::Context::OnReceivedRedirect(
 }
 
 void WebURLLoaderImpl::Context::OnReceivedResponse(
-    const ResourceResponseInfo& info) {
+    const ResourceResponseInfo& info,
+    const TimeTicks& start_time,
+    const TimeTicks& end_time) {
   if (!client_)
     return;
 
+  TimeTicks callback_time = TimeTicks::Now();
   WebURLResponse response;
   response.initialize();
-  PopulateURLResponse(request_.url(), info, &response);
+  PopulateURLResponse(request_.url(), info, initiation_time_, start_time,
+                      end_time, callback_time, &response);
 
   bool show_raw_listing = (GURL(request_.url()).query() == "raw");
 
@@ -594,7 +606,9 @@ void WebURLLoaderImpl::Context::OnReceivedCachedMetadata(
 void WebURLLoaderImpl::Context::OnCompletedRequest(
     const net::URLRequestStatus& status,
     const std::string& security_info,
-    const base::Time& completion_time) {
+    const TimeTicks& completion_time) {
+  TimeTicks monotonic_completion_time = std::min(completion_time,
+                                                 TimeTicks::Now());
   if (ftp_listing_delegate_.get()) {
     ftp_listing_delegate_->OnCompletedRequest();
     ftp_listing_delegate_.reset(NULL);
@@ -626,7 +640,9 @@ void WebURLLoaderImpl::Context::OnCompletedRequest(
       error.unreachableURL = request_.url();
       client_->didFail(loader_, error);
     } else {
-      client_->didFinishLoading(loader_, completion_time.ToDoubleT());
+      client_->didFinishLoading(
+          loader_, completion_time.ToInternalValue() /
+          static_cast<double>(base::Time::kMicrosecondsPerSecond));
     }
   }
 
@@ -664,13 +680,15 @@ void WebURLLoaderImpl::Context::HandleDataURL() {
   net::URLRequestStatus status;
   std::string data;
 
-  if (GetInfoFromDataURL(request_.url(), &info, &data, &status)) {
-    OnReceivedResponse(info);
+  TimeTicks response_time;
+  if (GetInfoFromDataURL(request_.url(), &info, &data, &status,
+                         &response_time)) {
+    OnReceivedResponse(info, response_time, response_time);
     if (!data.empty())
       OnReceivedData(data.data(), data.size(), 0);
   }
 
-  OnCompletedRequest(status, info.security_info, base::Time::Now());
+  OnCompletedRequest(status, info.security_info, TimeTicks::Now());
 }
 
 // WebURLLoaderImpl -----------------------------------------------------------
@@ -687,8 +705,10 @@ void WebURLLoaderImpl::loadSynchronously(const WebURLRequest& request,
                                          WebURLResponse& response,
                                          WebURLError& error,
                                          WebData& data) {
+  TimeTicks initiation_time = TimeTicks::Now();
   ResourceLoaderBridge::SyncLoadResponse sync_load_response;
   context_->Start(request, &sync_load_response);
+  TimeTicks completion_time = TimeTicks::Now();
 
   const GURL& final_url = sync_load_response.url;
 
@@ -705,7 +725,9 @@ void WebURLLoaderImpl::loadSynchronously(const WebURLRequest& request,
     return;
   }
 
-  PopulateURLResponse(final_url, sync_load_response, &response);
+  PopulateURLResponse(final_url, sync_load_response, initiation_time,
+                      sync_load_response.start_time,
+                      sync_load_response.end_time, completion_time, &response);
 
   data.assign(sync_load_response.data.data(),
               sync_load_response.data.size());
@@ -731,4 +753,93 @@ void WebURLLoaderImpl::UpdateRoutingId(int new_routing_id) {
   context_->UpdateRoutingId(new_routing_id);
 }
 
+int64 CorrectTime(int64 raw_time, int64 numerator, int64 denominator) {
+  if (raw_time <= 0) {
+    return raw_time;
+  }
+  return numerator * raw_time / denominator;
+}
+
+// |timing_info| originates in the network layer, which may live in another
+// (browser) process. These values are recorded and passed as TimeTicks. On
+// Windows, TimeTicks do not tick consistently across processes. So one process
+// may be slightly ahead of the other and the delta between them may drift. In
+// practice, they usually differ by a few ms or less, and never more than 10 ms.

[jar (doing other things), 2011/10/15 02:42:13]

Since a common resolution is 15ms. The drift at any instance is commonly 15ms no
matter what.  I don't see how they could be less (when they differ) unless we're
in a higher-res mode.

[James Simonsen, 2011/10/18 23:15:47]

We use timeGetTime() on Windows, which attempts to interpolate time to a
sub-millisecond resolution. IMO, it's this interpolation that skews between
processes. Other timers, such as GetTickCount(), only have 15ms resolution and
don't skew. For more info, feel free to read the earlier messages on this code
review.

[jar (doing other things), 2011/11/08 03:42:49]

timeGetTime() returns a DWORD, which is in units of milliseconds.  How does that
"interpolate" to a sub-millisecond time??

+//
+// To make things consistent for WebKit, we must correct for this cross-process
+// skew. To do this, we record 4 times:
+// - |initiation_time|: when this process started handling the request.

[jar (doing other things), 2011/10/15 02:42:13]

Is this when you *tried* to contact the browser process?  Or is it when you (for
instance) got a click, and started to unload a previous page?

[James Simonsen, 2011/10/18 23:15:47]

The former. I've updated the comment.

+// - |start_time|: when the network layer (other process) started handling it.
+// - |end_time|: when the network layer finished the request.
+// - |callback_time|: when this process received the response from the network
+//                    layer.
+// Because of the monotonic clock, all members of |timing_info| will occur
+// between start_time and end_time. If |start_time| and/or |end_time| are out of
+// order wrt |initiation_time| and |callback_time|, then we adjust the bounds to
+// fit within |initiation_time| and |callback_time|. When the bounds are
+// adjusted, we scale all of the members of |timing_info| so that they are
+// relatively the same time delta from |start_time| and |end_time| as they were
+// before adjustment.

[jar (doing other things), 2011/10/15 02:42:13]

I'm still trying to understand the goal.  Is the goal to have times represented
in the renderer process as having been taken from the browser process
time-space?
What is the comparisons that "need to be consistent" so that I can judge the
value of what you're doing here?

What is the impact of rounding error?  What is the impact of error in the
numerator or denominator?

[James Simonsen, 2011/10/18 23:15:47]

I think we're talking about the same thing, but I'll rephrase it myself to be
sure...

Network times are recorded in the browser process. They're reported in the
renderer process. We want to make sure that the reported times occur in the
correct order relative to other events on the renderer's timeline.

I've added a better explanation to the code too.
The main use case I'm addressing is Navigation Timing. This W3C spec's goal is
to expose more detailed timing information to site authors via analytics
scripts. It's exposed as window.performance.timing in Javascript. We've had it
in Chrome since ~M11.

The problem is that we've received many bug reports about anomalies. For
instance, a responseEnd occurring before a responseStart. Other browsers have
had similar problems, so the Navigation Timing spec now requires the use of a
monotonic clock.

I've improved the comments to reflect this.

For the record, my primary concern is reporting events monotonically. My
secondary concern is making a reasonable effort to report accurate timing
information. I've tried to do both here.
It's hard to say. We have two independent observers of time that disagree with
each other. It's impossible to say which is right or by how much. Given that, I
don't know how we can quantify error.

+WebURLLoadTiming PopulateWebURLLoadTiming(
+    const ResourceLoadTimingInfo& timing_info,
+    const TimeTicks& initiation_time,
+    const TimeTicks& start_time,
+    const TimeTicks& end_time,
+    const TimeTicks& callback_time) {
+  int64 lower_bound = start_time.ToInternalValue();

[jar (doing other things), 2011/10/15 02:42:13]

nit: better might be 
int64 lower_bound = 
    std::min(start_time, initiation_time).ToInternalValue();

[James Simonsen, 2011/10/18 23:15:47]

That has a slightly different meaning.

The current code gives the network time the benefit of the doubt. If it's
already consistent with the renderer, leave it alone. If it's obviously
out-of-order, then we try to fix it.

+  if (start_time < initiation_time) {
+    lower_bound = initiation_time.ToInternalValue();
+  }
+  int64 upper_bound = end_time.ToInternalValue();
+  if (end_time > callback_time) {
+    upper_bound = callback_time.ToInternalValue();
+  }
+  if (lower_bound > upper_bound) {
+    lower_bound = upper_bound;
+  }
+
+  int64 numerator = upper_bound - lower_bound;
+  int64 denominator = (end_time - start_time).ToInternalValue();

[jar (doing other things), 2011/10/15 02:42:13]

Hmm... with a common 15ms granularity, I would assume that it would indeed be
comon that one or both of numerator and denominator are zero.

That said, other common differences will be 15ms and 30ms (min to max).

We do run in higher res modes sometimes, but (I think) always vanilla 15ms while
on battery power (for example).

[James Simonsen, 2011/10/18 23:15:47]

As above, we do get higher resolution numbers.

Also, keep in mind that initiation_time to callback_time spans the entire HTTP
request & response. For most resources on the internet, that's likely to be many
tens or hundreds of milliseconds.

+  if (denominator == 0) {
+    numerator = 0;
+    denominator = 1;
+  }
+
+  int64 adjusted_base =
+      lower_bound +
+      numerator *
+      (timing_info.base_ticks - start_time).ToInternalValue() /
+      denominator;
+
+  WebURLLoadTiming timing;
+  timing.initialize();
+  timing.setRequestTime(
+      adjusted_base /
+      static_cast<double>(base::Time::kMicrosecondsPerSecond));
+  timing.setProxyStart(
+      CorrectTime(timing_info.proxy_start, numerator, denominator));
+  timing.setProxyEnd(
+      CorrectTime(timing_info.proxy_end, numerator, denominator));
+  timing.setDNSStart(
+      CorrectTime(timing_info.dns_start, numerator, denominator));
+  timing.setDNSEnd(
+      CorrectTime(timing_info.dns_end, numerator, denominator));
+  timing.setConnectStart(
+      CorrectTime(timing_info.connect_start, numerator, denominator));
+  timing.setConnectEnd(
+      CorrectTime(timing_info.connect_end, numerator, denominator));
+  timing.setSSLStart(
+      CorrectTime(timing_info.ssl_start, numerator, denominator));
+  timing.setSSLEnd(
+      CorrectTime(timing_info.ssl_end, numerator, denominator));
+  timing.setSendStart(
+      CorrectTime(timing_info.send_start, numerator, denominator));
+  timing.setSendEnd(
+      CorrectTime(timing_info.send_end, numerator, denominator));
+  timing.setReceiveHeadersEnd(
+      CorrectTime(timing_info.receive_headers_end, numerator, denominator));
+
+  return timing;
+}
+
 }  // namespace webkit_glue