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 7b4ec9b79f564571687f4697015ead4f85ba40e7..e1400d7407e9372f2ce2a320f9e6bd60651084b7 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& ipc_request_time,
+    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());
@@ -167,20 +174,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);
   }
 
@@ -269,9 +265,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,
@@ -279,7 +279,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 +292,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 +343,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;

[jar (doing other things), 2011/11/19 03:42:32]

Is this meant to be the default, and hence end_time == start_time unless we hear
more?  I'm a bit more used to setting it to TimeTicks() (null) when it is not
yet initialized, so that we can detect that state.

Why is this different?

[James Simonsen, 2011/11/23 07:06:15]

This is the default. start_time == end_time and that won't change.

These are data: URLs that we're dealing with. That means there's nothing to
fetch from the network. The body of the URL contains the resource, and we just
have to decode it.

If you look at the implementation for GetInfoFromDataURL(), it sets the request
time and response time to the same Time::Now() value. I'm just doing the same
here for TimeTicks.

     } else {
       AddRef();  // Balanced in OnCompletedRequest
       MessageLoop::current()->PostTask(FROM_HERE,
@@ -452,6 +456,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 +477,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.
@@ -511,13 +520,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");
 
@@ -594,7 +607,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 +641,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() /

[jar (doing other things), 2011/11/19 03:42:32]

Given you divide by MicrosecondsPerSecond, shouldn't this be ToMicroseconds()

[James Simonsen, 2011/11/23 07:06:15]

Done.

+          static_cast<double>(base::Time::kMicrosecondsPerSecond));
     }
   }
 
@@ -664,13 +681,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);

[jar (doing other things), 2011/11/19 03:42:32]

Here again I'm confused about both start_time and end_time being set as
identical.  What am I missing?

[James Simonsen, 2011/11/23 07:06:15]

It's a data: url. There's no downloading.

Theoretically, we could time how long it takes us to parse the url. I'm not sure
it'd be worth it though, since the time is likely insignificant. Either way,
since it'd be a change in behavior, we should do it in a separate CL.

     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 +706,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);
+  TimeTicks completion_time = TimeTicks::Now();
 
   const GURL& final_url = sync_load_response.url;
 
@@ -705,7 +726,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());
@@ -731,4 +755,206 @@ 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.

[jar (doing other things), 2011/11/19 03:42:32]

Given that "drift" is the most likely (and understandable), I'd expect your
translation to perform perfectly if only drift takes place.  I'd expect that
when a shift can accomplish everything, then the net numbers should both be
shifted together, and land nicely between (or touching) the ipc time endpoints.

 Hence I'd expect you to first slide both net times (via shifts) so that they
are both between the ipc times if possible.  If not possible, then I'd expect
both end-point net times to be simply adjusted to match the end-point ipc times
exactly, giving you the desired ordering.  

[James Simonsen, 2011/11/23 07:06:15]

Agreed. This is much better.

