Measure tiled rendering.

tools/bbh_shootout.cpp

Index: tools/bbh_shootout.cpp
diff --git a/tools/bbh_shootout.cpp b/tools/bbh_shootout.cpp
new file mode 100644
index 0000000000000000000000000000000000000000..6966345f2b37cde2f9e0fd95ed0272c99d838a98
--- /dev/null
+++ b/tools/bbh_shootout.cpp
@@ -0,0 +1,335 @@
+/*
+ * Copyright 2013 Google Inc.
+ *
+ * Use of this source code is governed by a BSD-style license that can be
+ * found in the LICENSE file.
+ */
+
+#include "BenchTimer.h"
+#include "PictureBenchmark.h"
+#include "PictureRenderer.h"
+#include "PictureRenderingFlags.h"
+#include "SkBenchmark.h"
+#include "SkCommandLineFlags.h"
+#include "SkForceLinking.h"
+#include "SkGraphics.h"
+#include "SkStream.h"
+#include "SkString.h"
+#include "TimerData.h"
+
+__SK_FORCE_IMAGE_DECODER_LINKING;
+
+static const int kNumRecordings = SkBENCHLOOP(10);
+static const int kNumPlaybacks = SkBENCHLOOP(5);
+
+enum BenchmarkType {
+    kNormal_BenchmarkType = 0,
+    kRTree_BenchmarkType,
+};
+
+struct Histogram {

[caryclark, 2013/07/12 13:13:28]

Add 

Histogram() 
  : fCpuTime(SkIntToScalar(-1)) {
}

so it's always initialized to the invalid state (and comment it too)

+    SkScalar fCpuTime;
+    SkString fPath;
+};
+
+// Defined in PictureRenderingFlags.cpp
+extern bool lazy_decode_bitmap(const void* buffer, size_t size, SkBitmap* bitmap);

[caryclark, 2013/07/12 13:13:28]

since it's also used by bench_pictures_main.cpp, lua_pictures.cpp, and
render_pictures_main.cpp, it's time to move this to tools/PictureRenderFlags.h

(it also needs to be renamed to lazyDecodeBitmap, since in its present form, it
looks like a local static function)

Since this change is orthogonal to the shootout, prepare a separate CL that just
does the rename/add to .h, and (after running it through the trybots) I'll
approve it immediately

[sglez, 2013/07/13 03:57:15]

CL sent

