Fix for reverted cl http://codereview.chromium.org/147123

A recent change broke the load times. It also revealed some deficiencies.
This adds a new time marker for when a load is committed, which is
a more interesting value than the start of the load (which we still keep).
Also, the first layout time wasn't an interesting time to keep, instead
we keep the time of the first paint.
The histograms were modified to use the new values when appropriate.

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

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

7 files changed, 93 insertions, 38 deletions

diff --git a/chrome/browser/download/download_uitest.cc b/chrome/browser/download/download_uitest.cc
index a9a5125..c35bafc 100644
--- a/chrome/browser/download/download_uitest.cc
+++ b/chrome/browser/download/download_uitest.cc
@@ -329,6 +329,7 @@ TEST_F(DownloadTest, MAYBE_IncognitoDownload) {
 
   // Download something.
   FilePath file(FILE_PATH_LITERAL("download-test1.lib"));
+  //PlatformThread::Sleep(1000);
   ASSERT_TRUE(tab->NavigateToURL(
       URLRequestMockHTTPJob::GetMockUrl(file.ToWStringHack())));
   PlatformThread::Sleep(action_timeout_ms());
diff --git a/chrome/renderer/loadtimes_extension_bindings.cc b/chrome/renderer/loadtimes_extension_bindings.cc
index 4b800a7..5a65af7 100644
--- a/chrome/renderer/loadtimes_extension_bindings.cc
+++ b/chrome/renderer/loadtimes_extension_bindings.cc
@@ -29,10 +29,10 @@ class LoadTimesExtensionWrapper : public v8::Extension {
   // navigationType: A string describing what user action initiated the load
   LoadTimesExtensionWrapper() :
     v8::Extension(kLoadTimesExtensionName,
-      "var chromium;"
-      "if (!chromium)"
-      "  chromium = {};"
-      "chromium.GetLoadTimes = function() {"
+      "var chrome;"
+      "if (!chrome)"
+      "  chrome = {};"
+      "chrome.GetLoadTimes = function() {"
       "  native function GetLoadTimes();"
       "  return GetLoadTimes();"
       "}") {}
@@ -78,6 +78,9 @@ class LoadTimesExtensionWrapper : public v8::Extension {
             v8::String::New("startLoadTime"),
             v8::Number::New(navigation_state->start_load_time().ToDoubleT()));
         load_times->Set(
+            v8::String::New("commitLoadTime"),
+            v8::Number::New(navigation_state->commit_load_time().ToDoubleT()));
+        load_times->Set(
             v8::String::New("finishDocumentLoadTime"),
             v8::Number::New(
                 navigation_state->finish_document_load_time().ToDoubleT()));
@@ -85,11 +88,12 @@ class LoadTimesExtensionWrapper : public v8::Extension {
             v8::String::New("finishLoadTime"),
             v8::Number::New(navigation_state->finish_load_time().ToDoubleT()));
         load_times->Set(
-            v8::String::New("firstLayoutTime"),
-            v8::Number::New(navigation_state->first_layout_time().ToDoubleT()));
+            v8::String::New("firstPaintTime"),
+            v8::Number::New(navigation_state->first_paint_time().ToDoubleT()));
         load_times->Set(
             v8::String::New("navigationType"),
             v8::String::New(GetNavigationType(data_source->navigationType())));
+
         return load_times;
       }
     }
diff --git a/chrome/renderer/navigation_state.h b/chrome/renderer/navigation_state.h
index 7d6aed5..46c17f3 100644
--- a/chrome/renderer/navigation_state.h
+++ b/chrome/renderer/navigation_state.h
@@ -54,7 +54,7 @@ class NavigationState : public WebKit::WebDataSource::ExtraData {
     request_time_ = value;
   }
 
-  // The time that this navigation actually started.
+  // The time that the document load started.
   const base::Time& start_load_time() const {
     return start_load_time_;
   }
@@ -62,6 +62,14 @@ class NavigationState : public WebKit::WebDataSource::ExtraData {
     start_load_time_ = value;
   }
 