+namespace {
+
+class WebKitDelta {
+ public:
+  int ToWebKitTime() { return value_; }
+
+ private:
+  friend class TimeConverter;
+  friend class WebKitMilliseconds;
+
+  WebKitDelta(int value) : value_(value) {}
+
+  int value_;
+};
+
+class WebKitMilliseconds {
+ public:
+  static WebKitMilliseconds PickLowerBound(const TimeTicks& webkit_value,
+                                           const TimeTicks& net_value) {
+    int64 lower_bound = net_value.ToInternalValue();
+    if (net_value < webkit_value) {
+      lower_bound = webkit_value.ToInternalValue();
+    }
+    return WebKitMilliseconds(lower_bound);
+  }
+
+  static WebKitMilliseconds PickUpperBound(const TimeTicks& webkit_value,
+                                           const TimeTicks& net_value) {
+    int64 upper_bound = net_value.ToInternalValue();
+    if (net_value > webkit_value) {
+      upper_bound = webkit_value.ToInternalValue();
+    }
+    return WebKitMilliseconds(upper_bound);

[jar (doing other things), 2011/11/19 03:42:32]

I'm really wary that this is moving one samples in the browser space around, but
not moving the other sample in the same "shifted" way.  This seems very much at
odds with the belief that the clocks mostly skew (but don't race fast and slow
from microsecond to microsecond).

[James Simonsen, 2011/11/23 07:06:15]

Agreed. The data backs that up too. It's typically just an offset between
processes, except when one side sees a clock tick, but the other doesn't.

+  }
+
+  void EnsureLessOrEqual(const WebKitMilliseconds& limit) {
+    if (value_ > limit.value_) {
+      value_ = limit.value_;
+    }
+  }
+
+  WebKitMilliseconds operator+(const WebKitDelta& delta) {
+    return WebKitMilliseconds(value_ + delta.value_);
+  }
+
+  double ToWebKitTime() {
+    return value_ / static_cast<double>(base::Time::kMicrosecondsPerSecond);
+  }
+
+ 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) {
+    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) {
+    numerator_ = upper_bound.value_ - lower_bound.value_;
+    denominator_ = net_end_time.value_ - net_start_time.value_;
+    if (denominator_ == 0) {
+      numerator_ = 0;
+      denominator_ = 1;
+    }

[jar (doing other things), 2011/11/19 03:42:32]

I think you should use a nice affine map, including a scaling factor, and a
shifting constant.  That means you'll need to also have a member:

int64 offset_;

I think you should first make sure the pair of times have the same center (i.e.,
assume equal ipc transmission latency at for both directions).  You should then
check to see if the target range (gap between lower_bound and upper_bound) is
smaller than the domain gap (between net_start_time and net_end_time).  If they
are too far apart, then you need to scale them down.  In the best (common) case,
you'll get away with just using the offset.

For instance, the Convert() function should probably look like:

covert(int64 value) {
  return offset_ + numerator_ * value / denominator_;
}

The above constructor might then be close to:

int64 target_range = upper_bound - lower_bound;
int64 source_range = net_end_time - net_start_time;
if (source_range < target_range) {
  // We fit!  Just shift the midpoints to match.
  numerator_ = 1;
  denominator_ = 1;  // We get away with no scaling.
  offset_ = ((upper_bound + lower_bound) - (net_end_time + net_start_time)) / 2;
  return;
}
// Set up scaling factors, and then deduce shift.
numerator_ = target_range_;
denominator_ = source_range_;  // We probably need a +1 here.
// Find out what we need to shift by to make this really work.
offset_ = 0;  // Temporary value, to make converter work.
offset_ = lower_bound - Convert(net_start_time);
DCHECK_GE(upper_bound, Convert(net_end_time));
}

[James Simonsen, 2011/11/23 07:06:15]

Done with a few minor tweaks:
- Offset should not be applied to deltas.
- source_range == 0 is handled safely.
- No +1. I'm not sure why you suggested that. Can you clarify?

[jar (doing other things), 2011/11/23 17:25:04]

re: Why did I mention a +1.

This integer math stuff is hard to get right.  I was wary that when I divided,
I'd end up rounding in bad (wrong) direction... and at the time I thought you
might need a little extra wiggle room when you scaled.

To test to be sure this is all working, I'd suggest you test to see that this
stuff works correctly for source intervals:

[0, k]
having to map to intervals:
[0, m]

and try all combinations of values of k and m in, perchance, the range of 0 to
100.  In each test case the DCHECK_GE will ensure that all is as expected.

I'm probably being paranoid... and not doing my math carefully enough... but
having been burned by integer math before... I'd suggest you validate with a
quick run through such examples in your unit test.

Thinking about it now... I'm pretty convinced the math is right, and the
rounding will do the right thing... but the simple unit test wouldn't hurt...
and would make it very clear what the intent was (you might even duplicate the
DCHECK() with an EXPECT() in your test).

On 2011/11/23 07:06:15, James Simonsen wrote:

+  }
+
+  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 numerator_;
+  int64 denominator_;
+};
+
+}  // 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) {
+  // We only adjust the bounds if we have an inconsistency. Otherwise, if the
+  // |net_*| times are already within the |ipc_*| range, we leave the bounds as
+  // is. That means the times won't be adjusted. By doing so, we give the
+  // |net_*| times the benefit of the doubt and assume there was no skew.
+  WebKitMilliseconds lower_bound = WebKitMilliseconds::PickLowerBound(
+      ipc_request_time, net_start_time);
+  WebKitMilliseconds upper_bound = WebKitMilliseconds::PickUpperBound(
+      ipc_response_time, net_end_time);

[jar (doing other things), 2011/11/19 03:42:32]

This appears to broaden the interval between lower_boand and upper_bound,
translating a clock-skew into additional network-delay. 

I think you should just go ahead and use ipc_request_time as the lower bound,
and ipc_response_time as the upper bound, and map everything into that interval
with a little affine map.

[James Simonsen, 2011/11/23 07:06:15]

Done.

+  lower_bound.EnsureLessOrEqual(upper_bound);
+
+  NetMilliseconds net_start_ms = NetMilliseconds::FromTimeTicks(net_start_time);
+  NetMilliseconds net_end_ms = NetMilliseconds::FromTimeTicks(net_end_time);
+  NetMilliseconds base_ms = NetMilliseconds::FromTimeTicks(
+      net_timing_info.base_ticks);
+
+  TimeConverter time_converter(lower_bound, upper_bound,
+                               net_start_ms, net_end_ms);
+
+  WebURLLoadTiming timing;
+  timing.initialize();
+
+  WebKitMilliseconds adjusted_base = lower_bound +
+      time_converter.ConvertDelta(base_ms - net_start_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