LoadTimingObserver: only send timing struct over IPC if necessary. + Added unit tests.

Review URL: http://codereview.chromium.org/3057001

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

4 files changed, 347 insertions, 16 deletions

diff --git a/chrome/browser/net/load_timing_observer.h b/chrome/browser/net/load_timing_observer.h
index 9e25b2d..9d9ba82 100644
--- a/chrome/browser/net/load_timing_observer.h
+++ b/chrome/browser/net/load_timing_observer.h
@@ -5,6 +5,7 @@
 #ifndef CHROME_BROWSER_NET_LOAD_TIMING_OBSERVER_H_
 #define CHROME_BROWSER_NET_LOAD_TIMING_OBSERVER_H_
 
+#include "base/gtest_prod_util.h"
 #include "base/hash_tables.h"
 #include "base/time.h"
 #include "chrome/browser/net/chrome_net_log.h"
@@ -47,6 +48,11 @@ class LoadTimingObserver : public ChromeNetLog::Observer {
                           net::NetLog::EventPhase phase,
                           net::NetLog::EventParameters* params);
  private:
+  FRIEND_TEST_ALL_PREFIXES(LoadTimingObserverTest,
+                           ConnectJobRecord);
+  FRIEND_TEST_ALL_PREFIXES(LoadTimingObserverTest,
+                           SocketRecord);
+
   void OnAddURLRequestEntry(net::NetLog::EventType type,
                             const base::TimeTicks& time,
                             const net::NetLog::Source& source,
diff --git a/chrome/browser/net/load_timing_observer_unittest.cc b/chrome/browser/net/load_timing_observer_unittest.cc
new file mode 100644
index 0000000..318b254
--- /dev/null
+++ b/chrome/browser/net/load_timing_observer_unittest.cc
@@ -0,0 +1,315 @@
+// Copyright (c) 2010 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 "chrome/browser/net/load_timing_observer.h"
+
+#include "base/compiler_specific.h"
+#include "base/format_macros.h"
+#include "base/string_util.h"
+#include "base/time.h"
+#include "net/base/load_flags.h"
+#include "net/url_request/url_request_netlog_params.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace {
+
+using net::NetLog;
+using base::TimeDelta;
+
+base::TimeTicks current_time;
+
+void AddStartEntry(LoadTimingObserver& observer,
+                   const NetLog::Source& source,
+                   NetLog::EventType type,
+                   NetLog::EventParameters* params) {
+  observer.OnAddEntry(type, current_time, source, NetLog::PHASE_BEGIN, params);
+}
+
+void AddEndEntry(LoadTimingObserver& observer,
+                 const NetLog::Source& source,
+                 NetLog::EventType type,
+                 NetLog::EventParameters* params) {
+  observer.OnAddEntry(type, current_time, source, NetLog::PHASE_END, params);
+}
+
+void AddStartURLRequestEntries(LoadTimingObserver& observer,
+                               uint32 id,
+                               bool request_timing) {
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, id);
+  AddStartEntry(observer, source, NetLog::TYPE_REQUEST_ALIVE, NULL);
+  AddStartEntry(observer,
+                source,
+                NetLog::TYPE_URL_REQUEST_START_JOB,
+                new URLRequestStartEventParameters(
+                    GURL(StringPrintf("http://req%d", id)),
+                    "GET",
+                    request_timing ? net::LOAD_ENABLE_LOAD_TIMING : 0,
+                    net::LOW));
+}
+
+void AddEndURLRequestEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, id);
+  AddEndEntry(observer, source, NetLog::TYPE_REQUEST_ALIVE, NULL);
+  AddEndEntry(observer,
+              source,
+              NetLog::TYPE_URL_REQUEST_START_JOB,
+              NULL);
+}
+
+void AddStartConnectJobEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_CONNECT_JOB, id);
+  AddStartEntry(observer, source, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
+}
+
+void AddEndConnectJobEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_CONNECT_JOB, id);
+  AddEndEntry(observer, source, NetLog::TYPE_SOCKET_POOL_CONNECT_JOB, NULL);
+}
+
+void AddStartSocketEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_SOCKET, id);
+  AddStartEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
+}
+
+void AddEndSocketEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_SOCKET, id);
+  AddEndEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
+}
+
+}  // namespace
+
+// Test that URLRequest with no load timing flag is not processed.
+TEST(LoadTimingObserverTest, NoLoadTimingEnabled) {
+  LoadTimingObserver observer;
+
+  AddStartURLRequestEntries(observer, 0, false);
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_TRUE(record == NULL);
+}
+
+// Test that URLRequestRecord is created, deleted and is not growing unbound.
+TEST(LoadTimingObserverTest, URLRequestRecord) {
+  LoadTimingObserver observer;
+
+  // Create record.
+  AddStartURLRequestEntries(observer, 0, true);
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_FALSE(record == NULL);
+
+  // Collect record.
+  AddEndURLRequestEntries(observer, 0);
+  record = observer.GetURLRequestRecord(0);
+  ASSERT_TRUE(record == NULL);
+
+  // Check unbound growth.
+  for (size_t i = 1; i < 1100; ++i)
+    AddStartURLRequestEntries(observer, i, true);
+  record = observer.GetURLRequestRecord(1);
+  ASSERT_TRUE(record == NULL);
+}
+
+// Test that ConnectJobRecord is created, deleted and is not growing unbound.
+TEST(LoadTimingObserverTest, ConnectJobRecord) {
+  LoadTimingObserver observer;
+
+  // Create record.
+  AddStartConnectJobEntries(observer, 0);
+  ASSERT_FALSE(observer.connect_job_to_record_.find(0) ==
+                   observer.connect_job_to_record_.end());
+
+  // Collect record.
+  AddEndConnectJobEntries(observer, 0);
+  ASSERT_TRUE(observer.connect_job_to_record_.find(0) ==
+                   observer.connect_job_to_record_.end());
+
+  // Check unbound growth.
+  for (size_t i = 1; i < 1100; ++i)
+    AddStartConnectJobEntries(observer, i);
+  ASSERT_TRUE(observer.connect_job_to_record_.find(1) ==
+                  observer.connect_job_to_record_.end());
+}
+
+// Test that SocketRecord is created, deleted and is not growing unbound.
+TEST(LoadTimingObserverTest, SocketRecord) {
+  LoadTimingObserver observer;
+
+  // Create record.
+  AddStartSocketEntries(observer, 0);
+  ASSERT_FALSE(observer.socket_to_record_.find(0) ==
+                   observer.socket_to_record_.end());
+
+  // Collect record.
+  AddEndSocketEntries(observer, 0);
+  ASSERT_TRUE(observer.socket_to_record_.find(0) ==
+                   observer.socket_to_record_.end());
+
+
+  // Check unbound growth.
+  for (size_t i = 1; i < 1100; ++i)
+    AddStartSocketEntries(observer, i);
+  ASSERT_TRUE(observer.socket_to_record_.find(1) ==
+                  observer.socket_to_record_.end());
+}
+
+// Test that basic time is set to the request.
+TEST(LoadTimingObserverTest, BaseTicks) {
+  LoadTimingObserver observer;
+  current_time += TimeDelta::FromSeconds(1);
+  AddStartURLRequestEntries(observer, 0, true);
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(1000000, record->base_ticks.ToInternalValue());
+}
+
+// Test proxy time detection.
+TEST(LoadTimingObserverTest, ProxyTime) {
+  LoadTimingObserver observer;
+  current_time += TimeDelta::FromSeconds(1);
+
+  AddStartURLRequestEntries(observer, 0, true);
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
+
+  current_time += TimeDelta::FromSeconds(2);
+  AddStartEntry(observer, source, NetLog::TYPE_PROXY_SERVICE, NULL);
+  current_time += TimeDelta::FromSeconds(3);
+  AddEndEntry(observer, source, NetLog::TYPE_PROXY_SERVICE, NULL);
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(2000, record->timing.proxy_start);
+  ASSERT_EQ(5000, record->timing.proxy_end);
+}
+
+// Test connect time detection.
+TEST(LoadTimingObserverTest, ConnectTime) {
+  LoadTimingObserver observer;
+  current_time += TimeDelta::FromSeconds(1);
+
+  AddStartURLRequestEntries(observer, 0, true);
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
+
+  current_time += TimeDelta::FromSeconds(2);
+  AddStartEntry(observer, source, NetLog::TYPE_SOCKET_POOL, NULL);
+  current_time += TimeDelta::FromSeconds(3);
+  AddEndEntry(observer, source, NetLog::TYPE_SOCKET_POOL, NULL);
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(2000, record->timing.connect_start);
+  ASSERT_EQ(5000, record->timing.connect_end);
+}
+
+// Test dns time detection.
+TEST(LoadTimingObserverTest, DnsTime) {
+  LoadTimingObserver observer;
+
+  // Start request.
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
+  AddStartURLRequestEntries(observer, 0, true);
+  current_time += TimeDelta::FromSeconds(1);
+
+  // Add resolver entry.
+  AddStartConnectJobEntries(observer, 1);
+  NetLog::Source connect_source(NetLog::SOURCE_CONNECT_JOB, 1);
+  AddStartEntry(observer,
+                connect_source,
+                NetLog::TYPE_HOST_RESOLVER_IMPL,
+                NULL);
+  current_time += TimeDelta::FromSeconds(2);
+  AddEndEntry(observer, connect_source, NetLog::TYPE_HOST_RESOLVER_IMPL, NULL);
+
+  // Bind to connect job.
+  AddStartEntry(observer,
+                source,
+                NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+                new net::NetLogSourceParameter("connect_job", connect_source));
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(1000, record->timing.dns_start);
+  ASSERT_EQ(3000, record->timing.dns_end);
+}
+
+// Test send time detection.
+TEST(LoadTimingObserverTest, SendTime) {
+  LoadTimingObserver observer;
+
+  // Start request.
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
+  AddStartURLRequestEntries(observer, 0, true);
+  current_time += TimeDelta::FromSeconds(2);
+
+  // Add send request entry.
+  AddStartEntry(observer,
+                source,
+                NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST,
+                NULL);
+  current_time += TimeDelta::FromSeconds(5);
+  AddEndEntry(observer,
+              source,
+              NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST,
+              NULL);
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(2000, record->timing.send_start);
+  ASSERT_EQ(7000, record->timing.send_end);
+}
+
+// Test receive time detection.
+TEST(LoadTimingObserverTest, ReceiveTime) {
+  LoadTimingObserver observer;
+
+  // Start request.
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
+  AddStartURLRequestEntries(observer, 0, true);
+  current_time += TimeDelta::FromSeconds(2);
+
+  // Add send request entry.
+  AddStartEntry(observer,
+                source,
+                NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS,
+                NULL);
+  current_time += TimeDelta::FromSeconds(5);
+  AddEndEntry(observer,
+              source,
+              NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS,
+              NULL);
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(2000, record->timing.receive_headers_start);
+  ASSERT_EQ(7000, record->timing.receive_headers_end);
+}
+
+// Test ssl time detection.
+TEST(LoadTimingObserverTest, SslTime) {
+  LoadTimingObserver observer;
+
+  // Start request.
+  NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
+  AddStartURLRequestEntries(observer, 0, true);
+  current_time += TimeDelta::FromSeconds(1);
+
+  // Add resolver entry.
+  AddStartSocketEntries(observer, 1);
+  NetLog::Source socket_source(NetLog::SOURCE_SOCKET, 1);
+  AddStartEntry(observer, socket_source, NetLog::TYPE_SSL_CONNECT, NULL);
+  current_time += TimeDelta::FromSeconds(2);
+  AddEndEntry(observer, socket_source, NetLog::TYPE_SSL_CONNECT, NULL);
+
+  // Bind to connect job.
+  AddStartEntry(observer,
+                source,
+                NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
+                new net::NetLogSourceParameter("socket", socket_source));
+
+  LoadTimingObserver::URLRequestRecord* record =
+      observer.GetURLRequestRecord(0);
+  ASSERT_EQ(1000, record->timing.ssl_start);
+  ASSERT_EQ(3000, record->timing.ssl_end);
+}
diff --git a/chrome/chrome_tests.gypi b/chrome/chrome_tests.gypi
index 3507387..bb9998c 100644
--- a/chrome/chrome_tests.gypi
+++ b/chrome/chrome_tests.gypi
@@ -998,6 +998,7 @@
         'browser/mock_configuration_policy_store.h',
         'browser/net/chrome_url_request_context_unittest.cc',
         'browser/net/connection_tester_unittest.cc',
