Inject renderer receive message time into resource notifications.

Previously time calculations based on "now"-time taken when renderer processed resource notification messages.

Renderer time is calculated by interpolation based on taken values. Because of long JS evaluation or heavy rendering, "renderer" time range might be skewed.

To fix situation, "renderer" time should be taken when IPC messages are processed by renderer IO thread.

This patch adds message filter that supplies aforementioned messages with timestamps.


BUG=223836

Review URL: https://chromiumcodereview.appspot.com/14646006

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@202870 0039d316-1c4b-4281-b951-d872f2087c98

content/common/child_resource_message_filter.cc

+// Copyright 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 "content/common/child_resource_message_filter.h"
+
+#include "base/thread_task_runner_handle.h"
+#include "content/common/resource_dispatcher.h"
+#include "content/common/resource_messages.h"
+
+namespace content {
+
+ChildResourceMessageFilter::ChildResourceMessageFilter(
+    ResourceDispatcher* resource_dispatcher)
+    : main_thread_task_runner_(base::ThreadTaskRunnerHandle::Get()),
+      resource_dispatcher_(resource_dispatcher) {}
+
+ChildResourceMessageFilter::~ChildResourceMessageFilter() {}
+
+bool ChildResourceMessageFilter::OnMessageReceived(
+    const IPC::Message& message) {
+  if (message.type() == ResourceMsg_RequestComplete::ID ||
+      message.type() == ResourceMsg_ReceivedResponse::ID ||
+      message.type() == ResourceMsg_ReceivedRedirect::ID) {
+    main_thread_task_runner_->PostTask(FROM_HERE, base::Bind(
+        &ResourceDispatcher::set_io_timestamp,
+        base::Unretained(resource_dispatcher_),
+        base::TimeTicks::Now()));
+  }
+  return false;
+}
+
+}  // namespace content
\ No newline at end of file

content/common/child_resource_message_filter.h

+// Copyright 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.
+
+#ifndef CONTENT_COMMON_CHILD_RESOURCE_MESSAGE_FILTER_H_
+#define CONTENT_COMMON_CHILD_RESOURCE_MESSAGE_FILTER_H_
+
+#include "base/memory/ref_counted.h"
+#include "ipc/ipc_channel_proxy.h"
+
+namespace base {
+class SingleThreadTaskRunner;
+}
+
+namespace content {
+class ResourceDispatcher;
+
+// Supplies ResourceDispatcher with timestamps for some resource messages.
+//
+// Background: ResourceDispatcher converts browser process time to child
+// process time. This is done to achieve coherent timeline. Conversion is
+// a linear transformation such that given browser process time range is
+// mapped to corresponding child process time range. Timestamps for child
+// process time range should be taken by IO thread when resource messages
+// arrive. Otherwise, timestamps may be affected by long rendering / JS task.
+//
+// When specific message is processed by this filter, new task charged
+// with timestamp is posted to main thread. This task is processed just before
+// resource message and invokes ResourceDispatcher::set_io_timestamp.
+class ChildResourceMessageFilter : public IPC::ChannelProxy::MessageFilter {
+ public:
+  explicit ChildResourceMessageFilter(ResourceDispatcher* resource_dispatcher);
+
+  // IPC::ChannelProxy::MessageFilter implementation.
+  virtual bool OnMessageReceived(const IPC::Message& message) OVERRIDE;
+
+ private:
+  virtual ~ChildResourceMessageFilter();
+
+  scoped_refptr<base::SingleThreadTaskRunner> main_thread_task_runner_;
+  ResourceDispatcher* resource_dispatcher_;
+
+  DISALLOW_COPY_AND_ASSIGN(ChildResourceMessageFilter);
+};
+
+}  // namespace content
+
+#endif  // CONTENT_COMMON_CHILD_RESOURCE_MESSAGE_FILTER_H_
\ No newline at end of file

content/common/child_thread.cc

@@ -15,6 +15,7 @@
 #include "content/common/child_histogram_message_filter.h"
 #include "content/common/child_process.h"
 #include "content/common/child_process_messages.h"
+#include "content/common/child_resource_message_filter.h"
 #include "content/common/fileapi/file_system_dispatcher.h"
 #include "content/common/quota_dispatcher.h"
 #include "content/common/resource_dispatcher.h"
