Fixed WebTiming after introducing HTTP_STREAM_JOB in NetLog

BUG=76366
TEST=Open https:// site, open DevTools console, ensure window.performance.timing.secureConnectionStart is not zero.

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

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

3 files changed, 205 insertions, 51 deletions

diff --git a/chrome/browser/net/load_timing_observer.cc b/chrome/browser/net/load_timing_observer.cc
index 63ac8ea..7897069 100644
--- a/chrome/browser/net/load_timing_observer.cc
+++ b/chrome/browser/net/load_timing_observer.cc
@@ -56,6 +56,11 @@ LoadTimingObserver::URLRequestRecord::URLRequestRecord()
       socket_reused(false) {
 }
 
+LoadTimingObserver::HTTPStreamJobRecord::HTTPStreamJobRecord()
+    : socket_log_id(net::NetLog::Source::kInvalidId),
+      socket_reused(false) {
+}
+
 LoadTimingObserver::LoadTimingObserver()
     : ThreadSafeObserver(net::NetLog::LOG_BASIC),
       last_connect_job_id_(net::NetLog::Source::kInvalidId) {
@@ -84,6 +89,8 @@ void LoadTimingObserver::OnAddEntry(net::NetLog::EventType type,
     return;
   if (source.type == net::NetLog::SOURCE_URL_REQUEST)
     OnAddURLRequestEntry(type, time, source, phase, params);
+  else if (source.type == net::NetLog::SOURCE_HTTP_STREAM_JOB)
+    OnAddHTTPStreamJobEntry(type, time, source, phase, params);
   else if (source.type == net::NetLog::SOURCE_CONNECT_JOB)
     OnAddConnectJobEntry(type, time, source, phase, params);
   else if (source.type == net::NetLog::SOURCE_SOCKET)
@@ -133,7 +140,7 @@ void LoadTimingObserver::OnAddURLRequestEntry(
       if (!(load_flags & net::LOAD_ENABLE_LOAD_TIMING))
         return;
 
-      // Prevents us from passively growing the memory memory unbounded in case
+      // Prevents us from passively growing the memory unbounded in case
       // something went wrong. Should not happen.
       if (url_request_to_record_.size() > kMaxNumEntries) {
         LOG(WARNING) << "The load timing observer url request count has grown "
@@ -166,40 +173,24 @@ void LoadTimingObserver::OnAddURLRequestEntry(
       else if (is_end)
         timing.proxy_end = TimeTicksToOffset(time, record);
       break;
-    case net::NetLog::TYPE_SOCKET_POOL:
-      if (is_begin)
-        timing.connect_start = TimeTicksToOffset(time, record);
-      else if (is_end)
-        timing.connect_end = TimeTicksToOffset(time, record);
-      break;
-    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB:
-      {
-        uint32 connect_job_id = static_cast<net::NetLogSourceParameter*>(
-            params)->value().id;
-        if (last_connect_job_id_ == connect_job_id &&
-            !last_connect_job_record_.dns_start.is_null()) {
-          timing.dns_start =
-              TimeTicksToOffset(last_connect_job_record_.dns_start, record);
-          timing.dns_end =
-              TimeTicksToOffset(last_connect_job_record_.dns_end, record);
-        }
-      }
-      break;
-    case net::NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET:
-      record->socket_reused = true;
-      break;
-    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET:
-      record->socket_log_id = static_cast<net::NetLogSourceParameter*>(
+    case net::NetLog::TYPE_HTTP_STREAM_REQUEST_BOUND_TO_JOB: {
+      uint32 http_stream_job_id = static_cast<net::NetLogSourceParameter*>(
           params)->value().id;
-      if (!record->socket_reused) {
-        SocketToRecordMap::iterator it =
-            socket_to_record_.find(record->socket_log_id);
-        if (it != socket_to_record_.end() && !it->second.ssl_start.is_null()) {
-          timing.ssl_start = TimeTicksToOffset(it->second.ssl_start, record);
-          timing.ssl_end = TimeTicksToOffset(it->second.ssl_end, record);
-        }
-      }
+      HTTPStreamJobToRecordMap::iterator it =
+          http_stream_job_to_record_.find(http_stream_job_id);
+      if (it == http_stream_job_to_record_.end())
+        return;
+      timing.connect_start = TimeTicksToOffset(it->second.connect_start,
+                                               record);
+      timing.connect_end = TimeTicksToOffset(it->second.connect_end, record);
+      timing.dns_start = TimeTicksToOffset(it->second.dns_start, record);
+      timing.dns_end = TimeTicksToOffset(it->second.dns_end, record);
+      record->socket_reused = it->second.socket_reused;
+      record->socket_log_id = it->second.socket_log_id;
+      timing.ssl_start = TimeTicksToOffset(it->second.ssl_start, record);
+      timing.ssl_end = TimeTicksToOffset(it->second.ssl_end, record);
       break;
+    }
     case net::NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST:
       if (is_begin)
         timing.send_start = TimeTicksToOffset(time, record);
@@ -217,6 +208,78 @@ void LoadTimingObserver::OnAddURLRequestEntry(
   }
 }
 
+void LoadTimingObserver::OnAddHTTPStreamJobEntry(
+    net::NetLog::EventType type,
+    const base::TimeTicks& time,
+    const net::NetLog::Source& source,
+    net::NetLog::EventPhase phase,
+    net::NetLog::EventParameters* params) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
+
+  bool is_begin = phase == net::NetLog::PHASE_BEGIN;
+  bool is_end = phase == net::NetLog::PHASE_END;
+
+  if (type == net::NetLog::TYPE_HTTP_STREAM_JOB) {
+    if (is_begin) {
+      // Prevents us from passively growing the memory unbounded in
+      // case something went wrong. Should not happen.
+      if (http_stream_job_to_record_.size() > kMaxNumEntries) {
+        LOG(WARNING) << "The load timing observer http stream job count "
+                        "has grown larger than expected, resetting";
+        http_stream_job_to_record_.clear();
+      }
+
+      http_stream_job_to_record_.insert(
+          std::make_pair(source.id, HTTPStreamJobRecord()));
+    } else if (is_end) {
+      http_stream_job_to_record_.erase(source.id);
+    }
+    return;
+  }
+
+  HTTPStreamJobToRecordMap::iterator it =
+      http_stream_job_to_record_.find(source.id);
+  if (it == http_stream_job_to_record_.end())
+    return;
+
+  switch (type) {
+    case net::NetLog::TYPE_SOCKET_POOL:
+      if (is_begin)
+        it->second.connect_start = time;
+      else if (is_end)
+        it->second.connect_end = time;
+      break;
+    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB: {
+      uint32 connect_job_id = static_cast<net::NetLogSourceParameter*>(
+          params)->value().id;
+      if (last_connect_job_id_ == connect_job_id &&
+          !last_connect_job_record_.dns_start.is_null()) {
+        it->second.dns_start = last_connect_job_record_.dns_start;
+        it->second.dns_end = last_connect_job_record_.dns_end;
+      }
+      break;
+    }
+    case net::NetLog::TYPE_SOCKET_POOL_REUSED_AN_EXISTING_SOCKET:
+      it->second.socket_reused = true;
+      break;
+    case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET:
+      it->second.socket_log_id = static_cast<net::NetLogSourceParameter*>(
+        params)->value().id;
+      if (!it->second.socket_reused) {
+        SocketToRecordMap::iterator socket_it =
+            socket_to_record_.find(it->second.socket_log_id);
+        if (socket_it != socket_to_record_.end() &&
+            !socket_it->second.ssl_start.is_null()) {
+          it->second.ssl_start = socket_it->second.ssl_start;
+          it->second.ssl_end = socket_it->second.ssl_end;
+        }
+      }
+      break;
+    default:
+      break;
+  }
+}
+
 void LoadTimingObserver::OnAddConnectJobEntry(
     net::NetLog::EventType type,
     const base::TimeTicks& time,
@@ -231,7 +294,7 @@ void LoadTimingObserver::OnAddConnectJobEntry(
   // Manage record lifetime based on the SOCKET_POOL_CONNECT_JOB entry.
   if (type == net::NetLog::TYPE_SOCKET_POOL_CONNECT_JOB) {
     if (is_begin) {
-      // Prevents us from passively growing the memory memory unbounded in case
+      // Prevents us from passively growing the memory unbounded in case
       // something went wrong. Should not happen.
       if (connect_job_to_record_.size() > kMaxNumEntries) {
         LOG(WARNING) << "The load timing observer connect job count has grown "
@@ -276,7 +339,7 @@ void LoadTimingObserver::OnAddSocketEntry(
   // Manage record lifetime based on the SOCKET_ALIVE entry.
   if (type == net::NetLog::TYPE_SOCKET_ALIVE) {
     if (is_begin) {
-      // Prevents us from passively growing the memory memory unbounded in case
+      // Prevents us from passively growing the memory unbounded in case
       // something went wrong. Should not happen.
       if (socket_to_record_.size() > kMaxNumEntries) {
         LOG(WARNING) << "The load timing observer socket count has grown "
diff --git a/chrome/browser/net/load_timing_observer.h b/chrome/browser/net/load_timing_observer.h
index a280398..3cd70f5 100644
--- a/chrome/browser/net/load_timing_observer.h
+++ b/chrome/browser/net/load_timing_observer.h
@@ -36,6 +36,19 @@ class LoadTimingObserver : public ChromeNetLog::ThreadSafeObserver {
     base::TimeTicks base_ticks;
   };
 
+  struct HTTPStreamJobRecord {
+    HTTPStreamJobRecord();
+
+    uint32 socket_log_id;
+    bool socket_reused;
+    base::TimeTicks connect_start;
+    base::TimeTicks connect_end;
+    base::TimeTicks dns_start;
+    base::TimeTicks dns_end;
+    base::TimeTicks ssl_start;
+    base::TimeTicks ssl_end;
+  };
+
   struct ConnectJobRecord {
     base::TimeTicks dns_start;
     base::TimeTicks dns_end;
@@ -63,6 +76,8 @@ class LoadTimingObserver : public ChromeNetLog::ThreadSafeObserver {
 
  private:
   FRIEND_TEST_ALL_PREFIXES(LoadTimingObserverTest,
+                           HTTPStreamJobRecord);
+  FRIEND_TEST_ALL_PREFIXES(LoadTimingObserverTest,
                            ConnectJobRecord);
   FRIEND_TEST_ALL_PREFIXES(LoadTimingObserverTest,
                            SocketRecord);
@@ -73,6 +88,12 @@ class LoadTimingObserver : public ChromeNetLog::ThreadSafeObserver {
                             net::NetLog::EventPhase phase,
                             net::NetLog::EventParameters* params);
 
+  void OnAddHTTPStreamJobEntry(net::NetLog::EventType type,
+                               const base::TimeTicks& time,
+                               const net::NetLog::Source& source,
+                               net::NetLog::EventPhase phase,
+                               net::NetLog::EventParameters* params);
+
   void OnAddConnectJobEntry(net::NetLog::EventType type,
                             const base::TimeTicks& time,
                             const net::NetLog::Source& source,
@@ -89,9 +110,11 @@ class LoadTimingObserver : public ChromeNetLog::ThreadSafeObserver {
   void DeleteURLRequestRecord(uint32 source_id);
 
   typedef base::hash_map<uint32, URLRequestRecord> URLRequestToRecordMap;
+  typedef base::hash_map<uint32, HTTPStreamJobRecord> HTTPStreamJobToRecordMap;
   typedef base::hash_map<uint32, ConnectJobRecord> ConnectJobToRecordMap;
   typedef base::hash_map<uint32, SocketRecord> SocketToRecordMap;
   URLRequestToRecordMap url_request_to_record_;
+  HTTPStreamJobToRecordMap http_stream_job_to_record_;
   ConnectJobToRecordMap connect_job_to_record_;
   SocketToRecordMap socket_to_record_;
   uint32 last_connect_job_id_;
diff --git a/chrome/browser/net/load_timing_observer_unittest.cc b/chrome/browser/net/load_timing_observer_unittest.cc
index 9bb77d6..877d303 100644
--- a/chrome/browser/net/load_timing_observer_unittest.cc
+++ b/chrome/browser/net/load_timing_observer_unittest.cc
@@ -71,6 +71,16 @@ void AddEndURLRequestEntries(LoadTimingObserver& observer, uint32 id) {
               NULL);
 }
 
+void AddStartHTTPStreamJobEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_HTTP_STREAM_JOB, id);
+  AddStartEntry(observer, source, NetLog::TYPE_HTTP_STREAM_JOB, NULL);
+}
+
+void AddEndHTTPStreamJobEntries(LoadTimingObserver& observer, uint32 id) {
+  NetLog::Source source(NetLog::SOURCE_HTTP_STREAM_JOB, id);
+  AddEndEntry(observer, source, NetLog::TYPE_HTTP_STREAM_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);
@@ -91,6 +101,40 @@ void AddEndSocketEntries(LoadTimingObserver& observer, uint32 id) {
   AddEndEntry(observer, source, NetLog::TYPE_SOCKET_ALIVE, NULL);
 }
 
+void BindURLRequestToHTTPStreamJob(LoadTimingObserver& observer,
+                                   NetLog::Source url_request_source,
+                                   NetLog::Source http_stream_job_source) {
+  scoped_refptr<net::NetLogSourceParameter> params(
+      new net::NetLogSourceParameter("source_dependency",
+                                     http_stream_job_source));
+  AddStartEntry(observer,
+                url_request_source,
+                NetLog::TYPE_HTTP_STREAM_REQUEST_BOUND_TO_JOB,
+                params.get());
+}
+
+void BindHTTPStreamJobToConnectJob(LoadTimingObserver& observer,
+                                   NetLog::Source& http_stream_job_source,
+                                   NetLog::Source& connect_source) {
+  scoped_refptr<net::NetLogSourceParameter> params(
+      new net::NetLogSourceParameter("source_dependency", connect_source));
+  AddStartEntry(observer,
+                http_stream_job_source,
+                NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
+                params.get());
+}
+
+void BindHTTPStreamJobToSocket(LoadTimingObserver& observer,
+                               NetLog::Source& http_stream_job_source,
+                               NetLog::Source& socket_source) {
+  scoped_refptr<net::NetLogSourceParameter> params(
+      new net::NetLogSourceParameter("source_dependency", socket_source));
+  AddStartEntry(observer,
+                http_stream_job_source,
+                NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
+                params.get());
+}
+
 }  // namespace
 
 // Test that net::URLRequest with no load timing flag is not processed.
@@ -125,6 +169,27 @@ TEST_F(LoadTimingObserverTest, URLRequestRecord) {
   ASSERT_TRUE(record == NULL);
 }
 
+// Test that HTTPStreamJobRecord is created, deleted and is not growing unbound.
+TEST_F(LoadTimingObserverTest, HTTPStreamJobRecord) {
+  LoadTimingObserver observer;
+
+  // Create record.
+  AddStartHTTPStreamJobEntries(observer, 0);
+  ASSERT_FALSE(observer.http_stream_job_to_record_.find(0) ==
+                   observer.http_stream_job_to_record_.end());
+
+  // Collect record.
+  AddEndHTTPStreamJobEntries(observer, 0);
+  ASSERT_TRUE(observer.http_stream_job_to_record_.find(0) ==
+                   observer.http_stream_job_to_record_.end());
+
+  // Check unbound growth.
+  for (size_t i = 1; i < 1100; ++i)
+    AddStartHTTPStreamJobEntries(observer, i);
+  ASSERT_TRUE(observer.http_stream_job_to_record_.find(1) ==
+                  observer.http_stream_job_to_record_.end());
+}
+
 // Test that ConnectJobRecord is created, deleted and is not growing unbound.
 TEST_F(LoadTimingObserverTest, ConnectJobRecord) {
   LoadTimingObserver observer;
@@ -206,10 +271,16 @@ TEST_F(LoadTimingObserverTest, ConnectTime) {
   AddStartURLRequestEntries(observer, 0, true);
   NetLog::Source source(NetLog::SOURCE_URL_REQUEST, 0);
 
+  NetLog::Source http_stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, 1);
+  AddStartHTTPStreamJobEntries(observer, 1);
+
   current_time += TimeDelta::FromSeconds(2);
-  AddStartEntry(observer, source, NetLog::TYPE_SOCKET_POOL, NULL);
+  AddStartEntry(observer, http_stream_job_source, NetLog::TYPE_SOCKET_POOL,
+                NULL);
   current_time += TimeDelta::FromSeconds(3);
-  AddEndEntry(observer, source, NetLog::TYPE_SOCKET_POOL, NULL);
+  AddEndEntry(observer, http_stream_job_source, NetLog::TYPE_SOCKET_POOL, NULL);
+
+  BindURLRequestToHTTPStreamJob(observer, source, http_stream_job_source);
 
   LoadTimingObserver::URLRequestRecord* record =
       observer.GetURLRequestRecord(0);
@@ -237,13 +308,12 @@ TEST_F(LoadTimingObserverTest, DnsTime) {
   AddEndEntry(observer, connect_source, NetLog::TYPE_HOST_RESOLVER_IMPL, NULL);
   AddEndConnectJobEntries(observer, 1);
 
-  // Bind to connect job.
-  scoped_refptr<net::NetLogSourceParameter> params(
-      new net::NetLogSourceParameter("connect_job", connect_source));
-  AddStartEntry(observer,
-                source,
-                NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB,
-                params.get());
+  NetLog::Source http_stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, 2);
+  AddStartHTTPStreamJobEntries(observer, 2);
+
+  BindHTTPStreamJobToConnectJob(observer, http_stream_job_source,
+                                connect_source);
+  BindURLRequestToHTTPStreamJob(observer, source, http_stream_job_source);
 
   LoadTimingObserver::URLRequestRecord* record =
       observer.GetURLRequestRecord(0);
@@ -319,13 +389,11 @@ TEST_F(LoadTimingObserverTest, SslTime) {
   current_time += TimeDelta::FromSeconds(2);
   AddEndEntry(observer, socket_source, NetLog::TYPE_SSL_CONNECT, NULL);
 
-  // Bind to connect job.
-  scoped_refptr<net::NetLogSourceParameter> params(
-      new net::NetLogSourceParameter("socket", socket_source));
-  AddStartEntry(observer,
-                source,
-                NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET,
-                params.get());
+  NetLog::Source http_stream_job_source(NetLog::SOURCE_HTTP_STREAM_JOB, 2);
+  AddStartHTTPStreamJobEntries(observer, 2);
+
+  BindHTTPStreamJobToSocket(observer, http_stream_job_source, socket_source);
+  BindURLRequestToHTTPStreamJob(observer, source, http_stream_job_source);
 
   LoadTimingObserver::URLRequestRecord* record =
       observer.GetURLRequestRecord(0);