+        'browser/net/load_timing_observer_unittest.cc',
         'browser/net/passive_log_collector_unittest.cc',
         'browser/net/predictor_unittest.cc',
         'browser/net/resolve_proxy_msg_helper_unittest.cc',
diff --git a/chrome/common/render_messages.h b/chrome/common/render_messages.h
index 82888e6..4889965 100644
--- a/chrome/common/render_messages.h
+++ b/chrome/common/render_messages.h
@@ -1506,6 +1506,9 @@ template <>
 struct ParamTraits<webkit_glue::ResourceLoaderBridge::LoadTimingInfo> {
   typedef webkit_glue::ResourceLoaderBridge::LoadTimingInfo param_type;
   static void Write(Message* m, const param_type& p) {
+    WriteParam(m, p.base_time.is_null());
+    if (p.base_time.is_null())
+      return;
     WriteParam(m, p.base_time);
     WriteParam(m, p.proxy_start);
     WriteParam(m, p.proxy_end);
@@ -1521,6 +1524,12 @@ struct ParamTraits<webkit_glue::ResourceLoaderBridge::LoadTimingInfo> {
     WriteParam(m, p.receive_headers_end);
   }
   static bool Read(const Message* m, void** iter, param_type* r) {
+    bool is_null;
+    if (!ReadParam(m, iter, &is_null))
+      return false;
+    if (is_null)
+      return true;
+
     return
         ReadParam(m, iter, &r->base_time) &&
         ReadParam(m, iter, &r->proxy_start) &&
@@ -1591,22 +1600,22 @@ struct ParamTraits<webkit_glue::ResourceLoaderBridge::ResponseInfo> {
   }
   static bool Read(const Message* m, void** iter, param_type* r) {
     return
-      ReadParam(m, iter, &r->request_time) &&
-      ReadParam(m, iter, &r->response_time) &&
-      ReadParam(m, iter, &r->headers) &&
-      ReadParam(m, iter, &r->mime_type) &&
-      ReadParam(m, iter, &r->charset) &&
-      ReadParam(m, iter, &r->security_info) &&
-      ReadParam(m, iter, &r->content_length) &&
-      ReadParam(m, iter, &r->appcache_id) &&
-      ReadParam(m, iter, &r->appcache_manifest_url) &&
-      ReadParam(m, iter, &r->connection_id) &&
-      ReadParam(m, iter, &r->connection_reused) &&
-      ReadParam(m, iter, &r->load_timing) &&
-      ReadParam(m, iter, &r->was_fetched_via_spdy) &&
-      ReadParam(m, iter, &r->was_npn_negotiated) &&
-      ReadParam(m, iter, &r->was_alternate_protocol_available) &&
-      ReadParam(m, iter, &r->was_fetched_via_proxy);
+        ReadParam(m, iter, &r->request_time) &&
+        ReadParam(m, iter, &r->response_time) &&
+        ReadParam(m, iter, &r->headers) &&
+        ReadParam(m, iter, &r->mime_type) &&
+        ReadParam(m, iter, &r->charset) &&
+        ReadParam(m, iter, &r->security_info) &&
+        ReadParam(m, iter, &r->content_length) &&
+        ReadParam(m, iter, &r->appcache_id) &&
+        ReadParam(m, iter, &r->appcache_manifest_url) &&
+        ReadParam(m, iter, &r->connection_id) &&
+        ReadParam(m, iter, &r->connection_reused) &&
+        ReadParam(m, iter, &r->load_timing) &&
+        ReadParam(m, iter, &r->was_fetched_via_spdy) &&
+        ReadParam(m, iter, &r->was_npn_negotiated) &&
+        ReadParam(m, iter, &r->was_alternate_protocol_available) &&
+        ReadParam(m, iter, &r->was_fetched_via_proxy);
   }
   static void Log(const param_type& p, std::wstring* l) {
     l->append(L"(");