Switch various performance tests to produce output for use by the new generic

plotting log parser.

BUG=b/1221588
TEST=once scripts and data are also switched, perf tests still plot

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

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

6 files changed, 165 insertions, 110 deletions

diff --git a/chrome/test/page_cycler/page_cycler_test.cc b/chrome/test/page_cycler/page_cycler_test.cc
index b3f3355..25883aa 100644
--- a/chrome/test/page_cycler/page_cycler_test.cc
+++ b/chrome/test/page_cycler/page_cycler_test.cc
@@ -89,7 +89,6 @@ class PageCyclerTest : public UITest {
   }
 
   void PrintIOPerfInfo(const wchar_t* test_name) {
-    printf("\n");
     BrowserProcessFilter chrome_filter(L"");
     process_util::NamedProcessIterator
         chrome_process_itr(chrome::kBrowserProcessExecutableName,
@@ -109,34 +108,49 @@ class PageCyclerTest : public UITest {
       ZeroMemory(&io_counters, sizeof(io_counters));
 
       if (process_metrics.get()->GetIOCounters(&io_counters)) {
-        wchar_t* browser_name = L"browser";
-        wchar_t* render_name = L"render";
-        wchar_t* chrome_name;
-        if (pid == chrome_filter.browser_process_id()) {
-          chrome_name = browser_name;
-        } else {
-          chrome_name = render_name;
-        }
-
-        // print out IO performance
-        wprintf(L"%ls_%ls_read_op = %d\n",
-                test_name, chrome_name, io_counters.ReadOperationCount);
-        wprintf(L"%ls_%ls_write_op = %d\n",
-                test_name, chrome_name, io_counters.WriteOperationCount);
-        wprintf(L"%ls_%ls_other_op = %d\n",
-                test_name, chrome_name, io_counters.OtherOperationCount);
-        wprintf(L"%ls_%ls_read_byte = %d K\n",
-                test_name, chrome_name, io_counters.ReadTransferCount / 1024);
-        wprintf(L"%ls_%ls_write_byte = %d K\n",
-                test_name, chrome_name, io_counters.WriteTransferCount / 1024);
-        wprintf(L"%ls_%ls_other_byte = %d K\n",
-                test_name, chrome_name, io_counters.OtherTransferCount / 1024);
+        // Print out IO performance.  We assume that the values can be
+        // converted to size_t (they're reported as ULONGLONG, 64-bit numbers).
+        std::wstring chrome_name =
+            (pid == chrome_filter.browser_process_id()) ? L"_b" : L"_r";
+
+        PrintResult(L"read_op", chrome_name, chrome_name + test_name,
+                    static_cast<size_t>(io_counters.ReadOperationCount), L"",
+                    false /* not important */);
+        PrintResult(L"write_op", chrome_name, chrome_name + test_name,
+                    static_cast<size_t>(io_counters.WriteOperationCount), L"",
+                    false /* not important */);
+        PrintResult(L"other_op", chrome_name, chrome_name + test_name,
+                    static_cast<size_t>(io_counters.OtherOperationCount), L"",
+                    false /* not important */);
+
+        size_t total = static_cast<size_t>(io_counters.ReadOperationCount +
+                                           io_counters.WriteOperationCount +
+                                           io_counters.OtherOperationCount);
+        PrintResult(L"total_op", chrome_name, chrome_name + test_name,
+                    total, L"", true /* important */);
+
+        PrintResult(L"read_byte", chrome_name, chrome_name + test_name,
+                    static_cast<size_t>(io_counters.ReadTransferCount / 1024),
+                    L"kb", false /* not important */);
+        PrintResult(L"write_byte", chrome_name, chrome_name + test_name,
+                    static_cast<size_t>(io_counters.WriteTransferCount / 1024),
+                    L"kb", false /* not important */);
+        PrintResult(L"other_byte", chrome_name, chrome_name + test_name,
+                    static_cast<size_t>(io_counters.OtherTransferCount / 1024),
+                    L"kb", false /* not important */);
+
+        total = static_cast<size_t>((io_counters.ReadTransferCount +
+                                     io_counters.WriteTransferCount +
+                                     io_counters.OtherTransferCount) / 1024);
+        PrintResult(L"total_byte", chrome_name, chrome_name + test_name,
+                    total, L"kb", true /* important */);
+
+
       }
     }
   }
 
   void PrintMemoryUsageInfo(const wchar_t* test_name) {
-    printf("\n");
     BrowserProcessFilter chrome_filter(L"");
     process_util::NamedProcessIterator
         chrome_process_itr(chrome::kBrowserProcessExecutableName,
@@ -151,25 +165,29 @@ class PageCyclerTest : public UITest {
       size_t current_working_set_size;
       if (GetMemoryInfo(pid, &peak_virtual_size, &current_virtual_size,
                         &peak_working_set_size, &current_working_set_size)) {
-        if (pid == chrome_filter.browser_process_id()) {
-          wprintf(L"%ls_browser_vm_peak = %d\n", test_name, peak_virtual_size);
-          wprintf(L"%ls_browser_vm_final = %d\n", test_name,
-                                                  current_virtual_size);
-          wprintf(L"%ls_browser_ws_peak = %d\n", test_name,
-                                                  peak_working_set_size);
-          wprintf(L"%ls_browser_ws_final = %d\n", test_name,
-                                                  current_working_set_size);
-        } else {
-          wprintf(L"%ls_render_vm_peak = %d\n", test_name, peak_virtual_size);
-          wprintf(L"%ls_render_vm_final = %d\n", test_name,
-                                                 current_virtual_size);
-          wprintf(L"%ls_render_ws_peak = %d\n", test_name,
-                                                peak_working_set_size);
-          wprintf(L"%ls_render_ws_final = %d\n", test_name,
-                                                 current_working_set_size);
-        }
+
+        std::wstring chrome_name =
+            (pid == chrome_filter.browser_process_id()) ? L"_b" : L"_r";
+
+        std::wstring trace_name(test_name);
+        PrintResult(L"vm_peak", chrome_name,
+                    L"vm_pk" + chrome_name + trace_name,
+                    peak_virtual_size, L"bytes",
+                    true /* important */);
+        PrintResult(L"vm_final", chrome_name,
+                    L"vm_f" + chrome_name + trace_name,
+                    current_virtual_size, L"bytes",
+                    false /* not important */);
+        PrintResult(L"ws_peak", chrome_name,
+                    L"ws_pk" + chrome_name + trace_name,
+                    peak_working_set_size, L"bytes",
+                    true /* important */);
+        PrintResult(L"ws_final", chrome_name,
+                    L"ws_pk" + chrome_name + trace_name,
+                    current_working_set_size, L"bytes",
+                    false /* not important */);
       }
-    };
+    }
   }
 
   // When use_http is true, the test name passed here will be used directly in
@@ -182,12 +200,12 @@ class PageCyclerTest : public UITest {
     if (timings.empty())
       return;
 
-    PrintMemoryUsageInfo(L"__pc");
-    PrintIOPerfInfo(L"__pc");
+    PrintMemoryUsageInfo(L"");
+    PrintIOPerfInfo(L"");
 
-    printf("\n");
-    wprintf(L"__pc_pages = [%ls]\n", pages.c_str());
-    wprintf(L"__pc_timings = [%ls]\n", timings.c_str());
+    wprintf(L"\nPages: [%ls]\n", pages.c_str());
+    PrintResultList(L"times", L"", L"t", timings, L"ms",
+                    true /* important */);
   }
 };
 
