- Added support for keeping track of load times.

For each document loaded we record the time the page was requested by the user
(or as close as we can get to that), the time the load process started, the time
the
document and it's dependent resources (scripts) have been loaded (before
onload())
and the time all the document's resources have been loaded.
We use this data for two things:

1) We histogram the deltas between the time marks
2) We expose the times to javascript running on the page which was loaded

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

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

10 files changed, 284 insertions, 8 deletions

diff --git a/chrome/browser/renderer_host/render_view_host.cc b/chrome/browser/renderer_host/render_view_host.cc
index 83c55a7..76bc612 100644
--- a/chrome/browser/renderer_host/render_view_host.cc
+++ b/chrome/browser/renderer_host/render_view_host.cc
@@ -9,6 +9,7 @@
 
 #include "base/gfx/native_widget_types.h"
 #include "base/string_util.h"
+#include "base/time.h"
 #include "base/waitable_event.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/cross_site_request_manager.h"
@@ -618,6 +619,7 @@ void RenderViewHost::MakeNavigateParams(const NavigationEntry& entry,
   params->transition = entry.transition_type();
   params->state = entry.content_state();
   params->reload = reload;
+  params->request_time = base::Time::Now();
 }
 
 bool RenderViewHost::CanBlur() const {
diff --git a/chrome/chrome.gyp b/chrome/chrome.gyp
index 2c6641e..f0b1161 100644
--- a/chrome/chrome.gyp
+++ b/chrome/chrome.gyp
@@ -1392,6 +1392,8 @@
         'renderer/automation/dom_automation_controller.h',
         'renderer/extensions/extension_process_bindings.cc',
         'renderer/extensions/extension_process_bindings.h',
+        'renderer/extensions/loadtimes_extension_bindings.h',
+        'renderer/extensions/loadtimes_extension_bindings.cc',
         'renderer/extensions/renderer_extension_bindings.cc',
         'renderer/extensions/renderer_extension_bindings.h',
         'renderer/media/audio_renderer_impl.cc',
diff --git a/chrome/common/render_messages.h b/chrome/common/render_messages.h
index 38af203..1c983d0 100644
--- a/chrome/common/render_messages.h
+++ b/chrome/common/render_messages.h
@@ -42,6 +42,10 @@
 #include "skia/include/SkBitmap.h"
 #endif
 
+namespace base {
+class Time;
+}
+
 struct ViewHostMsg_UpdateFeedList_Params {
   // The page_id for this navigation, or -1 if it is a new navigation.  Back,
   // Forward, and Reload navigations should have a valid page_id.  If the load
@@ -78,6 +82,9 @@ struct ViewMsg_Navigate_Params {
   // Specifies if the URL should be loaded using 'reload' semantics (i.e.,
   // bypassing any locally cached content).
   bool reload;
+
+  // The time the request was created
+  base::Time request_time;
 };
 
 // Parameters structure for ViewHostMsg_FrameNavigate, which has too many data
@@ -662,6 +669,7 @@ struct ParamTraits<ViewMsg_Navigate_Params> {
     WriteParam(m, p.transition);
     WriteParam(m, p.state);
     WriteParam(m, p.reload);
+    WriteParam(m, p.request_time);
   }
   static bool Read(const Message* m, void** iter, param_type* p) {
     return
@@ -670,7 +678,8 @@ struct ParamTraits<ViewMsg_Navigate_Params> {
       ReadParam(m, iter, &p->referrer) &&
       ReadParam(m, iter, &p->transition) &&
       ReadParam(m, iter, &p->state) &&
-      ReadParam(m, iter, &p->reload);
+      ReadParam(m, iter, &p->reload) &&
+      ReadParam(m, iter, &p->request_time);
   }
   static void Log(const param_type& p, std::wstring* l) {
     l->append(L"(");
@@ -683,6 +692,8 @@ struct ParamTraits<ViewMsg_Navigate_Params> {
     LogParam(p.state, l);
     l->append(L", ");
     LogParam(p.reload, l);
+    l->append(L", ");
+    LogParam(p.request_time, l);
     l->append(L")");
   }
 };
diff --git a/chrome/renderer/extensions/loadtimes_extension_bindings.cc b/chrome/renderer/extensions/loadtimes_extension_bindings.cc
new file mode 100644
index 0000000..b0836036
--- /dev/null
+++ b/chrome/renderer/extensions/loadtimes_extension_bindings.cc
@@ -0,0 +1,91 @@
+// Copyright (c) 2006-2009 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/renderer/extensions/loadtimes_extension_bindings.h"
+
+#include "base/time.h"
+#include "v8/include/v8.h"
+#include "webkit/glue/webframe.h"
+#include "webkit/glue/webdatasource.h"
+
+namespace extensions_v8 {
+
+static const char* kLoadTimesExtensionName = "v8/LoadTimes";
+
+class LoadTimesExtensionWrapper : public v8::Extension {
+ public:
+  // Creates an extension which adds a new function, chromium.GetLoadTimes()
+  // This function returns an object containing the following members:
+  // requestTime: The time the request to load the page was received
+  // loadTime: The time the renderer started the load process
+  // finishDocumentLoadTime: The time the document itself was loaded
+  //                         (this is before the onload() method is fired)
+  // finishLoadTime: The time all loading is done, after the onload()
+  //                 method and all resources
+  // navigationType: A string describing what user action initiated the load
+  LoadTimesExtensionWrapper() :
+    v8::Extension(kLoadTimesExtensionName,
+      "var chromium;"
+      "if (!chromium)"
+      "  chromium = {};"
+      "chromium.GetLoadTimes = function() {"
+      "  native function GetLoadTimes();"
+      "  return GetLoadTimes();"
+      "}") {}
+
+  virtual v8::Handle<v8::FunctionTemplate> GetNativeFunction(
+      v8::Handle<v8::String> name) {
+    if (name->Equals(v8::String::New("GetLoadTimes"))) {
+      return v8::FunctionTemplate::New(GetLoadTimes);
+    }
+    return v8::Handle<v8::FunctionTemplate>();
+  }
+
+  static const char *GetNavigationType(WebNavigationType nav_type) {
+    switch (nav_type) {
+      case WebNavigationTypeLinkClicked: return "LinkClicked";
+      case WebNavigationTypeFormSubmitted: return "FormSubmitted";
+      case WebNavigationTypeBackForward: return "BackForward";
+      case WebNavigationTypeReload: return "Reload";
+      case WebNavigationTypeFormResubmitted: return "Resubmitted";
+      case WebNavigationTypeOther: return "Other";
+    }
+    return "";
+  }
+
+  static v8::Handle<v8::Value> GetLoadTimes(const v8::Arguments& args) {
+    WebFrame* win_frame = WebFrame::RetrieveActiveFrame();
+    if (win_frame) {
+      WebDataSource* data_source = win_frame->GetDataSource();
+      if (data_source) {
+        v8::Local<v8::Object> load_times = v8::Object::New();
+        load_times->Set(
+            v8::String::New("requestTime"),
+            v8::Number::New(data_source->GetRequestTime().ToDoubleT()));
+        load_times->Set(
+            v8::String::New("startLoadTime"),
+            v8::Number::New(data_source->GetStartLoadTime().ToDoubleT()));
+        load_times->Set(
+            v8::String::New("finishDocumentLoadTime"),
+            v8::Number::New(
+                data_source->GetFinishDocumentLoadTime().ToDoubleT()));
+        load_times->Set(
+            v8::String::New("finishLoadTime"),
+            v8::Number::New(data_source->GetFinishLoadTime().ToDoubleT()));
+        load_times->Set(
+            v8::String::New("navigationType"),
+            v8::String::New(
+                GetNavigationType(data_source->GetNavigationType())));
+        return load_times;
+      }
+    }
+    return v8::Null();
+  }
+};
+
+v8::Extension* LoadTimesExtension::Get() {
+  return new LoadTimesExtensionWrapper();
+}
+
+}  // namespace extensions_v8
diff --git a/chrome/renderer/extensions/loadtimes_extension_bindings.h b/chrome/renderer/extensions/loadtimes_extension_bindings.h
new file mode 100644
index 0000000..4a6bcf5
--- /dev/null
+++ b/chrome/renderer/extensions/loadtimes_extension_bindings.h
@@ -0,0 +1,24 @@
+// Copyright (c) 2006-2008 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.
+
+// The LoadTimesExtension is a v8 extension to access the time it took
+// to load a page.
+
+#ifndef CHROME_RENDERER_EXTENSIONS_LOADTIMES_EXTENSION_BINDINGS_H_
+#define CHROME_RENDERER_EXTENSIONS_LOADTIMES_EXTENSION_BINDINGS_H_
+
+namespace v8 {
+class Extension;
+}
+
+namespace extensions_v8 {
+
+class LoadTimesExtension {
+ public:
+  static v8::Extension* Get();
+};
+
+}  // namespace extensions_v8
+
+#endif  // CHROME_RENDERER_EXTENSIONS_LOADTIMES_EXTENSION_BINDINGS_H_
diff --git a/chrome/renderer/render_thread.cc b/chrome/renderer/render_thread.cc
index e161438..8eb1c21 100644
--- a/chrome/renderer/render_thread.cc
+++ b/chrome/renderer/render_thread.cc
@@ -24,6 +24,7 @@
 #include "webkit/glue/weburlrequest.h"
 #endif
 #include "chrome/renderer/extensions/extension_process_bindings.h"
+#include "chrome/renderer/extensions/loadtimes_extension_bindings.h"
 #include "chrome/renderer/extensions/renderer_extension_bindings.h"
 #include "chrome/renderer/net/render_dns_master.h"
 #include "chrome/renderer/render_process.h"
@@ -269,6 +270,7 @@ void RenderThread::EnsureWebKitInitialized() {
 
   WebKit::registerExtension(extensions_v8::GearsExtension::Get());
   WebKit::registerExtension(extensions_v8::IntervalExtension::Get());
+  WebKit::registerExtension(extensions_v8::LoadTimesExtension::Get());
   WebKit::registerExtension(
       extensions_v8::RendererExtensionBindings::Get(this));
 
diff --git a/chrome/renderer/render_view.cc b/chrome/renderer/render_view.cc
index 2feecfc..a13c74f 100644
--- a/chrome/renderer/render_view.cc
+++ b/chrome/renderer/render_view.cc
@@ -82,6 +82,7 @@
 #include "skia/ext/vector_canvas.h"
 #endif
 
+using base::Time;
 using base::TimeDelta;
 using webkit_glue::WebAccessibility;
 using WebKit::WebConsoleMessage;
@@ -134,8 +135,10 @@ namespace {
 class RenderViewExtraRequestData : public WebRequest::ExtraData {
  public:
   RenderViewExtraRequestData(int32 pending_page_id,
-                             PageTransition::Type transition)
+                             PageTransition::Type transition,
+                             Time request_time)
       : transition_type(transition),
+        request_time(request_time),
         request_committed(false),
         pending_page_id_(pending_page_id) {
   }
@@ -149,6 +152,7 @@ class RenderViewExtraRequestData : public WebRequest::ExtraData {
   // Contains the transition type that the browser specified when it
   // initiated the load.
   PageTransition::Type transition_type;
+  Time request_time;
 
   // True if we have already processed the "DidCommitLoad" event for this
   // request.  Used by session history.
@@ -807,7 +811,7 @@ void RenderView::OnNavigate(const ViewMsg_Navigate_Params& params) {
   scoped_ptr<WebRequest> request(WebRequest::Create(params.url));
   request->SetCachePolicy(cache_policy);
   request->SetExtraData(new RenderViewExtraRequestData(
-      params.page_id, params.transition));
+      params.page_id, params.transition, params.request_time));
 
   // If we are reloading, then WebKit will use the state of the current page.
   // Otherwise, we give it the state to navigate to.
@@ -1207,6 +1211,15 @@ void RenderView::DidStartProvisionalLoadForFrame(
     completed_client_redirect_src_ = GURL();
   }
 
+  WebDataSource* ds = frame->GetProvisionalDataSource();
+  if (ds) {
+    const WebRequest& req = ds->GetRequest();
+    RenderViewExtraRequestData* extra_data =
+        static_cast<RenderViewExtraRequestData*>(req.GetExtraData());
+    if (extra_data) {
+      ds->SetRequestTime(extra_data->request_time);
+    }
+  }
   Send(new ViewHostMsg_DidStartProvisionalLoadForFrame(
        routing_id_, webview->GetMainFrame() == frame,
        frame->GetProvisionalDataSource()->GetRequest().GetURL()));
@@ -1411,6 +1424,11 @@ void RenderView::DidReceiveTitle(WebView* webview,
 }
 
 void RenderView::DidFinishLoadForFrame(WebView* webview, WebFrame* frame) {
+  if (webview->GetMainFrame() == frame) {
+    const GURL& url = frame->GetURL();
+    if (url.SchemeIs("http") || url.SchemeIs("https"))
+      DumpLoadHistograms();
+  }
 }
 
 void RenderView::DidFailLoadWithError(WebView* webview,
@@ -2988,3 +3006,116 @@ void RenderView::OnExtensionResponse(int callback_id,
       web_frame, callback_id, response);
   pending_extension_callbacks_.Remove(callback_id);
 }
+
+// Dump all load time histograms. We create 2 sets time based histograms,
+// one that is specific to the navigation type and one that aggregates all
+// navigation types
+//
+// Each set contains 5 histograms measuring various times.
+// The time points we keep are
+//    request: time document was requested by user
+//    start: time load of document started
+//    finishDoc: main document loaded, before onload()
+//    finish: after onload() and all resources are loaded
+// finish_document_load_time and finish_load_time.
+// The times that we histogram are
+//    requestToStart,
+//    startToFinishDoc,
+//    finishDocToFinish,
+//    startToFinish,
+//    requestToFinish,
+//
+void RenderView::DumpLoadHistograms() const {
+  WebFrame* main_frame = webview()->GetMainFrame();
+  WebDataSource* ds = main_frame->GetDataSource();
+  WebNavigationType nav_type = ds->GetNavigationType();
+  Time request_time = ds->GetRequestTime();
+  Time start_load_time = ds->GetStartLoadTime();
+  Time finish_document_load_time = ds->GetFinishDocumentLoadTime();
+  Time finish_load_time = ds->GetFinishLoadTime();
+  TimeDelta request_to_start = start_load_time - request_time;
+  TimeDelta start_to_finish_doc = finish_document_load_time - start_load_time;
+  TimeDelta finish_doc_to_finish = finish_load_time - finish_document_load_time;
+  TimeDelta start_to_finish = finish_load_time - start_load_time;
+  TimeDelta request_to_finish = finish_load_time - start_load_time;
+
+  UMA_HISTOGRAM_TIMES("Renderer.All.RequestToStart", request_to_start);
+  UMA_HISTOGRAM_TIMES("Renderer.All.StartToFinishDoc", start_to_finish_doc);
+  UMA_HISTOGRAM_TIMES("Renderer.All.FinishDocToFinish", finish_doc_to_finish);
+  UMA_HISTOGRAM_TIMES("Renderer.All.StartToFinish", start_to_finish);
+  UMA_HISTOGRAM_TIMES("Renderer.All.RequestToFinish", request_to_finish);
+  switch (nav_type) {
+    case WebNavigationTypeLinkClicked:
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.LinkClicked.RequestToStart", request_to_start);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.LinkClicked.StartToFinishDoc", start_to_finish_doc);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.LinkClicked.FinishDocToFinish", finish_doc_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.LinkClicked.RequestToFinish", request_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.LinkClicked.StartToFinish", start_to_finish);
+      break;
+    case WebNavigationTypeFormSubmitted:
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormSubmitted.RequestToStart", request_to_start);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormSubmitted.StartToFinishDoc", start_to_finish_doc);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormSubmitted.FinishDocToFinish", finish_doc_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormSubmitted.RequestToFinish", request_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormSubmitted.StartToFinish", start_to_finish);
+      break;
+    case WebNavigationTypeBackForward:
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.BackForward.RequestToStart", request_to_start);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.BackForward.StartToFinishDoc", start_to_finish_doc);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.BackForward.FinishDocToFinish", finish_doc_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.BackForward.RequestToFinish", request_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.BackForward.StartToFinish", start_to_finish);
+      break;
+    case WebNavigationTypeReload:
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Reload.RequestToStart", request_to_start);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Reload.StartToFinishDoc", start_to_finish_doc);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Reload.FinishDocToFinish", finish_doc_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Reload.RequestToFinish", request_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Reload.StartToFinish", start_to_finish);
+      break;
+    case WebNavigationTypeFormResubmitted:
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormResubmitted.RequestToStart", request_to_start);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormResubmitted.StartToFinishDoc", start_to_finish_doc);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormResubmitted.FinishDocToFinish", finish_doc_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormResubmitted.RequestToFinish", request_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.FormResubmitted.StartToFinish", start_to_finish);
+      break;
+    case WebNavigationTypeOther:
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Other.RequestToStart", request_to_start);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Other.StartToFinishDoc", start_to_finish_doc);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Other.FinishDocToFinish", finish_doc_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Other.RequestToFinish", request_to_finish);
+      UMA_HISTOGRAM_TIMES(
+          "Renderer.Other.StartToFinish", start_to_finish);
+      break;
+  }
+}
diff --git a/chrome/renderer/render_view.h b/chrome/renderer/render_view.h
index a9c8915..a272a3f 100644
--- a/chrome/renderer/render_view.h
+++ b/chrome/renderer/render_view.h
@@ -641,6 +641,8 @@ class RenderView : public RenderWidget,
   // A helper method used by WasOpenedByUserGesture.
   bool WasOpenedByUserGestureHelper() const;
 
