Add a RWH_TabSwitchPaintDuration histogram.

The RWH_TabSwitchPaintDuration histogram calculates
the amount of time it took after a particular view was
selected for it to be fully painted.

I modified the tab switching test to use the new tab
switch paint duration histogram in place of the whiteout
duration histogram.  As a measure, whiteout duration
would not carry a value if we kept the backing store
around for a tab, and we would end up with a result of
zero instead of a useful result.  Local results with the
new measure are consistent with the number of operations
we perform on the tabs.

The tab switching test now fails if it cannot locate
the correct histogram.  In that case, it will output
the contents of the log file for remote debugging.

BUG=4104
TEST=count of tab switch paint duration histogram
results in tab switching test equals number of tabs
used in test

First committed as: http://src.chromium.org/viewvc/chrome?view=rev&revision=31632
Reverted in: 31645

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

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

7 files changed, 64 insertions, 20 deletions

diff --git a/chrome/browser/renderer_host/render_widget_host_view_gtk.cc b/chrome/browser/renderer_host/render_widget_host_view_gtk.cc
index b54aba3..b19cb46 100644
--- a/chrome/browser/renderer_host/render_widget_host_view_gtk.cc
+++ b/chrome/browser/renderer_host/render_widget_host_view_gtk.cc
@@ -376,6 +376,8 @@ void RenderWidgetHostViewGtk::DidBecomeSelected() {
   if (!is_hidden_)
     return;
 
+  if (tab_switch_paint_time_.is_null())
+    tab_switch_paint_time_ = base::TimeTicks::Now();
   is_hidden_ = false;
   host_->WasRestored();
 }
@@ -595,6 +597,15 @@ void RenderWidgetHostViewGtk::Paint(const gfx::Rect& damage_rect) {
       // time the backing store is NULL...
       whiteout_start_time_ = base::TimeTicks();
     }
