Add JSON logging support to bench_pictures by adding a PictureResultsWriter class (in tools/PictureResultsWriter.h) to process logging information, using a very similar style as bench/ResultsWriter.h

JSON format described in code, above PictureJSONResultsWriter class

BUG=skia:
R=bensong@google.com, jcgregorio@google.com

Author: kelvinly@google.com

Review URL: https://codereview.chromium.org/286903025

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

4 files changed, 283 insertions, 49 deletions

diff --git a/tools/PictureBenchmark.cpp b/tools/PictureBenchmark.cpp
index 6c0325e2ee..f1d00035cc 100644
--- a/tools/PictureBenchmark.cpp
+++ b/tools/PictureBenchmark.cpp
@@ -5,7 +5,6 @@
  * found in the LICENSE file.
  */
 
-#include "SkBenchLogger.h"
 #include "BenchTimer.h"
 #include "PictureBenchmark.h"
 #include "SkCanvas.h"
@@ -17,13 +16,13 @@ namespace sk_tools {
 
 PictureBenchmark::PictureBenchmark()
 : fRepeats(1)
-, fLogger(NULL)
 , fRenderer(NULL)
 , fTimerResult(TimerData::kAvg_Result)
 , fTimerTypes(0)
 , fTimeIndividualTiles(false)
 , fPurgeDecodedTex(false)
 , fPreprocess(false)
+, fWriter(NULL)
 {}
 
 PictureBenchmark::~PictureBenchmark() {
@@ -52,12 +51,6 @@ BenchTimer* PictureBenchmark::setupTimer(bool useGLTimer) {
     return SkNEW_ARGS(BenchTimer, (NULL));
 }
 
-void PictureBenchmark::logProgress(const char msg[]) {
-    if (fLogger != NULL) {
-        fLogger->logProgress(msg);
-    }
-}
-
 PictureRenderer* PictureBenchmark::setRenderer(sk_tools::PictureRenderer* renderer) {
     SkRefCnt_SafeAssign(fRenderer, renderer);
     return renderer;
@@ -137,10 +130,6 @@ void PictureBenchmark::run(SkPicture* pict) {
             return;
         }
 
-        // Insert a newline so that each tile is reported on its own line (separate from the line
-        // that describes the skp being run).
-        this->logProgress("\n");
-
         int x, y;
         while (tiledRenderer->nextTile(x, y)) {
             // There are two timers, which will behave slightly differently:
@@ -184,8 +173,8 @@ void PictureBenchmark::run(SkPicture* pict) {
                 SkAssertResult(longRunningTimerData.appendTimes(longRunningTimer.get()));
             }
 
-            SkString configName = tiledRenderer->getConfigName();
-            configName.appendf(": tile [%i,%i] out of [%i,%i]", x, y, xTiles, yTiles);
+            fWriter->tileConfig(tiledRenderer->getConfigName());
+            fWriter->tileMeta(x, y, xTiles, yTiles);
 
             // TODO(borenet): Turn off per-iteration tile time reporting for now.
             // Avoiding logging the time for every iteration for each tile cuts
@@ -193,22 +182,23 @@ void PictureBenchmark::run(SkPicture* pict) {
             // we're loading the bench data directly into a data store and are no
             // longer generating SVG graphs.
 #if 0
-            SkString result = perTileTimerData.getResult(timeFormat.c_str(), fTimerResult,
-                                                         configName.c_str(), timerTypes);
-            result.append("\n");
-            this->logProgress(result.c_str());
+            fWriter->tileData(
+                    &perTileTimerData, 
+                    timeFormat.c_str(), 
+                    fTimerResult,
+                    timerTypes);
 #endif
 
             if (fPurgeDecodedTex) {
-                configName.append(" <withPurging>");
+                fWriter->addTileFlag(PictureResultsWriter::kPurging);
             }
-            configName.append(" <averaged>");
-            SkString longRunningResult = longRunningTimerData.getResult(
+            fWriter->addTileFlag(PictureResultsWriter::kAvg);
+            fWriter->tileData(
+                &longRunningTimerData, 
                 tiledRenderer->getNormalTimeFormat().c_str(),
                 TimerData::kAvg_Result,
-                configName.c_str(), timerTypes, numInnerLoops);
-            longRunningResult.append("\n");
-            this->logProgress(longRunningResult.c_str());
+                timerTypes,
+                numInnerLoops);
         }
     } else {
         SkAutoTDelete<BenchTimer> longRunningTimer(this->setupTimer());
@@ -246,29 +236,26 @@ void PictureBenchmark::run(SkPicture* pict) {
             SkAssertResult(longRunningTimerData.appendTimes(longRunningTimer.get()));
         }
 
-        SkString configName = fRenderer->getConfigName();
+        fWriter->tileConfig(fRenderer->getConfigName());
         if (fPurgeDecodedTex) {
-            configName.append(" <withPurging>");
+            fWriter->addTileFlag(PictureResultsWriter::kPurging);
         }
 
         // Beware - since the per-run-timer doesn't ever include a glFinish it can
         // report a lower time then the long-running-timer
 #if 0
-        SkString result = perRunTimerData.getResult(timeFormat.c_str(),
-                                                    fTimerResult,
-                                                    configName.c_str(),
-                                                    timerTypes);
-        result.append("\n");
-
-        this->logProgress(result.c_str());
+        fWriter->tileData(
+                &perRunTimerData,
+                timeFormat.c_str(),
+                fTimerResult,
+                timerTypes);
 #else
-        SkString result = longRunningTimerData.getResult(timeFormat.c_str(),
-                                                            fTimerResult,
-                                                            configName.c_str(),
-                                                            timerTypes,
-                                                            numInnerLoops);
-        result.append("\n");
-        this->logProgress(result.c_str());
+        fWriter->tileData(
+                &longRunningTimerData,
+                timeFormat.c_str(),
+                fTimerResult,
+                timerTypes,
+                numInnerLoops);
 #endif
     }
 
diff --git a/tools/PictureBenchmark.h b/tools/PictureBenchmark.h
index e149f8c9e9..3ec3c6691c 100644
--- a/tools/PictureBenchmark.h
+++ b/tools/PictureBenchmark.h
@@ -11,6 +11,7 @@
 #include "SkTypes.h"
 #include "PictureRenderer.h"
 #include "TimerData.h"
+#include "PictureResultsWriter.h"
 
 class BenchTimer;
 class SkBenchLogger;
@@ -27,7 +28,7 @@ public:
 
     /**
      * Draw the provided SkPicture fRepeats times while collecting timing data, and log the output
-     * via fLogger.
+     * via fWriter.
      */
     void run(SkPicture* pict);
 
@@ -55,11 +56,10 @@ public:
 
     void setTimersToShow(bool wall, bool truncatedWall, bool cpu, bool truncatedCpu, bool gpu);
 
-    void setLogger(SkBenchLogger* logger) { fLogger = logger; }
+    void setWriter(PictureResultsWriter* writer) { fWriter = writer; }
 
 private:
     int               fRepeats;
-    SkBenchLogger*    fLogger;
     PictureRenderer*  fRenderer;
     TimerData::Result fTimerResult;
     uint32_t          fTimerTypes; // bitfield of TimerData::TimerFlags values
@@ -67,7 +67,7 @@ private:
     bool              fPurgeDecodedTex;
     bool              fPreprocess;
 
-    void logProgress(const char msg[]);
+    PictureResultsWriter* fWriter;
 
     BenchTimer* setupTimer(bool useGLTimer = true);
 };
diff --git a/tools/PictureResultsWriter.h b/tools/PictureResultsWriter.h
new file mode 100644
index 0000000000..0571e80d05
--- /dev/null
+++ b/tools/PictureResultsWriter.h
@@ -0,0 +1,232 @@
+/*
+ * Copyright 2014 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ *
+ * Classes for writing out bench results in various formats.
+ */
+#ifndef SkPictureResultsWriter_DEFINED
+#define SkPictureResultsWriter_DEFINED
+
+#include "ResultsWriter.h"
+#include "SkBenchLogger.h"
+#include "SkJSONCPP.h"
+#include "SkStream.h"
+#include "SkString.h"
+#include "SkTArray.h"
+
+/**
+ * Base class for writing picture bench results.
+ */
+class PictureResultsWriter : SkNoncopyable {
+public:
+    enum TileFlags {kPurging, kAvg};
+
+    PictureResultsWriter() {}
+    virtual ~PictureResultsWriter() {}
+
+    virtual void bench(const char name[], int32_t x, int32_t y) = 0;
+    virtual void tileConfig(SkString configName) = 0;
+    virtual void tileMeta(int x, int y, int tx, int ty) = 0;
+    virtual void addTileFlag(PictureResultsWriter::TileFlags flag) = 0;
+    virtual void tileData(
+            TimerData* data, 
+            const char format[], 
+            const TimerData::Result result,
+            uint32_t timerTypes,
+            int numInnerLoops = 1) = 0;
+   virtual void end() = 0;
+};
+
+/**
+ * This class allows bench data to be piped into multiple
+ * PictureResultWriter classes. It does not own any classes
+ * passed to it, so the owner is required to manage any classes
+ * passed to PictureResultsMultiWriter */
+class PictureResultsMultiWriter : public PictureResultsWriter {
+public:
+    PictureResultsMultiWriter() 
+        : fWriters() {}
+    void add(PictureResultsWriter* newWriter) {
+        fWriters.push_back(newWriter);
+    }
+    virtual ~PictureResultsMultiWriter() {}
+    virtual void bench(const char name[], int32_t x, int32_t y) {
+        for(int i=0; i<fWriters.count(); ++i) {
+            fWriters[i]->bench(name, x, y);
+        }
+    }
+    virtual void tileConfig(SkString configName) {
+        for(int i=0; i<fWriters.count(); ++i) {
+            fWriters[i]->tileConfig(configName);
+        }
+    }
+    virtual void tileMeta(int x, int y, int tx, int ty) {
+        for(int i=0; i<fWriters.count(); ++i) {
+            fWriters[i]->tileMeta(x, y, tx, ty);
+        }
+    }
+    virtual void addTileFlag(PictureResultsWriter::TileFlags flag) {
+        for(int i=0; i<fWriters.count(); ++i) {
+            fWriters[i]->addTileFlag(flag);
+        }
+    }
+    virtual void tileData(
+            TimerData* data, 
+            const char format[], 
+            const TimerData::Result result,
+            uint32_t timerTypes,
+            int numInnerLoops = 1) {
+        for(int i=0; i<fWriters.count(); ++i) {
+            fWriters[i]->tileData(data, format, result, timerTypes, 
+                                 numInnerLoops);
+        }
+    }
+   virtual void end() {
+        for(int i=0; i<fWriters.count(); ++i) {
+            fWriters[i]->end();
+        }
+   }
+private:
+    SkTArray<PictureResultsWriter*> fWriters;
+};
+
+/**
+ * Writes to SkBenchLogger to mimic original behavior
+ */
+class PictureResultsLoggerWriter : public PictureResultsWriter {    
+private:
+    void logProgress(const char str[]) {
+        if(fLogger != NULL) {
+            fLogger->logProgress(str);
+        }
+    }
+public:
+    PictureResultsLoggerWriter(SkBenchLogger* log)
+          : fLogger(log), currentLine() {}
+    virtual void bench(const char name[], int32_t x, int32_t y) {
+        SkString result;
+        result.printf("running bench [%i %i] %s ", x, y, name);
+        this->logProgress(result.c_str());
+    }
+    virtual void tileConfig(SkString configName) {
+        currentLine = configName;
+    }
+    virtual void tileMeta(int x, int y, int tx, int ty) {
+        currentLine.appendf(": tile [%i,%i] out of [%i,%i]", x, y, tx, ty);
+    }
+    virtual void addTileFlag(PictureResultsWriter::TileFlags flag) {
+        if(flag == PictureResultsWriter::kPurging) {
+            currentLine.append(" <withPurging>");
+        } else if(flag == PictureResultsWriter::kAvg) {
+            currentLine.append(" <averaged>");
+        }
+    }
+    virtual void tileData(
+            TimerData* data, 
+            const char format[], 
+            const TimerData::Result result,
+            uint32_t timerTypes,
+            int numInnerLoops = 1) {
+        SkString results = data->getResult(format, result,
+                currentLine.c_str(), timerTypes, numInnerLoops);
+        results.append("\n");
+        this->logProgress(results.c_str());
+    }
+    virtual void end() {}
+private:
+    SkBenchLogger* fLogger;
+    SkString currentLine;
+};
+
+#ifdef SK_BUILD_JSON_WRITER
+/**
+ * This PictureResultsWriter collects data in a JSON node
+ *
+ * The format is something like
+ * {
+ *      benches: [
+ *          {
+ *              name: "Name_of_test"
+ *              tilesets: [
+ *                  {
+ *                      name: "Name of the configuration"
+ *                      tiles: [
+ *                          {
+ *                              flags: {
+ *                                  purging: true //Flags for the current tile
+ *                                              // are put here
+ *                              }
+ *                              data: {
+ *                                  wsecs: [....] //Actual data ends up here
+ *                              }
+ *                          }
+ *                      ]
+ *                  }
+ *              ]
+ *          }
+ *      ]
+ * }*/
+
+class PictureJSONResultsWriter : public PictureResultsWriter {
+public:
+    PictureJSONResultsWriter(const char filename[])
+        : fFilename(filename),
+          fRoot(), 
+          fCurrentBench(NULL),
+          fCurrentTileSet(NULL),
+          fCurrentTile(NULL) {}
+
+    virtual void bench(const char name[], int32_t x, int32_t y) {
+        SkString sk_name(name);
+        sk_name.append("_");
+        sk_name.appendS32(x);
+        sk_name.append("_");
+        sk_name.appendS32(y);
+        Json::Value* bench_node = SkFindNamedNode(&fRoot["benches"], sk_name.c_str());
+        fCurrentBench = &(*bench_node)["tileSets"];
+    }
+    virtual void tileConfig(SkString configName) {
+        SkASSERT(fCurrentBench != NULL);
+        fCurrentTileSet = SkFindNamedNode(fCurrentBench, configName.c_str());
+        fCurrentTile = &(*fCurrentTileSet)["tiles"][0];
+    }
+    virtual void tileMeta(int x, int y, int tx, int ty) {
+        SkASSERT(fCurrentTileSet != NULL);
+        (*fCurrentTileSet)["tx"] = tx;
+        (*fCurrentTileSet)["ty"] = ty;
+        fCurrentTile = &(*fCurrentTileSet)["tiles"][x+tx*y];
+    }
+    virtual void addTileFlag(PictureResultsWriter::TileFlags flag) {
+        SkASSERT(fCurrentTile != NULL);
+        if(flag == PictureResultsWriter::kPurging) {
+            (*fCurrentTile)["flags"]["purging"] = true;
+        } else if(flag == PictureResultsWriter::kAvg) {
+            (*fCurrentTile)["flags"]["averaged"] = true;
+        }
+    }
+    virtual void tileData(
+            TimerData* data, 
+            const char format[], 
+            const TimerData::Result result,
+            uint32_t timerTypes,
+            int numInnerLoops = 1) {
+        SkASSERT(fCurrentTile != NULL);
+        (*fCurrentTile)["data"] = data->getJSON(timerTypes, result, numInnerLoops);
+    }
+    virtual void end() {
+       SkFILEWStream stream(fFilename.c_str());
+       stream.writeText(Json::FastWriter().write(fRoot).c_str());
+       stream.flush();
+    }
+private:
+    SkString fFilename;
+    Json::Value fRoot;
+    Json::Value *fCurrentBench;
+    Json::Value *fCurrentTileSet;
+    Json::Value *fCurrentTile;
+};
+#endif // SK_BUILD_JSON_WRITER
+
+#endif
diff --git a/tools/bench_pictures_main.cpp b/tools/bench_pictures_main.cpp
index 5ff519c8c5..b79dfedff2 100644
--- a/tools/bench_pictures_main.cpp
+++ b/tools/bench_pictures_main.cpp
@@ -12,6 +12,7 @@
 #include "PictureRenderingFlags.h"
 #include "SkBenchLogger.h"
 #include "SkCommandLineFlags.h"
+#include "SkData.h"
 #include "SkDiscardableMemoryPool.h"
 #include "SkGraphics.h"
 #include "SkImageDecoder.h"
@@ -20,8 +21,11 @@
 #include "SkPicture.h"
 #include "SkStream.h"
 #include "picture_utils.h"
+#include "PictureResultsWriter.h"
 
 SkBenchLogger gLogger;
+PictureResultsLoggerWriter gLogWriter(&gLogger);
+PictureResultsMultiWriter gWriter;
 
 // Flags used by this file, in alphabetical order.
 DEFINE_bool(countRAM, false, "Count the RAM used for bitmap pixels in each skp file");
@@ -35,6 +39,9 @@ DEFINE_string(filter, "",
         "Specific flags are listed above.");
 DEFINE_string(logFile, "", "Destination for writing log output, in addition to stdout.");
 DEFINE_bool(logPerIter, false, "Log each repeat timer instead of mean.");
+#ifdef SK_BUILD_JSON_WRITER
+DEFINE_string(jsonLog, "", "Destination for writing JSON data.");
+#endif
 DEFINE_bool(min, false, "Print the minimum times (instead of average).");
 DECLARE_int32(multi);
 DECLARE_string(readPath);
@@ -187,10 +194,7 @@ static bool run_single_benchmark(const SkString& inputPath,
     SkString filename;
     sk_tools::get_basename(&filename, inputPath);
 
-    SkString result;
-    result.printf("running bench [%i %i] %s ", picture->width(), picture->height(),
-                  filename.c_str());
-    gLogger.logProgress(result);
+    gWriter.bench(filename.c_str(), picture->width(), picture->height());
 
     benchmark.run(picture);
 
@@ -360,7 +364,7 @@ static void setup_benchmark(sk_tools::PictureBenchmark* benchmark) {
     }
     benchmark->setRenderer(renderer);
     benchmark->setRepeats(FLAGS_repeat);
-    benchmark->setLogger(&gLogger);
+    benchmark->setWriter(&gWriter);
 }
 
 static int process_input(const char* input,
@@ -417,6 +421,16 @@ int tool_main(int argc, char** argv) {
         }
     }
 
+#ifdef SK_BUILD_JSON_WRITER
+    SkAutoTDelete<PictureJSONResultsWriter> jsonWriter;
+    if (FLAGS_jsonLog.count() == 1) {
+        jsonWriter.reset(SkNEW(PictureJSONResultsWriter(FLAGS_jsonLog[0])));
+        gWriter.add(jsonWriter.get());
+    }
+
+#endif
+    gWriter.add(&gLogWriter);
+
 
 #if SK_ENABLE_INST_COUNT
     gPrintInstCount = true;
@@ -444,6 +458,7 @@ int tool_main(int argc, char** argv) {
                  (double) gTotalCacheHits / (gTotalCacheHits + gTotalCacheMisses));
     }
 #endif
+    gWriter.end();
     return 0;
 }