@@ -119,11 +120,14 @@ void ChildThread::Init() {
       new ThreadSafeSender(base::MessageLoopProxy::current(),
                            sync_message_filter_);
   histogram_message_filter_ = new ChildHistogramMessageFilter();
+  resource_message_filter_ =
+      new ChildResourceMessageFilter(resource_dispatcher());
 
   channel_->AddFilter(histogram_message_filter_.get());
   channel_->AddFilter(sync_message_filter_.get());
   channel_->AddFilter(new tracing::ChildTraceMessageFilter(
       ChildProcess::current()->io_message_loop_proxy()));
+  channel_->AddFilter(resource_message_filter_.get());
 
 #if defined(OS_POSIX)
   // Check that --process-type is specified so we don't do this in unit tests

content/common/child_thread.h

@@ -30,6 +30,7 @@ class WebFrame;
 
 namespace content {
 class ChildHistogramMessageFilter;
+class ChildResourceMessageFilter;
 class FileSystemDispatcher;
 class QuotaDispatcher;
 class ResourceDispatcher;
@@ -180,6 +181,8 @@ class CONTENT_EXPORT ChildThread : public IPC::Listener, public IPC::Sender {
 
   scoped_refptr<ChildHistogramMessageFilter> histogram_message_filter_;
 
+  scoped_refptr<ChildResourceMessageFilter> resource_message_filter_;
+
   base::WeakPtrFactory<ChildThread> channel_connected_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(ChildThread);

content/common/resource_dispatcher.cc

@@ -257,7 +257,8 @@ void IPCResourceLoaderBridge::SyncLoad(SyncLoadResponse* response) {
 ResourceDispatcher::ResourceDispatcher(IPC::Sender* sender)
     : message_sender_(sender),
       weak_factory_(this),
-      delegate_(NULL) {
+      delegate_(NULL),
+      io_timestamp_(base::TimeTicks()) {
 }
 
 ResourceDispatcher::~ResourceDispatcher() {
@@ -334,7 +335,7 @@ void ResourceDispatcher::OnReceivedResponse(
   PendingRequestInfo* request_info = GetPendingRequestInfo(request_id);
   if (!request_info)
     return;
-  request_info->response_start = base::TimeTicks::Now();
+  request_info->response_start = ConsumeIOTimestamp();
 
   if (delegate_) {
     ResourceLoaderBridge::Peer* new_peer =
@@ -447,7 +448,7 @@ void ResourceDispatcher::OnReceivedRedirect(
   PendingRequestInfo* request_info = GetPendingRequestInfo(request_id);
   if (!request_info)
     return;
-  request_info->response_start = base::TimeTicks::Now();
+  request_info->response_start = ConsumeIOTimestamp();
 
   int32 routing_id = message.routing_id();
   bool has_new_first_party_for_cookies = false;
@@ -491,7 +492,7 @@ void ResourceDispatcher::OnRequestComplete(
   PendingRequestInfo* request_info = GetPendingRequestInfo(request_id);
   if (!request_info)
     return;
-  request_info->completion_time = base::TimeTicks::Now();
+  request_info->completion_time = ConsumeIOTimestamp();
   request_info->buffer.reset();
   request_info->buffer_size = 0;
 
@@ -702,6 +703,14 @@ base::TimeTicks ResourceDispatcher::ToRendererCompletionTime(
   return base::TimeTicks::FromInternalValue(result);
 }
 
+base::TimeTicks ResourceDispatcher::ConsumeIOTimestamp() {
+  if (io_timestamp_ == base::TimeTicks())
+    return base::TimeTicks::Now();
+  base::TimeTicks result = io_timestamp_;
+  io_timestamp_ = base::TimeTicks();
+  return result;
+}
+
 // static
 bool ResourceDispatcher::IsResourceDispatcherMessage(
     const IPC::Message& message) {

content/common/resource_dispatcher.h

@@ -71,6 +71,11 @@ class CONTENT_EXPORT ResourceDispatcher : public IPC::Listener {
     delegate_ = delegate;
   }
 
+  // Remembers IO thread timestamp for next resource message.
+  void set_io_timestamp(base::TimeTicks io_timestamp) {
+    io_timestamp_ = io_timestamp;
+  }
+
  private:
   friend class ResourceDispatcherTest;
 
@@ -157,6 +162,11 @@ class CONTENT_EXPORT ResourceDispatcher : public IPC::Listener {
       const PendingRequestInfo& request_info,
       const base::TimeTicks& browser_completion_time) const;
 
+  // Returns timestamp provided by IO thread. If no timestamp is supplied,
+  // then current time is returned. Saved timestamp is reset, so following
+  // invocations will return current time until set_io_timestamp is called.
+  base::TimeTicks ConsumeIOTimestamp();
+
   // Returns true if the message passed in is a resource related message.
   static bool IsResourceDispatcherMessage(const IPC::Message& message);
 
@@ -180,6 +190,9 @@ class CONTENT_EXPORT ResourceDispatcher : public IPC::Listener {
 
   ResourceDispatcherDelegate* delegate_;
 
+  // IO thread timestamp for ongoing IPC message.
+  base::TimeTicks io_timestamp_;
+
   DISALLOW_COPY_AND_ASSIGN(ResourceDispatcher);
 };
 

content/content_common.gypi

@@ -140,6 +140,8 @@
     'common/child_process_sandbox_support_impl_linux.cc',
     'common/child_process_sandbox_support_impl_linux.h',
     'common/child_process_sandbox_support_impl_shm_linux.cc',
+    'common/child_resource_message_filter.cc',
+    'common/child_resource_message_filter.h',
     'common/child_thread.cc',
     'common/child_thread.h',
     'common/clipboard_messages.cc',