@@ -210,11 +228,11 @@ class PageCyclerReferenceTest : public PageCyclerTest {
     if (timings.empty())
       return;
 
-    PrintMemoryUsageInfo(L"__pc_reference");
-    PrintIOPerfInfo(L"__pc_reference");
+    PrintMemoryUsageInfo(L"_ref");
+    PrintIOPerfInfo(L"_ref");
 
-    printf("\n");
-    wprintf(L"__pc_reference_timings = [%ls]\n", timings.c_str());
+    PrintResultList(L"times", L"", L"t_ref", timings, L"ms",
+                    true /* important */);
   }
 };
 
diff --git a/chrome/test/startup/feature_startup_test.cc b/chrome/test/startup/feature_startup_test.cc
index 08b44e1..ce37879 100644
--- a/chrome/test/startup/feature_startup_test.cc
+++ b/chrome/test/startup/feature_startup_test.cc
@@ -39,20 +39,18 @@ class NewTabUIStartupTest : public UITest {
 
   static const int kNumCycles = 5;
 
-  void PrintTimings(const char* label, TimeDelta timings[kNumCycles]) {
-    printf("\n%s = [", label);
-    for (int i = 0; i < kNumCycles; ++i) {
-      if (i > 0)
-        printf(",");
-      printf("%.2f", timings[i].InMillisecondsF());
-    }
-    printf("]\n");
+  void PrintTimings(const wchar_t* label, TimeDelta timings[kNumCycles],
+                    bool important) {
+    std::wstring times;
+    for (int i = 0; i < kNumCycles; ++i)
+      StringAppendF(&times, L"%.2f,", timings[i].InMillisecondsF());
+    PrintResultList(L"new_tab", L"", label, times, L"ms", important);
   }
 
   // Run the test, by bringing up a browser and timing the new tab startup.
   // |want_warm| is true if we should output warm-disk timings, false if
   // we should report cold timings.
-  void RunStartupTest(bool want_warm) {
+  void RunStartupTest(const wchar_t* label, bool want_warm, bool important) {
     // Install the location of the test profile file.
     set_template_user_data(ComputeTypicalUserDataSource());
 
@@ -94,41 +92,18 @@ class NewTabUIStartupTest : public UITest {
       UITest::TearDown();
     }
 
-    // The buildbot log-scraper looks for this "__.._pages" line to tell when
-    // the test has completed and how many pages it loaded.
-    printf("\n__ts_pages = [about:blank]\n");
-    PrintTimings("__ts_timings", timings);
+    PrintTimings(label, timings, important);
   }
 };
 
-// The name of this test is important, since the buildbot runs with a gTest
-// filter.
-typedef NewTabUIStartupTest NewTabUIStartupTestReference;
-
 }  // namespace
 
+// TODO(pamg): run these tests with a reference build?
+
 TEST_F(NewTabUIStartupTest, PerfCold) {
-  RunStartupTest(false);
+  RunStartupTest(L"tab_cold", false /* not cold */, true /* important */);
 }
 
 TEST_F(NewTabUIStartupTest, DISABLED_PerfWarm) {
-  RunStartupTest(true);
-}
-
-TEST_F(NewTabUIStartupTestReference, FakePerfForLogScraperCold) {
-  // Print an empty reference-test result line so the log-scraper is happy.
-  // TODO(pamg): really run the test with a reference build?
-  TimeDelta timings[kNumCycles];
-  for (int i = 0; i < kNumCycles; ++i)
-    timings[i] = TimeDelta::FromMilliseconds(0);
-  PrintTimings("__ts_reference_timings", timings);
-}
-
-TEST_F(NewTabUIStartupTestReference, FakePerfForLogScraperWarm) {
-  // Print an empty reference-test result line so the log-scraper is happy.
-  // TODO(pamg): really run the test with a reference build?
-  TimeDelta timings[kNumCycles];
-  for (int i = 0; i < kNumCycles; ++i)
-    timings[i] = TimeDelta::FromMilliseconds(0);
-  PrintTimings("__ts_reference_timings", timings);
+  RunStartupTest(L"tab_warm", true /* cold */, false /* not important */);
 }
diff --git a/chrome/test/startup/startup_test.cc b/chrome/test/startup/startup_test.cc
index d6b8c3b..10d0bff 100644
--- a/chrome/test/startup/startup_test.cc
+++ b/chrome/test/startup/startup_test.cc
@@ -4,6 +4,7 @@
 
 #include "base/file_util.h"
 #include "base/path_service.h"
+#include "base/string_util.h"
 #include "base/time.h"
 #include "chrome/common/chrome_paths.h"
 #include "chrome/test/ui/ui_test.h"
@@ -32,7 +33,7 @@ class StartupTest : public UITest {
   void SetUp() {}
   void TearDown() {}
 
-  void RunStartupTest(const char* label, bool test_cold) {
+  void RunStartupTest(const wchar_t* label, bool test_cold, bool important) {
     const int kNumCycles = 20;
 
     // Make a backup of gears.dll so we can overwrite the original, which
@@ -73,14 +74,10 @@ class StartupTest : public UITest {
     ASSERT_TRUE(file_util::Delete(chrome_dll_copy, false));
     ASSERT_TRUE(file_util::Delete(gears_dll_copy, false));
 
-    printf("\n__ts_pages = [%s]\n", pages_.c_str());
-    printf("\n%s = [", label);
-    for (int i = 0; i < kNumCycles; ++i) {
-      if (i > 0)
-        printf(",");
-      printf("%.2f", timings[i].InMillisecondsF());
-    }
-    printf("]\n");
+    std::wstring times;
+    for (int i = 0; i < kNumCycles; ++i)
+      StringAppendF(&times, L"%.2f,", timings[i].InMillisecondsF());
+    PrintResultList(L"startup", L"", label, times, L"ms", important);
   }
 
  protected:
@@ -117,24 +114,24 @@ class StartupFileTest : public StartupTest {
 }  // namespace
 
 TEST_F(StartupTest, Perf) {
-  RunStartupTest("__ts_timings", false);
+  RunStartupTest(L"warm", false /* not cold */, true /* important */);
 }
 
 TEST_F(StartupReferenceTest, Perf) {
-  RunStartupTest("__ts_reference_timings", false);
+  RunStartupTest(L"warm_ref", false /* not cold */, true /* important */);
 }
 
 // TODO(mpcomplete): Should we have reference timings for all these?
 
 TEST_F(StartupTest, PerfCold) {
-  RunStartupTest("__ts_cold_timings", true);
+  RunStartupTest(L"cold", true /* cold */, false /* not important */);
 }
 
 TEST_F(StartupFileTest, PerfGears) {
-  RunStartupTest("__ts_gears_timings", false);
+  RunStartupTest(L"gears", false /* not cold */, false /* not important */);
 }
 
 TEST_F(StartupFileTest, PerfColdGears) {
-  RunStartupTest("__ts_cold_gears_timings", true);
+  RunStartupTest(L"gears_cold", true /* cold */, false /* not important */);
 }
 
diff --git a/chrome/test/tab_switching/tab_switching_test.cc b/chrome/test/tab_switching/tab_switching_test.cc
index 11c7c19..14a993a 100644
--- a/chrome/test/tab_switching/tab_switching_test.cc
+++ b/chrome/test/tab_switching/tab_switching_test.cc
@@ -101,10 +101,9 @@ class TabSwitchingUITest : public UITest {
     }
 
     // Print the average and standard deviation.
-    // Format: __tsw_timings = [512.00, 419.17]
-    //         Where 512.00 = average
-    //               419.17 = std dev.
-    printf("__tsw_timings = [%s,%s]\n", average.c_str(), std_dev.c_str());
+    PrintResultMeanAndError(L"tab_switch", L"", L"t",
+        ASCIIToWide(average) + L", " + ASCIIToWide(std_dev), L"ms",
+        true /* important */);
   }
 
  protected:
diff --git a/chrome/test/ui/ui_test.cc b/chrome/test/ui/ui_test.cc
index a9e799f..f0aec29 100644
--- a/chrome/test/ui/ui_test.cc
+++ b/chrome/test/ui/ui_test.cc
@@ -582,9 +582,29 @@ void UITest::PrintResult(const std::wstring& measurement,
                          size_t value,
                          const std::wstring& units,
                          bool important) {
-  wprintf(L"%lsRESULT %ls%ls: %ls= %d %ls\n",
-          important ? L"*" : L"", measurement.c_str(), modifier.c_str(),
-          trace.c_str(), value, units.c_str());
+  std::wstring value_str = StringPrintf(L"%d", value);
+  PrintResultsImpl(measurement, modifier, trace, value_str,
+                   L"", L"", units, important);
+}
+
+void UITest::PrintResultMeanAndError(const std::wstring& measurement,
+                                     const std::wstring& modifier,
+                                     const std::wstring& trace,
+                                     const std::wstring& mean_and_error,
+                                     const std::wstring& units,
+                                     bool important) {
+  PrintResultsImpl(measurement, modifier, trace, mean_and_error,
+                   L"{", L"}", units, important);
+}
+
+void UITest::PrintResultList(const std::wstring& measurement,
+                             const std::wstring& modifier,
+                             const std::wstring& trace,
+                             const std::wstring& values,
+                             const std::wstring& units,
+                             bool important) {
+  PrintResultsImpl(measurement, modifier, trace, values,
+                   L"[", L"]", units, important);
 }
 
 GURL UITest::GetTestUrl(const std::wstring& test_directory,
@@ -623,4 +643,19 @@ void UITest::WaitForFinish(const std::string &name,
   EXPECT_EQ(true, test_result);
 }
 
-
+void UITest::PrintResultsImpl(const std::wstring& measurement,
+                              const std::wstring& modifier,
+                              const std::wstring& trace,
+                              const std::wstring& values,
+                              const std::wstring& prefix,
+                              const std::wstring& suffix,
+                              const std::wstring& units,
+                              bool important) {
+  // <*>RESULT <graph_name>: <trace_name>= <value> <units>
+  // <*>RESULT <graph_name>: <trace_name>= {<mean>, <std deviation>} <units>
+  // <*>RESULT <graph_name>: <trace_name>= [<value>,value,value,...,] <units>
+  wprintf(L"%lsRESULT %ls%ls: %ls= %ls%ls%ls %ls\n",
+          important ? L"*" : L"", measurement.c_str(), modifier.c_str(),
+          trace.c_str(), prefix.c_str(), values.c_str(), suffix.c_str(),
+          units.c_str());
+}
diff --git a/chrome/test/ui/ui_test.h b/chrome/test/ui/ui_test.h
index 0027c97..8c67282 100644
--- a/chrome/test/ui/ui_test.h
+++ b/chrome/test/ui/ui_test.h
@@ -160,6 +160,27 @@ class UITest : public testing::Test {
                    const std::wstring& units,
                    bool important);
 
+  // Like PrintResult(), but prints a (mean, standard deviation) result pair.
+  // The |<values>| should be two comma-seaprated numbers, the mean and
+  // standard deviation (or other error metric) of the measurement.
+  void PrintResultMeanAndError(const std::wstring& measurement,
+                               const std::wstring& modifier,
+                               const std::wstring& trace,
+                               const std::wstring& mean_and_error,
+                               const std::wstring& units,
+                               bool important);
+
+  // Like PrintResult(), but prints an entire list of results. The |values|
+  // will generally be a list of comma-separated numbers. A typical
+  // post-processing step might produce plots of their mean and standard
+  // deviation.
+  void PrintResultList(const std::wstring& measurement,
+                       const std::wstring& modifier,
+                       const std::wstring& trace,
+                       const std::wstring& values,
+                       const std::wstring& units,
+                       bool important);
+
   // Gets the directory for the currently active profile in the browser.
   std::wstring GetDownloadDirectory();
 
@@ -291,6 +312,16 @@ class UITest : public testing::Test {
   // the given message if any do.
   void AssertAppNotRunning(const std::wstring& error_message);
 
+  // Common functionality for the public PrintResults methods.
+  void PrintResultsImpl(const std::wstring& measurement,
+                        const std::wstring& modifier,
+                        const std::wstring& trace,
+                        const std::wstring& values,
+                        const std::wstring& prefix,
+                        const std::wstring& suffix,
+                        const std::wstring& units,
+                        bool important);
+
  protected:
   AutomationProxy* automation() {
     EXPECT_TRUE(server_.get());