DevTools: provide network log details to the WebCore's InspectorController.

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

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

5 files changed, 256 insertions, 0 deletions

diff --git a/chrome/browser/net/passive_log_collector.cc b/chrome/browser/net/passive_log_collector.cc
index 152d332..c96c3a7 100644
--- a/chrome/browser/net/passive_log_collector.cc
+++ b/chrome/browser/net/passive_log_collector.cc
@@ -241,6 +241,14 @@ void PassiveLogCollector::SourceTracker::AppendAllEntries(
   }
 }
 
+PassiveLogCollector::SourceInfo*
+PassiveLogCollector::SourceTracker::GetSourceInfo(uint32 source_id) {
+  SourceIDToInfoMap::iterator it = sources_.find(source_id);
+  if (it != sources_.end())
+    return &(it->second);
+  return NULL;
+}
+
 void PassiveLogCollector::SourceTracker::AddToDeletionQueue(
     uint32 source_id) {
   DCHECK(sources_.find(source_id) != sources_.end());
diff --git a/chrome/browser/net/passive_log_collector.h b/chrome/browser/net/passive_log_collector.h
index 7615b28..316aada1 100644
--- a/chrome/browser/net/passive_log_collector.h
+++ b/chrome/browser/net/passive_log_collector.h
@@ -142,6 +142,9 @@ class PassiveLogCollector : public ChromeNetLog::Observer {
     virtual void Clear();
     virtual void AppendAllEntries(EntryList* out) const;
 
+    // Finds a source info with given id.
+    SourceInfo* GetSourceInfo(uint32 id);
+
 #ifdef UNIT_TEST
     // Helper used to inspect the current state by unit-tests.
     // Retuns a copy of the source infos held by the tracker.
diff --git a/chrome/browser/renderer_host/async_resource_handler.cc b/chrome/browser/renderer_host/async_resource_handler.cc
index 30df3a2..3ab36a2 100644
--- a/chrome/browser/renderer_host/async_resource_handler.cc
+++ b/chrome/browser/renderer_host/async_resource_handler.cc
@@ -7,11 +7,20 @@
 #include "base/logging.h"
 #include "base/process.h"
 #include "base/shared_memory.h"
+#include "chrome/browser/browser_process.h"
+#include "chrome/browser/net/chrome_net_log.h"
 #include "chrome/browser/net/chrome_url_request_context.h"
+#include "chrome/browser/net/passive_log_collector.h"
 #include "chrome/browser/renderer_host/global_request_id.h"
 #include "chrome/browser/renderer_host/resource_dispatcher_host_request_info.h"
 #include "chrome/common/render_messages.h"
 #include "net/base/io_buffer.h"
+#include "net/base/load_flags.h"
+#include "net/base/net_log.h"
+#include "webkit/glue/resource_loader_bridge.h"
+
+using base::Time;
+using base::TimeTicks;
 
 namespace {
 
@@ -26,6 +35,22 @@ const int kInitialReadBufSize = 32768;
 // The maximum size of the shared memory buffer. (512 kilobytes).
 const int kMaxReadBufSize = 524288;
 
+// We know that this conversion is not solid and suffers from world clock
+// changes, but it should be good enough for the load timing info.
+static Time TimeTicksToTime(const TimeTicks& time_ticks) {
+  static int64 tick_to_time_offset;
+  static bool tick_to_time_offset_available = false;
+  if (!tick_to_time_offset_available) {
+    int64 cur_time = (Time::Now() - Time()).InMicroseconds();
+    int64 cur_time_ticks = (TimeTicks::Now() - TimeTicks()).InMicroseconds();
+    // If we add this number to a time tick value, it gives the timestamp.
+    tick_to_time_offset = cur_time - cur_time_ticks;
+    tick_to_time_offset_available = true;
+  }
+  return Time::FromInternalValue(time_ticks.ToInternalValue() +
+                                 tick_to_time_offset);
+}
+
 }  // namespace
 
 // Our version of IOBuffer that uses shared memory.
@@ -81,6 +106,140 @@ AsyncResourceHandler::AsyncResourceHandler(
 AsyncResourceHandler::~AsyncResourceHandler() {
 }
 
+void AsyncResourceHandler::PopulateTimingInfo(URLRequest* request,
+                                              ResourceResponse* response) {
+  uint32 source_id = request->net_log().source().id;
+  ChromeNetLog* chrome_net_log = static_cast<ChromeNetLog*>(
+      request->net_log().net_log());
+
+  PassiveLogCollector* collector = chrome_net_log->passive_collector();
+  PassiveLogCollector::SourceTracker* url_tracker =
+      static_cast<PassiveLogCollector::SourceTracker*>(collector->
+          GetTrackerForSourceType(net::NetLog::SOURCE_URL_REQUEST));
+
+  PassiveLogCollector::SourceInfo* url_request =
+      url_tracker->GetSourceInfo(source_id);
+
+  if (!url_request)
+    return;
+
+  ResourceResponseHead& response_head = response->response_head;
+  webkit_glue::ResourceLoaderBridge::LoadTimingInfo& timing =
+      response_head.load_timing;
+
+  uint32 connect_job_id = net::NetLog::Source::kInvalidId;
+
+  base::TimeTicks base_time;
+
+  for (PassiveLogCollector::EntryList::const_iterator it =
+           url_request->entries.begin();
+       it != url_request->entries.end(); ++it) {
+    const PassiveLogCollector::Entry& entry = *it;
+
+    bool is_begin = entry.phase == net::NetLog::PHASE_BEGIN;
+    bool is_end = entry.phase == net::NetLog::PHASE_END;
+
+    switch (entry.type) {
+      case net::NetLog::TYPE_URL_REQUEST_START_JOB:
+        if (is_begin) {
+          // Reset state so that we captured last redirect only.
+          timing.base_time = TimeTicksToTime(entry.time);
+          base_time = entry.time;
+          connect_job_id = net::NetLog::Source::kInvalidId;
+        }
+        break;
+      case net::NetLog::TYPE_PROXY_SERVICE:
+        if (is_begin) {
+          timing.proxy_start = static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        } else if (is_end) {
+          timing.proxy_end = static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        }
+        break;
+      case net::NetLog::TYPE_SOCKET_POOL:
+        if (is_begin) {
+          timing.connect_start = static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        } else if (is_end &&
+                       connect_job_id != net::NetLog::Source::kInvalidId) {
+          timing.connect_end = static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        }
+        break;
+      case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_CONNECT_JOB:
+        connect_job_id = static_cast<net::NetLogSourceParameter*>(
+            entry.params.get())->value().id;
+        break;
+      case net::NetLog::TYPE_SOCKET_POOL_BOUND_TO_SOCKET:
+        {
+          uint32 log_id = static_cast<net::NetLogSourceParameter*>(
+              entry.params.get())->value().id;
+          response->response_head.connection_id =
+              log_id != net::NetLog::Source::kInvalidId ? log_id : 0;
+        }
+        break;
+      case net::NetLog::TYPE_HTTP_TRANSACTION_SEND_REQUEST:
+      case net::NetLog::TYPE_SPDY_TRANSACTION_SEND_REQUEST:
+        if (is_begin) {
+          timing.send_start = static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        } else if (is_end) {
+          timing.send_end = static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        }
+        break;
+      case net::NetLog::TYPE_HTTP_TRANSACTION_READ_HEADERS:
+      case net::NetLog::TYPE_SPDY_TRANSACTION_READ_HEADERS:
+        if (is_begin) {
+          timing.receive_headers_start =  static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        } else if (is_end) {
+          timing.receive_headers_end =  static_cast<int32>(
+              (entry.time - base_time).InMillisecondsRoundedUp());
+        }
+        break;
+      default:
+        break;
+    }
+  }
+
+  // For DNS time, get the ID of the "connect job" from the
+  // BOUND_TO_CONNECT_JOB entry, in its source info look at the
+  // HOST_RESOLVER_IMPL times.
+  if (connect_job_id == net::NetLog::Source::kInvalidId) {
+    // Clean up connection time to match contract.
+    timing.connect_start = -1;
+    timing.connect_end = -1;
+    return;
+  }
+
+  PassiveLogCollector::SourceTracker* connect_job_tracker =
+      static_cast<PassiveLogCollector::SourceTracker*>(
+          collector->GetTrackerForSourceType(net::NetLog::SOURCE_CONNECT_JOB));
+  PassiveLogCollector::SourceInfo* connect_job =
+      connect_job_tracker->GetSourceInfo(connect_job_id);
+  if (!connect_job)
+    return;
+
+  for (PassiveLogCollector::EntryList::const_iterator it =
+           connect_job->entries.begin();
+       it != connect_job->entries.end(); ++it) {
+    const PassiveLogCollector::Entry& entry = *it;
+    if (entry.phase == net::NetLog::PHASE_BEGIN &&
+        entry.type == net::NetLog::TYPE_HOST_RESOLVER_IMPL) {
+      timing.dns_start = static_cast<int32>(
+          (entry.time - base_time).InMillisecondsRoundedUp());
+    } else if (entry.phase == net::NetLog::PHASE_END &&
+          entry.type == net::NetLog::TYPE_HOST_RESOLVER_IMPL) {
+      timing.dns_end = static_cast<int32>(
+          (entry.time - base_time).InMillisecondsRoundedUp());
+      // Connect time already includes dns time, subtract it here.
+      break;
+    }
+  }
+}
+
 bool AsyncResourceHandler::OnUploadProgress(int request_id,
                                             uint64 position,
                                             uint64 size) {
@@ -94,6 +253,11 @@ bool AsyncResourceHandler::OnRequestRedirected(int request_id,
                                                ResourceResponse* response,
                                                bool* defer) {
   *defer = true;
+  URLRequest* request = rdh_->GetURLRequest(
+      GlobalRequestID(process_id_, request_id));
+  // TODO(pfeldman): enable once migrated to LoadTimingObserver.
+  if (false && request && (request->load_flags() & net::LOAD_ENABLE_LOAD_TIMING))
+    PopulateTimingInfo(request, response);
   return receiver_->Send(new ViewMsg_Resource_ReceivedRedirect(
       routing_id_, request_id, new_url, response->response_head));
 }
@@ -107,6 +271,11 @@ bool AsyncResourceHandler::OnResponseStarted(int request_id,
   // or of having to layout the new content twice.
   URLRequest* request = rdh_->GetURLRequest(
       GlobalRequestID(process_id_, request_id));
+
+  // TODO(pfeldman): enable once migrated to LoadTimingObserver.
+  if (false && request->load_flags() & net::LOAD_ENABLE_LOAD_TIMING)
+    PopulateTimingInfo(request, response);
+
   ResourceDispatcherHostRequestInfo* info = rdh_->InfoForRequest(request);
   if (info->resource_type() == ResourceType::MAIN_FRAME) {
     GURL request_url(request->url());
diff --git a/chrome/browser/renderer_host/async_resource_handler.h b/chrome/browser/renderer_host/async_resource_handler.h
index 9f11c42..5442117 100644
--- a/chrome/browser/renderer_host/async_resource_handler.h
+++ b/chrome/browser/renderer_host/async_resource_handler.h
@@ -43,6 +43,8 @@ class AsyncResourceHandler : public ResourceHandler {
  private:
   ~AsyncResourceHandler();
 
+  void PopulateTimingInfo(URLRequest* request, ResourceResponse* response);
+
   scoped_refptr<SharedIOBuffer> read_buffer_;
   ResourceDispatcherHost::Receiver* receiver_;
   int process_id_;
diff --git a/chrome/common/render_messages.h b/chrome/common/render_messages.h
index 430caff..96e8a4c 100644
--- a/chrome/common/render_messages.h
+++ b/chrome/common/render_messages.h
@@ -1406,6 +1406,72 @@ struct ParamTraits<scoped_refptr<net::HttpResponseHeaders> > {
   }
 };
 
+// Traits for webkit_glue::ResourceLoaderBridge::LoadTimingInfo
+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);
+    WriteParam(m, p.proxy_start);
+    WriteParam(m, p.proxy_end);
+    WriteParam(m, p.dns_start);
+    WriteParam(m, p.dns_end);
+    WriteParam(m, p.connect_start);
+    WriteParam(m, p.connect_end);
+    WriteParam(m, p.ssl_start);
+    WriteParam(m, p.ssl_end);
+    WriteParam(m, p.send_start);
+    WriteParam(m, p.send_end);
+    WriteParam(m, p.receive_headers_start);
+    WriteParam(m, p.receive_headers_end);
+  }
+  static bool Read(const Message* m, void** iter, param_type* r) {
+    return
+        ReadParam(m, iter, &r->base_time) &&
+        ReadParam(m, iter, &r->proxy_start) &&
+        ReadParam(m, iter, &r->proxy_end) &&
+        ReadParam(m, iter, &r->dns_start) &&
+        ReadParam(m, iter, &r->dns_end) &&
+        ReadParam(m, iter, &r->connect_start) &&
+        ReadParam(m, iter, &r->connect_end) &&
+        ReadParam(m, iter, &r->ssl_start) &&
+        ReadParam(m, iter, &r->ssl_end) &&
+        ReadParam(m, iter, &r->send_start) &&
+        ReadParam(m, iter, &r->send_end) &&
+        ReadParam(m, iter, &r->receive_headers_start) &&
+        ReadParam(m, iter, &r->receive_headers_end);
+  }
+  static void Log(const param_type& p, std::wstring* l) {
+    l->append(L"(");
+    LogParam(p.base_time, l);
+    l->append(L", ");
+    LogParam(p.proxy_start, l);
+    l->append(L", ");
+    LogParam(p.proxy_end, l);
+    l->append(L", ");
+    LogParam(p.dns_start, l);
+    l->append(L", ");
+    LogParam(p.dns_end, l);
+    l->append(L", ");
+    LogParam(p.connect_start, l);
+    l->append(L", ");
+    LogParam(p.connect_end, l);
+    l->append(L", ");
+    LogParam(p.ssl_start, l);
+    l->append(L", ");
+    LogParam(p.ssl_end, l);
+    l->append(L", ");
+    LogParam(p.send_start, l);
+    l->append(L", ");
+    LogParam(p.send_end, l);
+    l->append(L", ");
+    LogParam(p.receive_headers_start, l);
+    l->append(L", ");
+    LogParam(p.receive_headers_end, l);
+    l->append(L")");
+  }
+};
+
 // Traits for webkit_glue::ResourceLoaderBridge::ResponseInfo
 template <>
 struct ParamTraits<webkit_glue::ResourceLoaderBridge::ResponseInfo> {
@@ -1420,6 +1486,8 @@ struct ParamTraits<webkit_glue::ResourceLoaderBridge::ResponseInfo> {
     WriteParam(m, p.content_length);
     WriteParam(m, p.appcache_id);
     WriteParam(m, p.appcache_manifest_url);
+    WriteParam(m, p.connection_id);
+    WriteParam(m, p.load_timing);
     WriteParam(m, p.was_fetched_via_spdy);
     WriteParam(m, p.was_npn_negotiated);
     WriteParam(m, p.was_alternate_protocol_available);
@@ -1436,6 +1504,8 @@ struct ParamTraits<webkit_glue::ResourceLoaderBridge::ResponseInfo> {
       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->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) &&
@@ -1461,6 +1531,10 @@ struct ParamTraits<webkit_glue::ResourceLoaderBridge::ResponseInfo> {
     l->append(L", ");
     LogParam(p.appcache_manifest_url, l);
     l->append(L", ");
+    LogParam(p.connection_id, l);
+    l->append(L", ");
+    LogParam(p.load_timing, l);
+    l->append(L", ");
     LogParam(p.was_fetched_via_spdy, l);
     l->append(L", ");
     LogParam(p.was_npn_negotiated, l);