+
+static SkPicture* pic_from_path(const char path[]) {
+    SkFILEStream stream(path);
+    if (!stream.isValid()) {
+        SkDebugf("-- Can't open '%s'\n", path);
+        return NULL;
+    }
+    return SkPicture::CreateFromStream(&stream, &lazy_decode_bitmap);
+}
+
+/**
+ * This function is the sink to which all work ends up going.
+ * Renders the picture into the renderer. It may or may not use an RTree.
+ * The renderer is chosen upstream. If we want to measure recording, we will
+ * use a RecordPictureRenderer. If we want to measure rendering, we eill use a
+ * TiledPictureRenderer.
+ */
+static void do_benchmark_work(sk_tools::PictureRenderer* renderer,
+        int benchmarkType, const SkString& path, SkPicture* pic,
+        const int numRepeats, const char *msg, BenchTimer* timer) {
+    SkString msgPrefix;
+
+    switch (benchmarkType){
+        case kNormal_BenchmarkType:
+            msgPrefix.set("Normal");
+            renderer->setBBoxHierarchyType(sk_tools::PictureRenderer::kNone_BBoxHierarchyType);
+            break;
+        case kRTree_BenchmarkType:
+            msgPrefix.set("RTree");
+            renderer->setBBoxHierarchyType(sk_tools::PictureRenderer::kRTree_BBoxHierarchyType);
+            break;
+        default:
+            SkASSERT(0);
+            break;
+    }
+
+    renderer->init(pic);
+
+    /**
+     * If the renderer is not tiled, assume we are measuring recording.
+     */
+    bool recording = (NULL == renderer->getTiledRenderer());
+
+    SkDebugf("%s %s %s %d times...\n", msgPrefix.c_str(), msg, path.c_str(), numRepeats);
+    for (int i = 0; i < numRepeats; ++i) {
+        renderer->setup();
+        // Render once to fill caches.
+        renderer->render(NULL);
+        // Render again to measure
+        timer->start();
+        bool result = renderer->render(NULL);
+        timer->end();
+        // We only care about a false result on playback. RecordPictureRenderer::render will always
+        // return false because we are passing a NULL ptr.
+        if(!recording && !result) {
+            SkDebugf("Error rendering (playback).\n");

[caryclark, 2013/07/12 13:13:28]

If recording == false, this will print the debug message each time through the
loop, whether render() returns true or not. Do the check outside the loop
instead.

[sglez, 2013/07/13 03:57:15]

RecordPictureRenderer::render(..), returns false when it fails to write to a
file. We expect this when we are recording because we pass NULL. (It still does
the job we want it to do)
TiledPictureRenderer::render(..) returns true unless something bad happens. 

So if recording == false, result will hopefully be true and we won't print.

I don't know why they behave differently with NULL input. Perhaps
RecordPictureRenderer has the assumption that it is only useful when writing to
a file?

I changed 'recording' to 'isPlayback', to make this code clearer.

[caryclark, 2013/07/15 12:00:15]

My mistake. I misread the && for an ||. 
On 2013/07/13 03:57:15, sglez wrote:

+        }
+    }
+    renderer->end();
+}
+
+/**
+ * Call do_benchmark_work with a tiled renderer using the default tile dimensions.
+ */
+static void benchmark_playback(
+        BenchmarkType benchmarkType, const int tileSize[2],
+        const SkString& path, SkPicture* pic, BenchTimer* timer) {
+    sk_tools::TiledPictureRenderer renderer;
+
+    SkString message("tiled_playback");
+    message.appendf("_%dx%d", tileSize[0], tileSize[1]);
+    do_benchmark_work(&renderer, benchmarkType,
+            path, pic, kNumPlaybacks, message.c_str(), timer);
+}
+
+/**
+ * Call do_benchmark_work with a RecordPictureRenderer.
+ */
+static void benchmark_recording(
+        BenchmarkType benchmarkType, const int tileSize[2],
+        const SkString& path, SkPicture* pic, BenchTimer* timer) {
+    sk_tools::RecordPictureRenderer renderer;
+    do_benchmark_work(&renderer, benchmarkType, path, pic, kNumRecordings, "recording", timer);
+}
+
+static const SkString perIterTimeFormat("%f");
+static const SkString normalTimeFormat("%f");
+
+/**
+ * Takes argc,argv along with one of the benchmark functions defined above.
+ * Will loop along all skp files and perform measurments.
+ *
+ * Returns a SkScalar representing CPU time taken during benchmark.
+ * As a side effect, it spits the timer result to stdout.
+ * Will return -1.0 on error.
+ */
+static SkScalar benchmark_loop(
+        int argc,
+        char **argv,
+        void (*func)(BenchmarkType, const int[], const SkString&, SkPicture*, BenchTimer*),

[caryclark, 2013/07/12 13:13:28]

below, you use const int[kNumBenchMarks]. Make these consistent.

I recommend moving your const data to the top of the file, so you can reference
any computed consts consistently. Also, since this func shows up more than once,
I recommend using a typedef so that all uses are always the same.

Name the typedef so that the purpose of the function pointer is
self-documenting.

[sglez, 2013/07/13 03:57:15]

Yes, I should have typedef'd that some time ago.

Moved most constants to the top.

+        const int tileSize[2],

[caryclark, 2013/07/12 13:13:28]

I assume the '2' is the number of tile dimensions, i.e., it's a 2D tile with a
width and height. Replacing the 2 with a good const name would make this more
clear.

In general, I recommend avoiding any numbers other than 1 and 0 outside of auto
initialization unless it's awkward (I wouldn't, for instance, name a number and
then just use the number once). I also wouldn't change the 