+  void DumpLoadHistograms() const;
+
   // Bitwise-ORed set of extra bindings that have been enabled.  See
   // BindingsPolicy for details.
   int enabled_bindings_;
diff --git a/chrome/renderer/renderer.vcproj b/chrome/renderer/renderer.vcproj
index 3a70134..3b85de0 100644
--- a/chrome/renderer/renderer.vcproj
+++ b/chrome/renderer/renderer.vcproj
@@ -185,19 +185,27 @@
 			Name="extensions"
 			>
 			<File
-				RelativePath=".\extensions\renderer_extension_bindings.cc"
+				RelativePath=".\extensions\extension_process_bindings.cc"
 				>
 			</File>
 			<File
-				RelativePath=".\extensions\renderer_extension_bindings.h"
+				RelativePath=".\extensions\extension_process_bindings.h"
 				>
 			</File>
 			<File
-				RelativePath=".\extensions\extension_process_bindings.cc"
+				RelativePath=".\extensions\loadtimes_extension_bindings.cc"
 				>
 			</File>
 			<File
-				RelativePath=".\extensions\extension_process_bindings.h"
+				RelativePath=".\extensions\loadtimes_extension_bindings.h"
+				>
+			</File>
+			<File
+				RelativePath=".\extensions\renderer_extension_bindings.cc"
+				>
+			</File>
+			<File
+				RelativePath=".\extensions\renderer_extension_bindings.h"
 				>
 			</File>
 		</Filter>
