Report data from bench_pictures in the same fashion as bench.

Move SkBenchLogger into separate files and make bench_pictures use it.
Remove sk_tools::print_msg, since SkBenchLogger is now used instead.

Combine picture_benchmark with bench_pictures, since that is the
only project that uses it.

Refactor the aggregator for bench timer data into its own class and
make bench_pictures use it.

Consolidate the various virtual PictureBenchmark::run functions
into one for reuse.

BUG=https://code.google.com/p/skia/issues/detail?id=822

Review URL: https://codereview.appspot.com/6488086

git-svn-id: http://skia.googlecode.com/svn/trunk@5432 2bbb7eff-a529-9590-31e7-b0007b416f81

5 files changed, 274 insertions, 136 deletions

diff --git a/bench/SkBenchLogger.cpp b/bench/SkBenchLogger.cpp
new file mode 100644
index 0000000000..7cda32772c
--- /dev/null
+++ b/bench/SkBenchLogger.cpp
@@ -0,0 +1,30 @@
+
+/*
+ * Copyright 2012 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#include "SkBenchLogger.h"
+#include "SkStream.h"
+
+SkBenchLogger::SkBenchLogger()
+: fFileStream(NULL) {}
+
+SkBenchLogger::~SkBenchLogger() {
+    if (fFileStream) {
+        SkDELETE(fFileStream);
+    }
+}
+
+bool SkBenchLogger::SetLogFile(const char *file) {
+    fFileStream = SkNEW_ARGS(SkFILEWStream, (file));
+    return fFileStream->isValid();
+}
+
+void SkBenchLogger::fileWrite(const char msg[], size_t size) {
+    if (fFileStream && fFileStream->isValid()) {
+        fFileStream->write(msg, size);
+    }
+}
diff --git a/bench/SkBenchLogger.h b/bench/SkBenchLogger.h
new file mode 100644
index 0000000000..5eed9d373c
--- /dev/null
+++ b/bench/SkBenchLogger.h
@@ -0,0 +1,77 @@
+
+/*
+ * Copyright 2012 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#ifndef SkBenchLogger_DEFINED
+#define SkBenchLogger_DEFINED
+
+#include "SkTypes.h"
+#include "SkString.h"
+
+class SkFILEWStream;
+
+/**
+ * Class that allows logging to a file while simultaneously logging to stdout/stderr.
+ */
+class SkBenchLogger {
+public:
+    SkBenchLogger();
+
+    /**
+     * Not virtual, since this class is not intended to be subclassed.
+     */
+    ~SkBenchLogger();
+
+    /**
+     * Specify a file to write progress logs to. Unless this is called with a valid file path,
+     * SkBenchLogger will only write to stdout/stderr.
+     */
+    bool SetLogFile(const char file[]);
+
+    /**
+     * Log an error to stderr, taking a C style string as input.
+     */
+    void logError(const char msg[]) { this->nativeLogError(msg); }
+
+    /**
+     * Log an error to stderr, taking an SkString as input.
+     */
+    void logError(const SkString& str) { this->nativeLogError(str.c_str()); }
+
+    /**
+     * Log the progress of the bench tool to both stdout and the log file specified by SetLogFile,
+     * if any, taking a C style string as input.
+     */
+    void logProgress(const char msg[]) {
+        this->nativeLogProgress(msg);
+        this->fileWrite(msg, strlen(msg));
+    }
+
+    /**
+     * Log the progress of the bench tool to both stdout and the log file specified by SetLogFile,
+     * if any, taking an SkString as input.
+     */
+    void logProgress(const SkString& str) {
+        this->nativeLogProgress(str.c_str());
+        this->fileWrite(str.c_str(), str.size());
+    }
+
+private:
+#ifdef SK_BUILD_FOR_ANDROID
+    void nativeLogError(const char msg[]) { SkDebugf("%s", msg); }
+    void nativeLogProgress(const char msg[]) { SkDebugf("%s", msg); }
+#else
+    void nativeLogError(const char msg[]) { fprintf(stderr, "%s", msg); }
+    void nativeLogProgress(const char msg[]) { printf("%s", msg); }
+#endif
+
+    void fileWrite(const char msg[], size_t size);
+
+    SkFILEWStream* fFileStream;
+};
+
+#endif // SkBenchLogger_DEFINED
diff --git a/bench/TimerData.cpp b/bench/TimerData.cpp
new file mode 100644
index 0000000000..3b4baacfcd
--- /dev/null
+++ b/bench/TimerData.cpp
@@ -0,0 +1,108 @@
+
+/*
+ * Copyright 2012 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#include "TimerData.h"
+
+#include "BenchTimer.h"
+#include <limits>
+
+using namespace std;
+
+TimerData::TimerData(const SkString& perIterTimeFormat, const SkString& normalTimeFormat)
+: fWallStr(" msecs = ")
+, fTruncatedWallStr(" Wmsecs = ")
+, fCpuStr(" cmsecs = ")
+, fTruncatedCpuStr(" Cmsecs = ")
+, fGpuStr(" gmsecs = ")
+, fWallSum(0.0)
+, fWallMin(numeric_limits<double>::max())
+, fTruncatedWallSum(0.0)
+, fTruncatedWallMin(numeric_limits<double>::max())
+, fCpuSum(0.0)
+, fCpuMin(numeric_limits<double>::max())
+, fTruncatedCpuSum(0.0)
+, fTruncatedCpuMin(numeric_limits<double>::max())
+, fGpuSum(0.0)
+, fGpuMin(numeric_limits<double>::max())
+, fPerIterTimeFormat(perIterTimeFormat)
+, fNormalTimeFormat(normalTimeFormat)
+{}
+
+static double Min(double a, double b) {
+    return (a < b) ? a : b;
+}
+
+void TimerData::appendTimes(BenchTimer* timer, bool last) {
+    SkASSERT(timer != NULL);
+    SkString formatString(fPerIterTimeFormat);
+    if (!last) {
+        formatString.append(",");
+    }
+    const char* format = formatString.c_str();
+    fWallStr.appendf(format, timer->fWall);
+    fCpuStr.appendf(format, timer->fCpu);
+    fTruncatedWallStr.appendf(format, timer->fTruncatedWall);
+    fTruncatedCpuStr.appendf(format, timer->fTruncatedCpu);
+    fGpuStr.appendf(format, timer->fGpu);
+
+    // Store the minimum values. We do not need to special case the first time since we initialized
+    // to max double.
+    fWallMin = Min(fWallMin, timer->fWall);
+    fCpuMin  = Min(fCpuMin,  timer->fCpu);
+    fTruncatedWallMin = Min(fTruncatedWallMin, timer->fTruncatedWall);
+    fTruncatedCpuMin  = Min(fTruncatedCpuMin,  timer->fTruncatedCpu);
+    fGpuMin  = Min(fGpuMin,  timer->fGpu);
+
+    // Tally the sum of each timer type.
+    fWallSum += timer->fWall;
+    fCpuSum += timer->fCpu;
+    fTruncatedWallSum += timer->fTruncatedWall;
+    fTruncatedCpuSum += timer->fTruncatedCpu;
+    fGpuSum += timer->fGpu;
+
+}
+
+SkString TimerData::getResult(bool logPerIter, bool printMin, int repeatDraw,
+                              const char *configName, bool showWallTime, bool showTruncatedWallTime,
+                              bool showCpuTime, bool showTruncatedCpuTime, bool showGpuTime) {
+    // output each repeat (no average) if logPerIter is set,
+    // otherwise output only the average
+    if (!logPerIter) {
+        const char* format = fNormalTimeFormat.c_str();
+        fWallStr.set(" msecs = ");
+        fWallStr.appendf(format, printMin ? fWallMin : fWallSum / repeatDraw);
+        fCpuStr.set(" cmsecs = ");
+        fCpuStr.appendf(format, printMin ? fCpuMin : fCpuSum / repeatDraw);
+        fTruncatedWallStr.set(" Wmsecs = ");
+        fTruncatedWallStr.appendf(format,
+                                  printMin ? fTruncatedWallMin : fTruncatedWallSum / repeatDraw);
+        fTruncatedCpuStr.set(" Cmsecs = ");
+        fTruncatedCpuStr.appendf(format,
+                                 printMin ? fTruncatedCpuMin : fTruncatedCpuSum / repeatDraw);
+        fGpuStr.set(" gmsecs = ");
+        fGpuStr.appendf(format, printMin ? fGpuMin : fGpuSum / repeatDraw);
+    }
+    SkString str;
+    str.printf("  %4s:", configName);
+    if (showWallTime) {
+        str += fWallStr;
+    }
+    if (showTruncatedWallTime) {
+        str += fTruncatedWallStr;
+    }
+    if (showCpuTime) {
+        str += fCpuStr;
+    }
+    if (showTruncatedCpuTime) {
+        str += fTruncatedCpuStr;
+    }
+    if (showGpuTime && fGpuSum > 0) {
+        str += fGpuStr;
+    }
+    return str;
+}
diff --git a/bench/TimerData.h b/bench/TimerData.h
new file mode 100644
index 0000000000..d97a0632aa
--- /dev/null
+++ b/bench/TimerData.h
@@ -0,0 +1,46 @@
+
+/*
+ * Copyright 2012 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#ifndef TimerData_DEFINED
+#define TimerData_DEFINED
+
+#include "SkString.h"
+
+class BenchTimer;
+
+class TimerData {
+public:
+    TimerData(const SkString& perIterTimeFormat, const SkString& normalTimeFormat);
+
+    /**
+     * Append the value from each timer in BenchTimer to our various strings, and update the
+     * minimum and sum times.
+     * @param BenchTimer Must not be null.
+     * @param last True if this is the last set of times to add.
+     */
+    void appendTimes(BenchTimer*, bool last);
+    SkString getResult(bool logPerIter, bool printMin, int repeatDraw, const char* configName,
+                       bool showWallTime, bool showTruncatedWallTime, bool showCpuTime,
+                       bool showTruncatedCpuTime, bool showGpuTime);
+private:
+    SkString fWallStr;
+    SkString fTruncatedWallStr;
+    SkString fCpuStr;
+    SkString fTruncatedCpuStr;
+    SkString fGpuStr;
+    double fWallSum, fWallMin;
+    double fTruncatedWallSum, fTruncatedWallMin;
+    double fCpuSum, fCpuMin;
+    double fTruncatedCpuSum, fTruncatedCpuMin;
+    double fGpuSum, fGpuMin;
+
+    SkString fPerIterTimeFormat;
+    SkString fNormalTimeFormat;
+};
+
+#endif // TimerData_DEFINED
diff --git a/bench/benchmain.cpp b/bench/benchmain.cpp
index e6f6620b31..bf5adfb098 100644
--- a/bench/benchmain.cpp
+++ b/bench/benchmain.cpp
@@ -21,6 +21,7 @@
 #include "SkGpuDevice.h"
 #endif // SK_SUPPORT_GPU
 