if (argc < 2) {

below because it would obscure rather than enlighten the code -- in other words,
use your best judgment.

[sglez, 2013/07/13 03:57:15]

In this instance, I think having a struct would be clearer. After some
searching, using SkISize seems like the right thing to do.

+        SkTArray<Histogram>& histogram,
+        BenchmarkType benchmarkType,
+        const char* configName) {
+    TimerData timerData(perIterTimeFormat, normalTimeFormat);
+    for (int index = 1; index < argc; ++index) {

[caryclark, 2013/07/12 13:13:28]

this seems inconsistent. If argc == 1, this loop executes once. However, the
check in tool_main requires argc to be 2 or larger.

[sglez, 2013/07/13 03:57:15]

If argc == 1 this loop doesn't excecute :)

[caryclark, 2013/07/15 12:00:15]

Understood -- my mistake again. See, aren't code reviews fun?
On 2013/07/13 03:57:15, sglez wrote:

+        BenchTimer timer;
+        SkString path(argv[index]);
+        SkAutoTUnref<SkPicture> pic(pic_from_path(argv[index]));
+        if (NULL == pic) {
+            SkDebugf("Couldn't create picture. Ignoring path: %s\n", path.c_str());

[caryclark, 2013/07/12 13:13:28]

Here you use path.c_str() for char* . A couple lines up you use argv[index] as
an argument to pic_from_path for char* . Pick one.

+            // Make fCpuTime negative so that we don't mess with stats:
+            histogram[index - 1].fCpuTime = SkIntToScalar(-1);

[caryclark, 2013/07/12 13:13:28]

move this to the struct constructor (see above)

+            continue;
+        }
+        func(benchmarkType, tileSize, path, pic, &timer);

[caryclark, 2013/07/12 13:13:28]

(*func)(benchmarkType ...

+        timerData.appendTimes(&timer, index == argc - 1);

[caryclark, 2013/07/12 13:13:28]

this is a good place to reverse this to

argc - 1 == index

since 

argc - 1 = index

won't compile

+
+        histogram[index - 1].fPath = path;
+        histogram[index - 1].fCpuTime = timer.fCpu;
+    }
+
+    const SkString timerResult = timerData.getResult(
+            /*logPerIter = */ false,
+            /*printMin = */ false,
+            /*repeatDraw = */ 1,
+            /*configName = */ configName,
+            /*showWallTime = */ false,
+            /*showTruncatedWallTime = */ false,
+            /*showCpuTime = */ true,
+            /*showTruncatedCpuTime = */ false,
+            /*showGpuTime = */ false);
+
+    const char findStr[] = "= ";
+    int pos = timerResult.find(findStr);
+    if (-1 == pos) {
+        SkDebugf("Unexpected output from TimerData::getResult(...). Unable to parse.");
+        return SkIntToScalar(-1);
+    }
+    SkDebugf("%s\n", timerResult.c_str());
+
+    SkScalar cpuTime = atof(timerResult.c_str() + pos + sizeof(findStr) - 1);
+    if (cpuTime == SkIntToScalar(0)) {  // atof returns 0.0 on error.

[caryclark, 2013/07/12 13:13:28]

0 is always 0, so you can say

if (cpuTime == 0) {

regardless of whether cpuTime's type.

+        SkDebugf("Unable to read value from timer result.\n");
+        return SkIntToScalar(-1);
+    }
+    return cpuTime;
+}
+
+static int tool_main(int argc, char** argv) {
+    SkAutoGraphics ag;
+    SkString usage;
+    usage.printf("Usage: filename [filename]*\n");
+
+    if (argc < 2) {
+        SkDebugf("%s\n", usage.c_str());

[caryclark, 2013/07/12 13:13:28]

return something other than zero in the error case?

+        return 0;
+    }
+
+    static const int tileSizes[][2] = {
+        {256, 256},
+        {512, 512},
+        {1024, 1024},
+    };
+    static const size_t kNumTileSizes = SK_ARRAY_COUNT(tileSizes);
+    static const size_t kNumBenchmarks = 3 + kNumTileSizes;

[caryclark, 2013/07/12 13:13:28]

you want kNumBaseBenches (or another name of your choice) instead of 3 -- see
below

+    static SkString benchNames[kNumBenchmarks];
+
+    benchNames[0] = "normal_recording";
+    benchNames[1] = "normal_playback";
+    benchNames[2] = "rtree_recording";
+    for (size_t i = 0; i < kNumTileSizes; ++i) {
+        SkString benchName;
+        benchName.printf("rtree_playback_%dx%d", tileSizes[i][0], tileSizes[i][1]);

[caryclark, 2013/07/12 13:13:28]

earlier, you set the name in the string and did appendf("_%dx%d"). Either
pattern is fine -- choose one.

+        benchNames[i + kNumTileSizes] = benchName.c_str();

[caryclark, 2013/07/12 13:13:28]

kNumTileSizes isn't what you want here. You need another const that describes
kNumBaseBenches or something like that, for bench 0, 1, and 2.

+    }
+    static SkScalar results[kNumBenchmarks];
+    static SkTArray<Histogram> histograms[kNumBenchmarks];
+
+    static void (*baseBenchmarkFunctions[3])
+        (BenchmarkType, const int [kNumBenchmarks], const SkString&, SkPicture*, BenchTimer*) = {
+            benchmark_recording,  // normal_recording
+            benchmark_playback,   // normal_playback
+            benchmark_recording,  // rtree_recording
+        };

[caryclark, 2013/07/12 13:13:28]

this is one possibility for

const int kNumBaseBenches = SK_ARRAY_COUNT(baseBenchmarkFunctions);

+
+    for (size_t i = 0; i < kNumBenchmarks; ++i) {
+        BenchmarkType type;
+        if (i < 2) {
+            type = kNormal_BenchmarkType;
+        } else {
+            type = kRTree_BenchmarkType;

[caryclark, 2013/07/12 13:13:28]

I'm not crazy about benchNames being initialized in one place,
baseBenchmarkFunctions in a second, and this in a third. I'd rather see a struct
with all three, and then an auto-initialized array that ensures that everything
is in sync. 

Along with this, add an enum that replaces your use of 0,1,2 (and sometimes 3)
with kNormalRecording, kNormalPlayback, etc.

Talk to me if this isn't clear.

[sglez, 2013/07/13 03:57:15]

This comment made me do a big change. I hope I was more careful this time. It
looks a lot better to me now.

+        }
+        int tileSize[2] = {256, 256};
+        static void (*benchmarkFunction)
+            (BenchmarkType, const int [kNumBenchmarks], const SkString&, SkPicture*, BenchTimer*);
+        if (i < 3) {
+            benchmarkFunction = baseBenchmarkFunctions[i];
+        } else {
+            // If our bencmark is of the type rtree_playback_[SIZE]:
+            // Set tileSize and set benchmark to playback.
+            tileSize[0] = tileSizes[i - 3][0];
+            tileSize[1] = tileSizes[i - 3][1];

[caryclark, 2013/07/12 13:13:28]

lots of '3's here :)

+            benchmarkFunction = benchmark_playback;
+        }
+        histograms[i] = SkTArray<Histogram>(argc - 1);
+        histograms[i].reset(argc - 1);
+        results[i] = benchmark_loop(
+                argc, argv, benchmarkFunction, tileSize, histograms[i],
+                type, benchNames[i].c_str());
+    }
+
+    // Print results
+    SkDebugf("\n");
+    for (size_t i = 0; i < kNumBenchmarks; ++i) {
+        SkDebugf("%s total: %f\n", benchNames[i].c_str(), results[i]);
+    }
+
+    // Print a rough analysis to stdout:
+    {
+        SkScalar normalRecordResult = results[0];
+        SkScalar normalPlaybackResult = results[1];
+        SkScalar rtreeRecordResult = results[2];
+        SkScalar rtreePlaybackResult = results[3];
+        SkASSERT(normalRecordResult != 0 && normalPlaybackResult != 0);
+        SkDebugf("\n");
+        SkDebugf("Recording: Relative difference: %.4f\n",
+                rtreeRecordResult / normalRecordResult);
+        SkDebugf("Playback (256x256):  Relative difference: %.4f\n",
+                rtreePlaybackResult / normalPlaybackResult);
+        SkScalar times =
+                (kNumPlaybacks * (normalRecordResult - rtreeRecordResult)) /
+                (kNumRecordings * (rtreePlaybackResult - normalPlaybackResult));

[caryclark, 2013/07/12 13:13:28]

what about if rtreePlaybackResult == normalPlaybackResult ?

[sglez, 2013/07/13 03:57:15]

I missed this comment and didn't address it. I will fix this for the next patch.

+        SkDebugf("Number of playback repetitions for RTree to be worth it: %d (ratio: %.4f)\n",
+                SkScalarCeilToInt(times), times);
+    }
+
+    // Print min/max times for each benchmark.
+    SkDebugf("\n");
+    SkScalar minMax[kNumBenchmarks][2];

[caryclark, 2013/07/12 13:13:28]

2 being one for min, one for max. Good place for an enum

enum {
  kMinBenchMarkTime,
  kMaxBenchMarkTime
};

const int kNumBenchMarkTimes = kMaxBenchMarkTime + 1;

or

const int kNumBenchMarkTimes = 2;

+    for (size_t i = 0; i < kNumBenchmarks; ++i) {
+        SkString minPath;
+        SkString maxPath;
+        minMax[i][0] = SK_ScalarMax;
+        minMax[i][1] = 0;
+        for (int j = 0; j < argc - 1; ++j) {
+            SkScalar value = histograms[i][j].fCpuTime;
+            if (value < 0) continue;  // skp wasn't found or couldn't be read.
+            if (value < minMax[i][0]) {
+                minMax[i][0] = value;

[caryclark, 2013/07/12 13:13:28]

I prefer the pattern of

if (a op b) {
 a = b;

but that may be a matter of taste

[sglez, 2013/07/13 03:57:15]

Normally I would agree, but when doing min/max I prefer saying:

"If the value is smaller than the minimum, set the minimum to be the value."

than to say:

"If the minimum is greater than the value, set the minimum to be the value."

The first one is clearer to me.

+                minPath = histograms[i][j].fPath;
+            }
+            if (value > minMax[i][1]) {
+                minMax[i][1] = value;
+                maxPath = histograms[i][j].fPath;
+            }
+        }
+        SkDebugf("%s min is %.3f:\t\t%s\n"
+                "%s max is %.3f:\t\t%s\n",
+                benchNames[i].c_str(), minMax[i][0], minPath.c_str(),
+                benchNames[i].c_str(), minMax[i][1], maxPath.c_str());
+    }
+
+    // Output gnuplot readable histogram data..
+    const char* pbTitle = "bbh_shootout_playback.dat";
+    const char* recTitle = "bbh_shootout_record.dat";
+    SkFILEWStream playbackOut(pbTitle);
+    SkFILEWStream recordOut(recTitle);
+    recordOut.writeText("# Index Normal RTree\n");
+    playbackOut.writeText("# Index Normal RTree\n");
+    for (int i = 0; i < argc - 1; ++i) {
+        SkString pbLine;
+        SkString recLine;
+        // ==== Write record info
+        recLine.printf("%d ", i);
+        recLine.appendf("%f ", histograms[0][i].fCpuTime);  // Append normal_record time
+        recLine.appendf("%f ", histograms[2][i].fCpuTime);  // Append rtree_record time
+
+        // ==== Write playback info
+        pbLine.printf("%d ", i);
+        pbLine.appendf("%f ", histograms[1][i].fCpuTime);  // Start with normal playback time.
+        // Append all playback benchmark times.
+        for (size_t j = kNumTileSizes; j < kNumBenchmarks; ++j) {
+            pbLine.appendf("%f ", histograms[j][i].fCpuTime);

[caryclark, 2013/07/12 13:13:28]

this puts a final ' ' followed by a '\n'

[sglez, 2013/07/13 03:57:15]

Added a line that trims the trailing space.

+        }
+        pbLine.appendf("\n");
+        recLine.appendf("\n");
+        playbackOut.writeText(pbLine.c_str());
+        recordOut.writeText(recLine.c_str());
+    }
+    SkDebugf("Wrote data to gnuplot-readable files: %s %s\n", pbTitle, recTitle);
+
+    return 0;
+}
+
+int main(int argc, char** argv) {
+    return tool_main(argc, argv);
+}
+