diff --git a/chrome/renderer/renderer_main.cc b/chrome/renderer/renderer_main.cc
index c9d6aa2..c6637ab 100644
--- a/chrome/renderer/renderer_main.cc
+++ b/chrome/renderer/renderer_main.cc
@@ -7,6 +7,7 @@
 #include "base/message_loop.h"
 #include "base/path_service.h"
 #include "base/platform_thread.h"
+#include "base/process_util.h"
 #include "base/scoped_nsautorelease_pool.h"
 #include "base/string_util.h"
 #include "base/system_monitor.h"
@@ -39,8 +40,10 @@ static void HandleRendererErrorTestParameters(const CommandLine& command_line) {
   if (command_line.HasSwitch(switches::kRendererStartupDialog)) {
 #if defined(OS_WIN)
     std::wstring title = l10n_util::GetString(IDS_PRODUCT_NAME);
+    std::wstring message = L"renderer starting with pid: ";
+    message += IntToWString(base::GetCurrentProcId());
     title += L" renderer";  // makes attaching to process easier
-    ::MessageBox(NULL, L"renderer starting...", title.c_str(),
+    ::MessageBox(NULL, message.c_str(), title.c_str(),
                  MB_OK | MB_SETFOREGROUND);
 #elif defined(OS_MACOSX)
     // TODO(playmobil): In the long term, overriding this flag doesn't seem