+    if (!tab_switch_paint_time_.is_null()) {
+      base::TimeDelta tab_switch_paint_duration = base::TimeTicks::Now() -
+          tab_switch_paint_time_;
+      UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration",
+          tab_switch_paint_duration);
+      // Reset tab_switch_paint_time_ to 0 so future tab selections are
+      // recorded.
+      tab_switch_paint_time_ = base::TimeTicks();
+    }
   } else {
     if (window)
       gdk_window_clear(window);
diff --git a/chrome/browser/renderer_host/render_widget_host_view_gtk.h b/chrome/browser/renderer_host/render_widget_host_view_gtk.h
index c246581..94f4f1a 100644
--- a/chrome/browser/renderer_host/render_widget_host_view_gtk.h
+++ b/chrome/browser/renderer_host/render_widget_host_view_gtk.h
@@ -120,6 +120,9 @@ class RenderWidgetHostViewGtk : public RenderWidgetHostView {
   // value returns true for is_null() if we are not recording whiteout times.
   base::TimeTicks whiteout_start_time_;
 
+  // The time it took after this view was selected for it to be fully painted.
+  base::TimeTicks tab_switch_paint_time_;
+
   // Variables used only for popups --------------------------------------------
   // Our parent widget.
   RenderWidgetHostView* parent_host_view_;
diff --git a/chrome/browser/renderer_host/render_widget_host_view_mac.h b/chrome/browser/renderer_host/render_widget_host_view_mac.h
index 9d6ffbb..67c8abf 100644
--- a/chrome/browser/renderer_host/render_widget_host_view_mac.h
+++ b/chrome/browser/renderer_host/render_widget_host_view_mac.h
@@ -140,6 +140,9 @@ class RenderWidgetHostViewMac : public RenderWidgetHostView {
   // value returns true for is_null() if we are not recording whiteout times.
   base::TimeTicks whiteout_start_time_;
 
+  // The time it took after this view was selected for it to be fully painted.
+  base::TimeTicks tab_switch_paint_time_;
+
   // Variables used by our implementaion of the NSTextInput protocol.
   // An input method of Mac calls the methods of this protocol not only to
   // notify an application of its status, but also to retrieve the status of
diff --git a/chrome/browser/renderer_host/render_widget_host_view_mac.mm b/chrome/browser/renderer_host/render_widget_host_view_mac.mm
index 82720be..d043a52 100644
--- a/chrome/browser/renderer_host/render_widget_host_view_mac.mm
+++ b/chrome/browser/renderer_host/render_widget_host_view_mac.mm
@@ -118,6 +118,8 @@ void RenderWidgetHostViewMac::DidBecomeSelected() {
   if (!is_hidden_)
     return;
 
+  if (tab_switch_paint_time_.is_null())
+    tab_switch_paint_time_ = base::TimeTicks::Now();
   is_hidden_ = false;
   render_widget_host_->WasRestored();
 }
@@ -823,6 +825,15 @@ void RenderWidgetHostViewMac::SetBackground(const SkBitmap& background) {
       // time the backing store is NULL...
       renderWidgetHostView_->whiteout_start_time_ = base::TimeTicks();
     }
+    if (!renderWidgetHostView_->tab_switch_paint_time_.is_null()) {
+      base::TimeDelta tab_switch_paint_duration = base::TimeTicks::Now() -
+          renderWidgetHostView_->tab_switch_paint_time_;
+      UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration",
+          tab_switch_paint_duration);
+      // Reset tab_switch_paint_time_ to 0 so future tab selections are
+      // recorded.
+      renderWidgetHostView_->tab_switch_paint_time_ = base::TimeTicks();
+    }
   } else {
     [[NSColor whiteColor] set];
     NSRectFill(dirtyRect);
diff --git a/chrome/browser/renderer_host/render_widget_host_view_win.cc b/chrome/browser/renderer_host/render_widget_host_view_win.cc
index f97d249..d01c410 100644
--- a/chrome/browser/renderer_host/render_widget_host_view_win.cc
+++ b/chrome/browser/renderer_host/render_widget_host_view_win.cc
@@ -255,6 +255,8 @@ void RenderWidgetHostViewWin::DidBecomeSelected() {
   if (!is_hidden_)
     return;
 
+  if (tab_switch_paint_time_.is_null())
+    tab_switch_paint_time_ = TimeTicks::Now();
   is_hidden_ = false;
   EnsureTooltip();
   render_widget_host_->WasRestored();
@@ -793,6 +795,15 @@ void RenderWidgetHostViewWin::OnPaint(HDC dc) {
       // time the backing store is NULL...
       whiteout_start_time_ = TimeTicks();
     }
+    if (!tab_switch_paint_time_.is_null()) {
+      TimeDelta tab_switch_paint_duration = TimeTicks::Now() -
+          tab_switch_paint_time_;
+      UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration",
+          tab_switch_paint_duration);
+      // Reset tab_switch_paint_time_ to 0 so future tab selections are
+      // recorded.
+      tab_switch_paint_time_ = TimeTicks();
+    }
   } else {
     DrawBackground(paint_dc.m_ps.rcPaint, &paint_dc);
     if (whiteout_start_time_.is_null())
diff --git a/chrome/browser/renderer_host/render_widget_host_view_win.h b/chrome/browser/renderer_host/render_widget_host_view_win.h
index 68db850..4601ec2 100644
--- a/chrome/browser/renderer_host/render_widget_host_view_win.h
+++ b/chrome/browser/renderer_host/render_widget_host_view_win.h
@@ -290,6 +290,9 @@ class RenderWidgetHostViewWin :
   // until that bug is fixed.
   bool renderer_accessible_;
 
+  // The time it took after this view was selected for it to be fully painted.
+  base::TimeTicks tab_switch_paint_time_;
+
   DISALLOW_COPY_AND_ASSIGN(RenderWidgetHostViewWin);
 };
 
diff --git a/chrome/test/tab_switching/tab_switching_test.cc b/chrome/test/tab_switching/tab_switching_test.cc
index d23bef9..4576fe6 100644
--- a/chrome/test/tab_switching/tab_switching_test.cc
+++ b/chrome/test/tab_switching/tab_switching_test.cc
@@ -25,7 +25,7 @@ namespace {
 // time taken for each switch. It then prints out the times on the console,
 // with the aim that the page cycler parser can interpret these numbers to
 // draw graphs for page cycler Tab Switching Performance.
-// Usage Flags: -enable-logging -dump-histograms-on-exit -log-level=0
+// Usage Flags: --enable-logging --dump-histograms-on-exit --log-level=0
 class TabSwitchingUITest : public UITest {
  public:
   TabSwitchingUITest() {
@@ -61,7 +61,7 @@ class TabSwitchingUITest : public UITest {
     EXPECT_TRUE(CloseBrowser(browser_proxy_.get(), &application_closed));
 
     // Now open the corresponding log file and collect average and std dev from
-    // the histogram stats generated for RenderWidgetHostHWND_WhiteoutDuration
+    // the histogram stats generated for RenderWidgetHost_TabSwitchPaintDuration
     FilePath log_file_name;
     ASSERT_TRUE(PathService::Get(chrome::DIR_LOGS, &log_file_name));
     log_file_name = log_file_name.AppendASCII("chrome_debug.log");
@@ -82,26 +82,28 @@ class TabSwitchingUITest : public UITest {
     const std::string average_str("average = ");
     const std::string std_dev_str("standard deviation = ");
     std::string::size_type pos = contents.find(
-        "Histogram: MPArch.RWHH_WhiteoutDuration", 0);
+        "Histogram: MPArch.RWH_TabSwitchPaintDuration", 0);
     std::string::size_type comma_pos;
     std::string::size_type number_length;
-    if (pos != std::string::npos) {
-      // Get the average.
-      pos = contents.find(average_str, pos);
-      comma_pos = contents.find(",", pos);
-      pos += average_str.length();
-      number_length = comma_pos - pos;
-      average = contents.substr(pos, number_length);
-
-      // Get the std dev.
-      pos = contents.find(std_dev_str, pos);
-      pos += std_dev_str.length();
-      comma_pos = contents.find(" ", pos);
-      number_length = comma_pos - pos;
-      std_dev = contents.substr(pos, number_length);
-    } else {
-      LOG(WARNING) << "Histogram: MPArch.RWHH_WhiteoutDuration wasn't found";
-    }
+
+    // Verify we found the TabSwitchPaintDuration histogram.
+    ASSERT_NE(pos, std::string::npos) <<
+        "Histogram: MPArch.RWH_TabSwitchPaintDuration wasn't found\n" <<
+        contents;
+
+    // Get the average.
+    pos = contents.find(average_str, pos);
+    comma_pos = contents.find(",", pos);
+    pos += average_str.length();
+    number_length = comma_pos - pos;
+    average = contents.substr(pos, number_length);
+
+    // Get the std dev.
+    pos = contents.find(std_dev_str, pos);
+    pos += std_dev_str.length();
+    comma_pos = contents.find(" ", pos);
+    number_length = comma_pos - pos;
+    std_dev = contents.substr(pos, number_length);
 
     // Print the average and standard deviation.
     PrintResultMeanAndError("tab_switch", "", "t",