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

webkit/glue/weburlloader_impl.cc

 // Copyright (c) 2011 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.
 
 // An implementation of WebURLLoader in terms of ResourceLoaderBridge.
 
 #include "webkit/glue/weburlloader_impl.h"
 
 #include "base/file_path.h"
 #include "base/memory/scoped_ptr.h"
@@ skipping 16 matching lines @@
 #include "third_party/WebKit/Source/WebKit/chromium/public/WebURLLoaderClient.h"
 #include "third_party/WebKit/Source/WebKit/chromium/public/WebURLRequest.h"
 #include "third_party/WebKit/Source/WebKit/chromium/public/WebURLResponse.h"
 #include "webkit/glue/ftp_directory_listing_response_delegate.h"
 #include "webkit/glue/multipart_response_delegate.h"
 #include "webkit/glue/resource_loader_bridge.h"
 #include "webkit/glue/webkit_glue.h"
 
 using base::Time;
 using base::TimeDelta;
+using base::TimeTicks;
 using WebKit::WebData;
 using WebKit::WebHTTPBody;
 using WebKit::WebHTTPHeaderVisitor;
 using WebKit::WebHTTPLoadInfo;
 using WebKit::WebSecurityPolicy;
 using WebKit::WebString;
 using WebKit::WebURL;
 using WebKit::WebURLError;
 using WebKit::WebURLLoadTiming;
 using WebKit::WebURLLoader;
@@ skipping 58 matching lines @@
  private:
   int load_flags_;
   std::string buffer_;
   bool has_accept_header_;
 };
 
 // Extracts the information from a data: url.
 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)) {
     *status = net::URLRequestStatus(net::URLRequestStatus::SUCCESS, 0);
     // 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;
     info->mime_type.swap(mime_type);
     info->charset.swap(charset);
     info->security_info.clear();
     info->content_length = -1;
     info->encoded_data_length = 0;
 
     return true;
   }
 
   *status = net::URLRequestStatus(net::URLRequestStatus::FAILED,
                                   net::ERR_INVALID_URL);
   return false;
 }
 
 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());
   response->setMIMEType(WebString::fromUTF8(info.mime_type));
   response->setTextEncodingName(WebString::fromUTF8(info.charset));
   response->setExpectedContentLength(info.content_length);
   response->setSecurityInfo(info.security_info);
   response->setAppCacheID(info.appcache_id);
   response->setAppCacheManifestURL(info.appcache_manifest_url);
   response->setWasCached(!info.load_timing.base_time.is_null() &&
       info.response_time < info.load_timing.base_time);
   response->setWasFetchedViaSPDY(info.was_fetched_via_spdy);
   response->setWasNpnNegotiated(info.was_npn_negotiated);
   response->setWasAlternateProtocolAvailable(
       info.was_alternate_protocol_available);
   response->setWasFetchedViaProxy(info.was_fetched_via_proxy);
   response->setRemoteIPAddress(
       WebString::fromUTF8(info.socket_address.host()));
   response->setRemotePort(info.socket_address.port());
   response->setConnectionID(info.connection_id);
   response->setConnectionReused(info.connection_reused);
   response->setDownloadFilePath(FilePathToWebString(info.download_file_path));
 
   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);
   }
 
   if (info.devtools_info.get()) {
     WebHTTPLoadInfo load_info;
 
     load_info.setHTTPStatusCode(info.devtools_info->http_status_code);
     load_info.setHTTPStatusText(WebString::fromUTF8(
         info.devtools_info->http_status_text));
     load_info.setEncodedDataLength(info.encoded_data_length);
@@ skipping 68 matching lines @@
   void Start(
       const WebURLRequest& request,
       ResourceLoaderBridge::SyncLoadResponse* sync_load_response);
   void UpdateRoutingId(int new_routing_id);
 
   // ResourceLoaderBridge::Peer methods:
   virtual void OnUploadProgress(uint64 position, uint64 size);
   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,
                               int encoded_data_length);
   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>;
   ~Context() {}
 
   // We can optimize the handling of data URLs in most cases.
   bool CanHandleDataURL(const GURL& url) const;
   void HandleDataURL();
 
   WebURLLoaderImpl* loader_;
   WebURLRequest request_;
   WebURLLoaderClient* client_;
+  TimeTicks initiation_time_;
   scoped_ptr<ResourceLoaderBridge> bridge_;
   scoped_ptr<FtpDirectoryListingResponseDelegate> ftp_listing_delegate_;
   scoped_ptr<MultipartResponseDelegate> multipart_delegate_;
   scoped_ptr<ResourceLoaderBridge> completed_bridge_;
 };
 
 WebURLLoaderImpl::Context::Context(WebURLLoaderImpl* loader)
     : loader_(loader),
       client_(NULL) {
 }