+#include "SkBenchLogger.h"
 #include "SkBenchmark.h"
 #include "SkCanvas.h"
 #include "SkDeferredCanvas.h"
@@ -30,56 +31,8 @@
 #include "SkImageEncoder.h"
 #include "SkNWayCanvas.h"
 #include "SkPicture.h"
-#include "SkStream.h"
 #include "SkString.h"
-
-template <typename T> const T& Min(const T& a, const T& b) {
-    return (a < b) ? a : b;
-}
-
-class SkBenchLogger {
-public:
-    SkBenchLogger() : fFileStream(NULL) {}
-    ~SkBenchLogger() {
-        if (fFileStream)
-            SkDELETE(fFileStream);
-    }
-
-    bool SetLogFile(const char file[]) {
-        fFileStream = SkNEW_ARGS(SkFILEWStream, (file));
-        return fFileStream->isValid();
-    }
-
-    void logError(const char msg[]) { nativeLogError(msg); }
-    void logError(const SkString& str) { nativeLogError(str.c_str()); }
-
-    void logProgress(const char msg[]) {
-        nativeLogProgress(msg);
-        fileWrite(msg, strlen(msg));
-    }
-    void logProgress(const SkString& str) {
-        nativeLogProgress(str.c_str());
-        fileWrite(str.c_str(), str.size());
-    }
-
-private:
-#ifdef SK_BUILD_FOR_ANDROID
-    void nativeLogError(const char msg[]) { SkDebugf("%s", msg); }
-    void nativeLogProgress(const char msg[]) { SkDebugf("%s", msg); }
-#else
-    void nativeLogError(const char msg[]) { fprintf(stderr, "%s", msg); }
-    void nativeLogProgress(const char msg[]) { printf("%s", msg); }
-#endif
-
-    void fileWrite(const char msg[], size_t size) {
-        if (fFileStream && fFileStream->isValid())
-            fFileStream->write(msg, size);
-    }
-    SkFILEWStream* fFileStream;
-
-} logger;
-
-///////////////////////////////////////////////////////////////////////////////
+#include "TimerData.h"
 
 enum benchModes {
     kNormal_benchModes,
@@ -400,7 +353,7 @@ static void help() {
              "    [-scale] [-clip] [-min] [-forceAA 1|0] [-forceFilter 1|0]\n"
              "    [-forceDither 1|0] [-forceBlend 1|0] [-strokeWidth width]\n"
              "    [-match name] [-mode normal|deferred|record|picturerecord]\n"
-             "    [-config 8888|565|GPU|ANGLE|NULLGPU] [-Dfoo bar]\n"
+             "    [-config 8888|565|GPU|ANGLE|NULLGPU] [-Dfoo bar] [-logFile filename]\n"
              "    [-h|--help]");
     SkDebugf("\n\n");
     SkDebugf("    -o outDir : Image of each bench will be put in outDir.\n");
@@ -429,7 +382,7 @@ static void help() {
              "                 record, Benchmark the time to record to an SkPicture;\n"
              "                 picturerecord, Benchmark the time to do record from a \n"
              "                                SkPicture to a SkPicture.\n");
-    SkDebugf("    -logFile : destination for writing log output, in addition to stdout.\n");
+    SkDebugf("    -logFile filename : destination for writing log output, in addition to stdout.\n");
 #if SK_SUPPORT_GPU
     SkDebugf("    -config 8888|565|GPU|ANGLE|NULLGPU : "
              "Run bench in corresponding config mode.\n");
@@ -478,6 +431,8 @@ int main (int argc, char * const argv[]) {
     SkTDArray<int> configs;
     bool userConfig = false;
 
+    SkBenchLogger logger;
+
     char* const* stop = argv + argc;
     for (++argv; argv < stop; ++argv) {
         if (strcmp(*argv, "-o") == 0) {
@@ -634,6 +589,7 @@ int main (int argc, char * const argv[]) {
                 if (!logger.SetLogFile(*argv)) {
                     SkString str;
                     str.printf("Could not open %s for writing.", *argv);
+                    logger.logError(str);
                     return -1;
                 }
             } else {
@@ -864,16 +820,7 @@ int main (int argc, char * const argv[]) {
             }
 
             // record timer values for each repeat, and their sum
-            SkString fWallStr(" msecs = ");
-            SkString fTruncatedWallStr(" Wmsecs = ");
-            SkString fCpuStr(" cmsecs = ");
-            SkString fTruncatedCpuStr(" Cmsecs = ");
-            SkString fGpuStr(" gmsecs = ");
-            double fWallSum = 0.0, fWallMin;
-            double fTruncatedWallSum = 0.0, fTruncatedWallMin;
-            double fCpuSum = 0.0, fCpuMin;
-            double fTruncatedCpuSum = 0.0, fTruncatedCpuMin;
-            double fGpuSum = 0.0, fGpuMin;
+            TimerData timerData(perIterTimeformat, normalTimeFormat);
             for (int i = 0; i < repeatDraw; i++) {
                 if ((benchMode == kRecord_benchModes
                      || benchMode == kPictureRecord_benchModes)) {
@@ -904,84 +851,14 @@ int main (int argc, char * const argv[]) {
                 // have completed
                 timer.end();
 
-                if (i == repeatDraw - 1) {
-                    // no comma after the last value
-                    fWallStr.appendf(perIterTimeformat.c_str(), timer.fWall);
-                    fCpuStr.appendf(perIterTimeformat.c_str(), timer.fCpu);
-                    fTruncatedWallStr.appendf(perIterTimeformat.c_str(), timer.fTruncatedWall);
-                    fTruncatedCpuStr.appendf(perIterTimeformat.c_str(), timer.fTruncatedCpu);
-                    fGpuStr.appendf(perIterTimeformat.c_str(), timer.fGpu);
-                } else {
-                    fWallStr.appendf(perIterTimeformat.c_str(), timer.fWall);
-                    fWallStr.appendf(",");
-                    fCpuStr.appendf(perIterTimeformat.c_str(), timer.fCpu);
-                    fCpuStr.appendf(",");
-                    fTruncatedWallStr.appendf(perIterTimeformat.c_str(), timer.fTruncatedWall);
-                    fTruncatedWallStr.appendf(",");
-                    fTruncatedCpuStr.appendf(perIterTimeformat.c_str(), timer.fTruncatedCpu);
-                    fTruncatedCpuStr.appendf(",");
-                    fGpuStr.appendf(perIterTimeformat.c_str(), timer.fGpu);
-                    fGpuStr.appendf(",");
-                }
-
-                if (0 == i) {
-                    fWallMin = timer.fWall;
-                    fCpuMin  = timer.fCpu;
-                    fTruncatedWallMin = timer.fTruncatedWall;
-                    fTruncatedCpuMin  = timer.fTruncatedCpu;
-                    fGpuMin  = timer.fGpu;
-                } else {
-                    fWallMin = Min(fWallMin, timer.fWall);
-                    fCpuMin  = Min(fCpuMin,  timer.fCpu);
-                    fTruncatedWallMin = Min(fTruncatedWallMin, timer.fTruncatedWall);
-                    fTruncatedCpuMin  = Min(fTruncatedCpuMin,  timer.fTruncatedCpu);
-                    fGpuMin  = Min(fGpuMin,  timer.fGpu);
-                }
+                timerData.appendTimes(&timer, repeatDraw - 1 == i);
 
-                fWallSum += timer.fWall;
-                fCpuSum += timer.fCpu;
-                fTruncatedWallSum += timer.fTruncatedWall;
-                fTruncatedCpuSum += timer.fTruncatedCpu;
-                fGpuSum += timer.fGpu;
             }
             if (repeatDraw > 1) {
-                // output each repeat (no average) if logPerIter is set,
-                // otherwise output only the average
-                if (!logPerIter) {
-                    fWallStr.set(" msecs = ");
-                    fWallStr.appendf(normalTimeFormat.c_str(),
-                        printMin ? fWallMin : fWallSum / repeatDraw);
-                    fCpuStr.set(" cmsecs = ");
-                    fCpuStr.appendf(normalTimeFormat.c_str(),
-                        printMin ? fCpuMin : fCpuSum / repeatDraw);
-                    fTruncatedWallStr.set(" Wmsecs = ");
-                    fTruncatedWallStr.appendf(normalTimeFormat.c_str(),
-                        printMin ? fTruncatedWallMin : fTruncatedWallSum / repeatDraw);
-                    fTruncatedCpuStr.set(" Cmsecs = ");
-                    fTruncatedCpuStr.appendf(normalTimeFormat.c_str(),
-                        printMin ? fTruncatedCpuMin : fTruncatedCpuSum / repeatDraw);
-                    fGpuStr.set(" gmsecs = ");
-                    fGpuStr.appendf(normalTimeFormat.c_str(),
-                        printMin ? fGpuMin : fGpuSum / repeatDraw);
-                }
-                SkString str;
-                str.printf("  %4s:", configName);
-                if (timerWall) {
-                    str += fWallStr;
-                }
-                if (truncatedTimerWall) {
-                    str += fTruncatedWallStr;
-                }
-                if (timerCpu) {
-                    str += fCpuStr;
-                }
-                if (truncatedTimerCpu) {
-                    str += fTruncatedCpuStr;
-                }
-                if (timerGpu && glHelper && fGpuSum > 0) {
-                    str += fGpuStr;
-                }
-                logger.logProgress(str);
+                SkString result = timerData.getResult(logPerIter, printMin, repeatDraw, configName,
+                                                      timerWall, truncatedTimerWall, timerCpu,
+                                                      truncatedTimerCpu, timerGpu && glHelper);
+                logger.logProgress(result);
             }
             if (outDir.size() > 0) {
                 saveFile(bench->getName(), configName, outDir.c_str(),