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 9e7c3eb3570e4ee295e2059e42ff5803974b905a..aed207b769f9271bbbc07d079491bdc429c20ccd 100644
--- a/webkit/glue/weburlloader_impl.cc
+++ b/webkit/glue/weburlloader_impl.cc
@@ -36,6 +36,7 @@
 
 using base::Time;
 using base::TimeDelta;
+using base::TimeTicks;
 using WebKit::WebData;
 using WebKit::WebHTTPBody;
 using WebKit::WebHTTPHeaderVisitor;
@@ -114,7 +115,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)) {
@@ -122,6 +124,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;
@@ -144,6 +147,10 @@ typedef ResourceDevToolsInfo::HeadersVector HeadersVector;
 void PopulateURLResponse(
     const GURL& url,
     const ResourceResponseInfo& info,
+    const TimeTicks& ipc_request_time,

[darin (slow to review), 2011/12/06 01:06:32]

This file should not know anything about IPC.  Perhaps some of this code should
move to the IPCResourceLoaderBridge level?  Or, maybe you can get by with
renaming these fields?

[James Simonsen, 2011/12/10 00:21:47]

Yeah, good point. Thanks. I went with the former. It makes a lot more sense and
simplified the code a lot.

+    const TimeTicks& net_start_time,
+    const TimeTicks& net_end_time,
+    const TimeTicks& ipc_response_time,
     WebURLResponse* response) {
   response->setURL(url);
   response->setResponseTime(info.response_time.ToDoubleT());
@@ -169,20 +176,9 @@ 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, ipc_request_time, net_start_time, net_end_time,
+        ipc_response_time);
     response->setLoadTiming(timing);
   }
 