@@ skipping 30 matching lines @@
   DCHECK(!bridge_.get());
 
   request_ = request;  // Save the request.
 
   GURL url = request.url();
   if (url.SchemeIs("data") && CanHandleDataURL(url)) {
     if (sync_load_response) {
       // 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,
           NewRunnableMethod(this, &Context::HandleDataURL));
     }
     return;
   }
 
   GURL referrer_url(
       request.httpHeaderField(WebString::fromUTF8("Referer")).utf8());
@@ skipping 87 matching lines @@
         case WebHTTPBody::Element::TypeBlob:
           bridge_->AppendBlobToUpload(GURL(element.blobURL));
           break;
         default:
           NOTREACHED();
       }
     }
     bridge_->SetUploadIdentifier(request.httpBody().identifier());
   }
 
+  initiation_time_ = TimeTicks::Now();
   if (sync_load_response) {
     bridge_->SyncLoad(sync_load_response);
     return;
   }
 
   if (bridge_->Start(this)) {
     AddRef();  // Balanced in OnCompletedRequest
   } else {
     bridge_.reset();
   }
 }
 
 void WebURLLoaderImpl::Context::OnUploadProgress(uint64 position, uint64 size) {
   if (client_)
     client_->didSendData(loader_, position, 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.
   WebURLRequest new_request(new_url);
   new_request.setFirstPartyForCookies(request_.firstPartyForCookies());
   new_request.setDownloadToFile(request_.downloadToFile());
 
   WebString referrer_string = WebString::fromUTF8("Referer");
   WebString referrer = request_.httpHeaderField(referrer_string);
   if (!WebSecurityPolicy::shouldHideReferrer(new_url, referrer))
@@ skipping 11 matching lines @@
   if (new_url == GURL(new_request.url()))
     return true;
 
   // We assume that WebKit only changes the URL to suppress a redirect, and we
   // assume that it does so by setting it to be invalid.
   DCHECK(!new_request.url().isValid());
   return false;
 }
 
 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");
 
   if (info.mime_type == "text/vnd.chromium.ftp-dir") {
     if (show_raw_listing) {
       // Set the MIME type to plain text to prevent any active content.
       response.setMIMEType("text/plain");
     } else {
       // We're going to produce a parsed listing in HTML.
       response.setMIMEType("text/html");
@@ skipping 56 matching lines @@
 
 void WebURLLoaderImpl::Context::OnReceivedCachedMetadata(
     const char* data, int len) {
   if (client_)
     client_->didReceiveCachedMetadata(loader_, data, len);
 }
 
 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);
   } else if (multipart_delegate_.get()) {
     multipart_delegate_->OnCompletedRequest();
     multipart_delegate_.reset(NULL);
   }
 
   // Prevent any further IPC to the browser now that we're complete, but
   // don't delete it to keep any downloaded temp files alive.
@@ skipping 11 matching lines @@
         error_code = status.error();
       }
       WebURLError error;
       if (error_code == net::ERR_ABORTED)
         error.isCancellation = true;
       error.domain = WebString::fromUTF8(net::kErrorDomain);
       error.reason = error_code;
       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));
     }
   }
 
   // We are done with the bridge now, and so we need to release the reference
   // to ourselves that we took on behalf of the bridge.  This may cause our
   // destruction.
   Release();
 }
 
 bool WebURLLoaderImpl::Context::CanHandleDataURL(const GURL& url) const {
@@ skipping 17 matching lines @@
     return true;
 
   return false;
 }
 
 void WebURLLoaderImpl::Context::HandleDataURL() {
   ResourceResponseInfo info;
   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 -----------------------------------------------------------
 
 WebURLLoaderImpl::WebURLLoaderImpl()
     : ALLOW_THIS_IN_INITIALIZER_LIST(context_(new Context(this))) {
 }
 
 WebURLLoaderImpl::~WebURLLoaderImpl() {
   cancel();
 }
 
 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;
 
   // TODO(tc): For file loads, we may want to include a more descriptive
   // status code or status text.
   const net::URLRequestStatus::Status& status =
       sync_load_response.status.status();
   if (status != net::URLRequestStatus::SUCCESS &&
       status != net::URLRequestStatus::HANDLED_EXTERNALLY) {
     response.setURL(final_url);
     error.domain = WebString::fromUTF8(net::kErrorDomain);
     error.reason = sync_load_response.status.error();
     error.unreachableURL = final_url;
     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());
 }
 
 void WebURLLoaderImpl::loadAsynchronously(const WebURLRequest& request,
                                           WebURLLoaderClient* client) {
   DCHECK(!context_->client());
 
   context_->set_client(client);
   context_->Start(request, NULL);
 }
 
 void WebURLLoaderImpl::cancel() {
   context_->Cancel();
 }
 
 void WebURLLoaderImpl::setDefersLoading(bool value) {
   context_->SetDefersLoading(value);
 }
 
 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