+  // The time that the document load was committed.
+  const base::Time& commit_load_time() const {
+    return commit_load_time_;
+  }
+  void set_commit_load_time(const base::Time& value) {
+    commit_load_time_ = value;
+  }
+
   // The time that the document finished loading.
   const base::Time& finish_document_load_time() const {
     return finish_document_load_time_;
@@ -79,11 +87,11 @@ class NavigationState : public WebKit::WebDataSource::ExtraData {
   }
 
   // The time that layout first ran after a new navigation.
-  const base::Time& first_layout_time() const {
-    return first_layout_time_;
+  const base::Time& first_paint_time() const {
+    return first_paint_time_;
   }
-  void set_first_layout_time(const base::Time& value) {
-    first_layout_time_ = value;
+  void set_first_paint_time(const base::Time& value) {
+    first_paint_time_ = value;
   }
 
   // True if we have already processed the "DidCommitLoad" event for this
@@ -123,9 +131,10 @@ class NavigationState : public WebKit::WebDataSource::ExtraData {
   PageTransition::Type transition_type_;
   base::Time request_time_;
   base::Time start_load_time_;
+  base::Time commit_load_time_;
   base::Time finish_document_load_time_;
   base::Time finish_load_time_;
-  base::Time first_layout_time_;
+  base::Time first_paint_time_;
   bool request_committed_;
   bool is_content_initiated_;
   int32 pending_page_id_;
diff --git a/chrome/renderer/render_view.cc b/chrome/renderer/render_view.cc
index d1aea1c..7d326f0 100644
--- a/chrome/renderer/render_view.cc
+++ b/chrome/renderer/render_view.cc
@@ -1072,6 +1072,25 @@ void RenderView::DidCreateDataSource(WebFrame* frame, WebDataSource* ds) {
   }
 }
 
+void RenderView::DidPaint() {
+  WebFrame* main_frame = webview()->GetMainFrame();
+
+  if (main_frame->GetProvisionalDataSource()) {
+    // If we have a provisional frame we are between the start
+    // and commit stages of loading...ignore this paint.
+    return;
+  }
+
+  WebDataSource* ds = main_frame->GetDataSource();
+  NavigationState* navigation_state = NavigationState::FromDataSource(ds);
+  // TODO(darin): It should not be possible for navigation_state to
+  // be null here! But the UI test DownloadTest.IncognitoDownload
+  // can cause it to happen.
+  if (navigation_state && navigation_state->first_paint_time().is_null()) {
+    navigation_state->set_first_paint_time(Time::Now());
+  }
+}
+
 void RenderView::DidStartProvisionalLoadForFrame(
     WebView* webview,
     WebFrame* frame,
@@ -1238,6 +1257,7 @@ void RenderView::DidCommitLoadForFrame(WebView *webview, WebFrame* frame,
   NavigationState* navigation_state =
       NavigationState::FromDataSource(frame->GetDataSource());
 
+  navigation_state->set_commit_load_time(Time::Now());
   if (is_new_navigation) {
     // When we perform a new navigation, we need to update the previous session
     // history entry with state for the page we are leaving.
@@ -1297,6 +1317,9 @@ void RenderView::DidReceiveTitle(WebView* webview,
 }
 
 void RenderView::DidFinishLoadForFrame(WebView* webview, WebFrame* frame) {
+  WebDataSource* ds = frame->GetDataSource();
+  NavigationState* navigation_state = NavigationState::FromDataSource(ds);
+  navigation_state->set_finish_load_time(Time::Now());
   if (webview->GetMainFrame() == frame) {
     const GURL& url = frame->GetURL();
     if (url.SchemeIs("http") || url.SchemeIs("https"))
@@ -1314,6 +1337,10 @@ void RenderView::DidFailLoadWithError(WebView* webview,
 
 void RenderView::DidFinishDocumentLoadForFrame(WebView* webview,
                                                WebFrame* frame) {
+  WebDataSource* ds = frame->GetDataSource();
+  NavigationState* navigation_state = NavigationState::FromDataSource(ds);
+  navigation_state->set_finish_document_load_time(Time::Now());
+
   Send(new ViewHostMsg_DocumentLoadedInFrame(routing_id_));
 
   // The document has now been fully loaded.  Scan for password forms to be
@@ -1764,8 +1791,6 @@ WebPluginDelegate* RenderView::CreatePluginDelegate(
   if (!proxy)
     return NULL;
 
-  // We hold onto the proxy so we can poke it when we are painting.  See our
-  // DidPaint implementation below.
   plugin_delegates_.push_back(proxy);
 
   return proxy;
@@ -2782,21 +2807,23 @@ void RenderView::OnExtensionResponse(int request_id,
 
 // Dump all load time histograms.
 //
-// There are 7 histograms measuring various times.
+// There are 8 histograms measuring various times.
 // The time points we keep are
 //    request: time document was requested by user
 //    start: time load of document started
+//    commit: time load of document started
 //    finishDoc: main document loaded, before onload()
 //    finish: after onload() and all resources are loaded
 //    firstLayout: first layout performed
 // The times that we histogram are
-//    requestToStart,
-//    startToFinishDoc,
-//    finishDocToFinish,
-//    startToFinish,
-//    requestToFinish,
-//    requestToFirstLayout
-//    startToFirstLayout
+//    request->start,
+//    request->commit,
+//    request->finish,
+//    request->firstPaint
+//    start->finishDoc,
+//    commit->finish,
+//    commit->firstPaint
+//    finishDoc->finish,
 //
 // It's possible for the request time not to be set, if a client
 // redirect had been done (the user never requested the page)
@@ -2809,39 +2836,43 @@ void RenderView::DumpLoadHistograms() const {
 
   Time request_time = navigation_state->request_time();
   Time start_load_time = navigation_state->start_load_time();
+  Time commit_load_time = navigation_state->commit_load_time();
   Time finish_document_load_time =
       navigation_state->finish_document_load_time();
   Time finish_load_time = navigation_state->finish_load_time();
-  Time first_layout_time = navigation_state->first_layout_time();
+  Time first_paint_time = navigation_state->first_paint_time();
 
   TimeDelta request_to_start = start_load_time - request_time;
-  TimeDelta start_to_finish_doc = finish_document_load_time - start_load_time;
+  TimeDelta request_to_commit = commit_load_time - request_time;
+  TimeDelta commit_to_finish_doc = finish_document_load_time - commit_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 commit_to_finish = finish_load_time - commit_load_time;
   TimeDelta request_to_finish = finish_load_time - request_time;
-  TimeDelta request_to_first_layout = first_layout_time - request_time;
-  TimeDelta start_to_first_layout = first_layout_time - start_load_time;
+  TimeDelta request_to_first_paint = first_paint_time - request_time;
+  TimeDelta commit_to_first_paint = first_paint_time - commit_load_time;
 
   // Client side redirects will have no request time
   if (request_time.ToInternalValue() != 0) {
-    UMA_HISTOGRAM_MEDIUM_TIMES("Renderer2.RequestToStart", request_to_start);
+    UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.RequestToStart", request_to_start);
+    UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.RequestToCommit", request_to_commit);
     UMA_HISTOGRAM_CUSTOM_TIMES(
-        FieldTrial::MakeName("Renderer2.RequestToFinish_2", "DnsImpact").data(),
+        FieldTrial::MakeName("Renderer3.RequestToFinish_2", "DnsImpact").data(),
         request_to_finish, TimeDelta::FromMilliseconds(10),
         TimeDelta::FromMinutes(10), 100);
-    if (request_to_first_layout.ToInternalValue() >= 0) {
-      UMA_HISTOGRAM_MEDIUM_TIMES("Renderer2.RequestToFirstLayout",
-          request_to_first_layout);
+    if (request_to_first_paint.ToInternalValue() >= 0) {
+      UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.RequestToFirstPaint",
+          request_to_first_paint);
     }
   }
-  UMA_HISTOGRAM_MEDIUM_TIMES("Renderer2.StartToFinishDoc", start_to_finish_doc);
-  UMA_HISTOGRAM_MEDIUM_TIMES("Renderer2.FinishDocToFinish",
+  UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.CommitToFinishDoc",
+                             commit_to_finish_doc);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.FinishDocToFinish",
                              finish_doc_to_finish);
-  UMA_HISTOGRAM_MEDIUM_TIMES("Renderer2.StartToFinish", start_to_finish);
-  if (start_to_first_layout.ToInternalValue() >= 0) {
-    UMA_HISTOGRAM_MEDIUM_TIMES("Renderer2.StartToFirstLayout",
-                               start_to_first_layout);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.CommitToFinish", commit_to_finish);
+  if (commit_to_first_paint.ToInternalValue() >= 0) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("Renderer3.CommitToFirstPaint",
+                               commit_to_first_paint);
   }
 }
 
diff --git a/chrome/renderer/render_view.h b/chrome/renderer/render_view.h
index 97f8130..66b16a0 100644
--- a/chrome/renderer/render_view.h
+++ b/chrome/renderer/render_view.h
@@ -375,6 +375,9 @@ class RenderView : public RenderWidget,
   virtual void OnResize(const gfx::Size& new_size,
                         const gfx::Rect& resizer_rect);
 
+  // RenderWidget override
+  virtual void DidPaint();
+
  private:
   // For unit tests.
   friend class RenderViewTest;
diff --git a/chrome/renderer/render_widget.cc b/chrome/renderer/render_widget.cc
index 5b9e0c3..2b359d4 100644
--- a/chrome/renderer/render_widget.cc
+++ b/chrome/renderer/render_widget.cc
@@ -247,6 +247,9 @@ void RenderWidget::OnPaintRectAck() {
     current_paint_buf_ = NULL;
   }
 
+  // Notify subclasses
+  DidPaint();
+
   // Continue painting if necessary...
   DoDeferredPaint();
 }
diff --git a/chrome/renderer/render_widget.h b/chrome/renderer/render_widget.h
index 440a7e2..fe69433 100644
--- a/chrome/renderer/render_widget.h
+++ b/chrome/renderer/render_widget.h
@@ -148,6 +148,10 @@ class RenderWidget : public IPC::Channel::Listener,
   void OnMsgRepaint(const gfx::Size& size_to_paint);
   void OnSetTextDirection(int direction);
 
+  // Override point to notify that a paint has happened. This fires after the
+  // browser side has updated the screen for a newly painted region.
+  virtual void DidPaint() {}
+
   // True if a PaintRect_ACK message is pending.
   bool paint_reply_pending() const {
     return paint_reply_pending_;