@@ -272,9 +268,13 @@ class WebURLLoaderImpl::Context : public base::RefCounted<Context>,
   virtual bool OnReceivedRedirect(
       const GURL& new_url,
       const ResourceResponseInfo& info,
+      const TimeTicks& net_start_time,
+      const TimeTicks& net_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& net_start_time,
+                                  const TimeTicks& net_end_time);
   virtual void OnDownloadedData(int len);
   virtual void OnReceivedData(const char* data,
                               int data_length,
@@ -282,7 +282,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>;
@@ -295,6 +295,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_;
@@ -346,9 +347,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->net_start_time = response_time;
+      sync_load_response->net_end_time = response_time;
     } else {
       AddRef();  // Balanced in OnCompletedRequest
       MessageLoop::current()->PostTask(FROM_HERE,
@@ -456,6 +460,7 @@ void WebURLLoaderImpl::Context::Start(
     bridge_->SetUploadIdentifier(request.httpBody().identifier());
   }
 
+  initiation_time_ = TimeTicks::Now();
   if (sync_load_response) {
     bridge_->SyncLoad(sync_load_response);
     return;
@@ -476,14 +481,18 @@ void WebURLLoaderImpl::Context::OnUploadProgress(uint64 position, uint64 size) {
 bool WebURLLoaderImpl::Context::OnReceivedRedirect(
     const GURL& new_url,
     const ResourceResponseInfo& info,
+    const TimeTicks& net_start_time,
+    const TimeTicks& net_end_time,
     bool* has_new_first_party_for_cookies,
     GURL* new_first_party_for_cookies) {
   if (!client_)
     return false;
 
+  TimeTicks ipc_response_time = TimeTicks::Now();
   WebURLResponse response;
   response.initialize();
-  PopulateURLResponse(request_.url(), info, &response);
+  PopulateURLResponse(request_.url(), info, initiation_time_, net_start_time,
+                      net_end_time, ipc_response_time, &response);
 
   // TODO(darin): We lack sufficient information to construct the actual
   // request that resulted from the redirect.
@@ -515,13 +524,17 @@ bool WebURLLoaderImpl::Context::OnReceivedRedirect(
 }
 
 void WebURLLoaderImpl::Context::OnReceivedResponse(
-    const ResourceResponseInfo& info) {
+    const ResourceResponseInfo& info,
+    const TimeTicks& net_start_time,
+    const TimeTicks& net_end_time) {
   if (!client_)
     return;
 
+  TimeTicks ipc_response_time = TimeTicks::Now();
   WebURLResponse response;
   response.initialize();
-  PopulateURLResponse(request_.url(), info, &response);
+  PopulateURLResponse(request_.url(), info, initiation_time_, net_start_time,
+                      net_end_time, ipc_response_time, &response);
 
   bool show_raw_listing = (GURL(request_.url()).query() == "raw");
 
@@ -598,7 +611,9 @@ void WebURLLoaderImpl::Context::OnReceivedCachedMetadata(
 void WebURLLoaderImpl::Context::OnCompletedRequest(
     const net::URLRequestStatus& original_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);
@@ -640,7 +655,9 @@ void WebURLLoaderImpl::Context::OnCompletedRequest(
       error.unreachableURL = request_.url();
       client_->didFail(loader_, error);
     } else {
-      client_->didFinishLoading(loader_, completion_time.ToDoubleT());
+      client_->didFinishLoading(
+          loader_, static_cast<double>(

[darin (slow to review), 2011/12/06 01:06:32]

Should TimeDelta have a InMicrosecondsF() method?

[James Simonsen, 2011/12/10 00:21:47]

Not sure what I was thinking. This should be in seconds, since that's all WebKit
uses. Fixed now.

+              (completion_time - TimeTicks()).InMicroseconds()));
     }
   }
 
@@ -678,13 +695,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 -----------------------------------------------------------
@@ -702,8 +721,10 @@ void WebURLLoaderImpl::loadSynchronously(const WebURLRequest& request,
                                          WebURLResponse& response,
                                          WebURLError& error,
                                          WebData& data) {
+  TimeTicks ipc_request_time = TimeTicks::Now();
   ResourceLoaderBridge::SyncLoadResponse sync_load_response;
   context_->Start(request, &sync_load_response, platform_);
+  TimeTicks completion_time = TimeTicks::Now();
 
   const GURL& final_url = sync_load_response.url;
 
@@ -720,7 +741,10 @@ void WebURLLoaderImpl::loadSynchronously(const WebURLRequest& request,
     return;
   }
 
-  PopulateURLResponse(final_url, sync_load_response, &response);
+  PopulateURLResponse(final_url, sync_load_response, ipc_request_time,
+                      sync_load_response.net_start_time,
+                      sync_load_response.net_end_time, completion_time,
+                      &response);
 
   data.assign(sync_load_response.data.data(),
               sync_load_response.data.size());
@@ -746,4 +770,202 @@ void WebURLLoaderImpl::UpdateRoutingId(int new_routing_id) {
   context_->UpdateRoutingId(new_routing_id);
 }
 
+// |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.
+//
+// Our goal is to present monotonically increasing timestamps to WebKit. So we
+// must fit the network layer's timestamps into WebKit's timeline. If we don't
+// correct for this skew, then we may report anomolies, such as negative page
+// load times, to developer tools and analytics scripts.
+//
+// To correct for this skew, we record 4 times:
+// - |ipc_request_time|: when this process passed the request on to the network
+//                       layer.
+// - |net_start_time|: when the network layer (other process) started handling
+//                     the request.
+// - |net_end_time|: when the network layer finished the request.
+// - |ipc_response_time|: when this process received the response from the
+//                        network layer.
+//
+// Because of the monotonic clock, all members of |timing_info| will occur
+// between |net_start_time| and |net_end_time|. If |net_start_time| and/or
+// |net_end_time| are out of order wrt |ipc_request_time| and
+// |ipc_response_time|, then we adjust the bounds to fit within
+// |ipc_request_time| and |ipc_response_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 |net_start_time| and |net_end_time| as they were before
+// adjustment.
+//
+// In addition to this, we always shift the |net_*| times so that the |net_*|
+// range is centered with |ipc_*| range.
+namespace {
+
+class WebKitDelta {

[darin (slow to review), 2011/12/06 01:06:32]

It might help to factor out this code into a separate file.  This all feels like
code that belongs in src/content/ instead of src/webkit/glue/ as this is all
about multi-process details.

+ public:
+  int ToWebKitTime() { return value_; }
+
+ private:
+  friend class TimeConverter;
+  friend class WebKitMilliseconds;
+
+  WebKitDelta(int value) : value_(value) {}
+
+  int value_;
+};
+
+class WebKitMilliseconds {
+ public:
+  static WebKitMilliseconds FromTimeTicks(const TimeTicks& value) {
+    return WebKitMilliseconds(value.ToInternalValue());
+  }
+
+  double ToWebKitTime() {
+    return value_ / static_cast<double>(base::Time::kMicrosecondsPerSecond);
+  }
+
+  WebKitMilliseconds operator+(const WebKitDelta& delta) {
+    return WebKitMilliseconds(value_ + delta.value_);
+  }
+
+ private:
+  friend class TimeConverter;
+
+  WebKitMilliseconds(int64 value) : value_(value) {}
+
+  int64 value_;
+};
+
+class NetDelta {
+ public:
+  static NetDelta FromRawDelta(int delta) {
+    return NetDelta(delta);
+  }
+
+ private:
+  friend class NetMilliseconds;
+  friend class TimeConverter;
+
+  NetDelta(int value) : value_(value) {}
+
+  int value_;
+};
+
+class NetMilliseconds {
+ public:
+  static NetMilliseconds FromTimeTicks(const TimeTicks& ticks) {
+    return NetMilliseconds(ticks.ToInternalValue());
+  }
+
+  NetDelta operator-(const NetMilliseconds& rhs) const {
+    return NetDelta(value_ - rhs.value_);
+  }
+
+ private:
+  friend class TimeConverter;
+
+  NetMilliseconds(int64 value) : value_(value) {}
+
+  int64 value_;
+};
+
+class TimeConverter {
+ public:
+  TimeConverter(const WebKitMilliseconds& lower_bound,
+                const WebKitMilliseconds& upper_bound,
+                const NetMilliseconds& net_start_time,
+                const NetMilliseconds& net_end_time)
+      : net_start_time_(net_start_time) {
+    int64 target_range = upper_bound.value_ - lower_bound.value_;
+    int64 source_range = net_end_time.value_ - net_start_time.value_;
+    if (source_range <= target_range) {
+      // We fit!  Just shift the midpoints to match.
+      numerator_ = 1;
+      denominator_ = 1;
+      offset_ = ((upper_bound.value_ + lower_bound.value_) -
+                 (net_end_time.value_ + net_start_time.value_)) / 2;
+      return;
+    }
+    // Set up scaling factors, and then deduce shift.
+    numerator_ = target_range;
+    denominator_ = source_range;
+    // Find out what we need to shift by to make this really work.
+    offset_ = lower_bound.value_ - Convert(net_start_time.value_);
+    DCHECK_GE(upper_bound.value_, Convert(net_end_time.value_));
+  }
+
+  WebKitMilliseconds ConvertMilliseconds(const NetMilliseconds& net_ms) {
+    NetDelta net_delta = net_ms - net_start_time_;
+    return WebKitMilliseconds(net_start_time_.value_ + offset_ +
+                              ConvertDelta(net_delta).value_);
+  }
+
+  WebKitDelta ConvertDelta(const NetDelta& net_delta) {
+    return WebKitDelta(Convert(net_delta.value_));
+  }
+
+ private:
+  int64 Convert(int64 value) {
+    if (value <= 0) {
+      return value;
+    }
+    return numerator_ * value / denominator_;
+  }
+
+  int64 offset_;
+  int64 numerator_;
+  int64 denominator_;
+  NetMilliseconds net_start_time_;
+};
+
+}  // anonymous namespace
+
+WebURLLoadTiming PopulateWebURLLoadTiming(
+    const ResourceLoadTimingInfo& net_timing_info,
+    const TimeTicks& ipc_request_time,
+    const TimeTicks& net_start_time,
+    const TimeTicks& net_end_time,
+    const TimeTicks& ipc_response_time) {
+  WebKitMilliseconds lower_bound = WebKitMilliseconds::FromTimeTicks(
+      ipc_request_time);
+  WebKitMilliseconds upper_bound = WebKitMilliseconds::FromTimeTicks(
+      ipc_response_time);
+  NetMilliseconds net_start_ms = NetMilliseconds::FromTimeTicks(net_start_time);
+  NetMilliseconds net_end_ms = NetMilliseconds::FromTimeTicks(net_end_time);
+
+  TimeConverter time_converter(lower_bound, upper_bound,
+                               net_start_ms, net_end_ms);
+
+  WebURLLoadTiming timing;
+  timing.initialize();
+
+  NetMilliseconds base_ms = NetMilliseconds::FromTimeTicks(
+      net_timing_info.base_ticks);
+  WebKitMilliseconds adjusted_base =
+      time_converter.ConvertMilliseconds(base_ms);
+  timing.setRequestTime(adjusted_base.ToWebKitTime());
+
+#define SET_TIME(setter, value) \
+  setter(time_converter.ConvertDelta(NetDelta::FromRawDelta(value)) \
+         .ToWebKitTime())
+
+  SET_TIME(timing.setProxyStart, net_timing_info.proxy_start);
+  SET_TIME(timing.setProxyEnd, net_timing_info.proxy_end);
+  SET_TIME(timing.setDNSStart, net_timing_info.dns_start);
+  SET_TIME(timing.setDNSEnd, net_timing_info.dns_end);
+  SET_TIME(timing.setConnectStart, net_timing_info.connect_start);
+  SET_TIME(timing.setConnectEnd, net_timing_info.connect_end);
+  SET_TIME(timing.setSSLStart, net_timing_info.ssl_start);
+  SET_TIME(timing.setSSLEnd, net_timing_info.ssl_end);
+  SET_TIME(timing.setSendStart, net_timing_info.send_start);
+  SET_TIME(timing.setSendEnd, net_timing_info.send_end);
+  SET_TIME(timing.setReceiveHeadersEnd, net_timing_info.receive_headers_end);
+
+#undef SET_TIME
+
+  return timing;
+}
+
 }  // namespace webkit_glue