Add timing to dump_record.

Prints microsecond timing for each command in the left-hand column:

optimized flat/http___mobile_news_sandbox_google_com_news_pt0_scroll_layer_7.skp
   4.0   1 Save
2075.0   2      DrawRect
 104.0   3      BoundedDrawPosTextH
 135.4   4      DrawRect
   9.4   5      DrawRect
   5.6   6      DrawRect
   8.2   7      DrawRect
   6.8   8      DrawRect
...

(I'm sure Rietveld will just mangle the crap out of that.  It's helpfully right-aligned.)

To do this, I made Draw from SkRecordDraw Skia-public as SkRecords::Draw,
and time it command-by-command.

BUG=skia:2378
R=fmalita@chromium.org, mtklein@google.com

Author: mtklein@chromium.org

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

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

4 files changed, 113 insertions, 71 deletions

diff --git a/gyp/tools.gyp b/gyp/tools.gyp
index 340f20766b..e724e3afa7 100644
--- a/gyp/tools.gyp
+++ b/gyp/tools.gyp
@@ -357,6 +357,7 @@
         '../src/record',
       ],
       'dependencies': [
+        'bench.gyp:bench_timer',
         'flags.gyp:flags',
         'record.gyp:*',
         'skia_lib.gyp:skia_lib',
diff --git a/src/record/SkRecordDraw.cpp b/src/record/SkRecordDraw.cpp
index 666cfc9000..324946e5d7 100644
--- a/src/record/SkRecordDraw.cpp
+++ b/src/record/SkRecordDraw.cpp
@@ -7,52 +7,30 @@
 
 #include "SkRecordDraw.h"
 
-namespace {
-
-// This is an SkRecord visitor that will draw that SkRecord to an SkCanvas.
-class Draw : SkNoncopyable {
-public:
-    explicit Draw(SkCanvas* canvas) : fCanvas(canvas), fIndex(0) {}
-
-    unsigned index() const { return fIndex; }
-    void next() { ++fIndex; }
-
-    template <typename T> void operator()(const T& r) {
-        if (!this->skip(r)) {
-            this->draw(r);
-        }
+void SkRecordDraw(const SkRecord& record, SkCanvas* canvas) {
+    for (SkRecords::Draw draw(canvas); draw.index() < record.count(); draw.next()) {
+        record.visit<void>(draw.index(), draw);
     }
+}
 
-private:
-    // No base case, so we'll be compile-time checked that we implemented all possibilities below.
-    template <typename T> void draw(const T&);
-
-    // skip() should return true if we can skip this command, false if not.
-    // It may update fIndex directly to skip more than just this one command.
-
-    // Mostly we just blindly call fCanvas and let it handle quick rejects itself.
-    template <typename T> bool skip(const T&) { return false; }
+namespace SkRecords {
 
-    // We add our own quick rejects for commands added by optimizations.
-    bool skip(const SkRecords::PairedPushCull& r) {
-        if (fCanvas->quickReject(r.base->rect)) {
-            fIndex += r.skip;
-            return true;
-        }
-        return false;
-    }
-    bool skip(const SkRecords::BoundedDrawPosTextH& r) {
-        return fCanvas->quickRejectY(r.minY, r.maxY);
+bool Draw::skip(const PairedPushCull& r) {
+    if (fCanvas->quickReject(r.base->rect)) {
+        fIndex += r.skip;
+        return true;
     }
+    return false;
+}
 
-    SkCanvas* fCanvas;
-    unsigned fIndex;
-};
+bool Draw::skip(const BoundedDrawPosTextH& r) {
+    return fCanvas->quickRejectY(r.minY, r.maxY);
+}
 
 // NoOps draw nothing.
-template <> void Draw::draw(const SkRecords::NoOp&) {}
+template <> void Draw::draw(const NoOp&) {}
 
-#define DRAW(T, call) template <> void Draw::draw(const SkRecords::T& r) { fCanvas->call; }
+#define DRAW(T, call) template <> void Draw::draw(const T& r) { fCanvas->call; }
 DRAW(Restore, restore());
 DRAW(Save, save(r.flags));
 DRAW(SaveLayer, saveLayer(r.bounds, r.paint, r.flags));
@@ -87,13 +65,7 @@ DRAW(DrawVertices, drawVertices(r.vmode, r.vertexCount, r.vertices, r.texs, r.co
                                 r.xmode.get(), r.indices, r.indexCount, r.paint));
 #undef DRAW
 
-template <> void Draw::draw(const SkRecords::PairedPushCull& r) { this->draw(*r.base); }
-template <> void Draw::draw(const SkRecords::BoundedDrawPosTextH& r) { this->draw(*r.base); }
-
-}  // namespace
+template <> void Draw::draw(const PairedPushCull& r) { this->draw(*r.base); }
+template <> void Draw::draw(const BoundedDrawPosTextH& r) { this->draw(*r.base); }
 
-void SkRecordDraw(const SkRecord& record, SkCanvas* canvas) {
-    for (Draw draw(canvas); draw.index() < record.count(); draw.next()) {
-        record.visit<void>(draw.index(), draw);
-    }
-}
+}  // namespace SkRecords
diff --git a/src/record/SkRecordDraw.h b/src/record/SkRecordDraw.h
index 8bf0e6694a..4ec6e68e92 100644
--- a/src/record/SkRecordDraw.h
+++ b/src/record/SkRecordDraw.h
@@ -11,7 +11,43 @@
 #include "SkRecord.h"
 #include "SkCanvas.h"
 
-// Draw an SkRecord into an SkCanvas.
+// Draw an SkRecord into an SkCanvas.  A convenience wrapper around SkRecords::Draw.
 void SkRecordDraw(const SkRecord&, SkCanvas*);
 
+namespace SkRecords {
+
+// This is an SkRecord visitor that will draw that SkRecord to an SkCanvas.
+class Draw : SkNoncopyable {
+public:
+    explicit Draw(SkCanvas* canvas) : fCanvas(canvas), fIndex(0) {}
+
+    unsigned index() const { return fIndex; }
+    void next() { ++fIndex; }
+
+    template <typename T> void operator()(const T& r) {
+        if (!this->skip(r)) {
+            this->draw(r);
+        }
+    }
+
+private:
+    // No base case, so we'll be compile-time checked that we implement all possibilities.
+    template <typename T> void draw(const T&);
+
+    // skip() should return true if we can skip this command, false if not.
+    // It may update fIndex directly to skip more than just this one command.
+
+    // Mostly we just blindly call fCanvas and let it handle quick rejects itself.
+    template <typename T> bool skip(const T&) { return false; }
+
+    // We add our own quick rejects for commands added by optimizations.
+    bool skip(const PairedPushCull&);
+    bool skip(const BoundedDrawPosTextH&);
+
+    SkCanvas* fCanvas;
+    unsigned fIndex;
+};
+
+}  // namespace SkRecords
+
 #endif//SkRecordDraw_DEFINED
diff --git a/tools/dump_record.cpp b/tools/dump_record.cpp
index b427a81d61..2d851e7c9f 100644
--- a/tools/dump_record.cpp
+++ b/tools/dump_record.cpp
@@ -7,12 +7,14 @@
 
 #include <stdio.h>
 
+#include "BenchTimer.h"
 #include "LazyDecodeBitmap.h"
 #include "SkCommandLineFlags.h"
 #include "SkGraphics.h"
 #include "SkOSFile.h"
 #include "SkPicture.h"
 #include "SkRecord.h"
+#include "SkRecordDraw.h"
 #include "SkRecordOpts.h"
 #include "SkRecorder.h"
 #include "SkStream.h"
@@ -20,37 +22,68 @@
 DEFINE_string2(skps, r, "", ".SKPs to dump.");
 DEFINE_string(match, "", "The usual filters on file names to dump.");
 DEFINE_bool2(optimize, O, false, "Run SkRecordOptimize before dumping.");
+DEFINE_int32(tile, 1000000000, "Simulated tile size.");
+DEFINE_bool(timeWithCommand, false, "If true, print time next to command, else in first column.");
 
 class Dumper {
 public:
-    Dumper() : fIndent(0) {}
+    explicit Dumper(SkCanvas* canvas, int count) : fDigits(0), fIndent(0), fDraw(canvas) {
+        while (count > 0) {
+            count /= 10;
+            fDigits++;
+        }
+    }
+
+    unsigned index() const { return fDraw.index(); }
+    void next() { fDraw.next(); }
 
     template <typename T>
     void operator()(const T& command) {
-        this->printIndentedName(command);
+        BenchTimer timer;
+        timer.start();
+            fDraw(command);
+        timer.end();
+
+        this->print(command, timer.fCpu);
     }
 
-    void operator()(const SkRecords::Restore& command) {
+    void operator()(const SkRecords::NoOp&) {
+        // Move on without printing anything.
+    }
+
+    template <typename T>
+    void print(const T& command, double time) {
+        this->printNameAndTime(command, time);
+    }
+
+    void print(const SkRecords::Restore& command, double time) {
         --fIndent;
-        this->printIndentedName(command);
+        this->printNameAndTime(command, time);
     }
 
-    void operator()(const SkRecords::Save& command) {
-        this->printIndentedName(command);
+    void print(const SkRecords::Save& command, double time) {
+        this->printNameAndTime(command, time);
         ++fIndent;
     }
 
-    void operator()(const SkRecords::SaveLayer& command) {
-        this->printIndentedName(command);
+    void print(const SkRecords::SaveLayer& command, double time) {
+        this->printNameAndTime(command, time);
         ++fIndent;
     }
 
 private:
     template <typename T>
-    void printIndentedName(const T& command) {
+    void printNameAndTime(const T& command, double time) {
+        if (!FLAGS_timeWithCommand) {
+            printf("%6.1f ", time * 1000);
+        }
+        printf("%*d ", fDigits, fDraw.index());
         for (int i = 0; i < fIndent; i++) {
             putchar('\t');
         }
+        if (FLAGS_timeWithCommand) {
+            printf("%6.1f ", time * 1000);
+        }
         puts(NameOf(command));
     }
 
@@ -67,24 +100,22 @@ private:
         return "\x1b[31;1mSaveLayer\x1b[0m";  // Bold red.
     }
 
+    int fDigits;
     int fIndent;
+    SkRecords::Draw fDraw;
 };
 
 
-static void dump(const char* name, const SkRecord& record) {
-    Dumper dumper;
-
-    unsigned count = record.count();
-    int digits = 0;
-    while (count > 0) {
-        count /= 10;
-        digits++;
-    }
+static void dump(const char* name, int w, int h, const SkRecord& record) {
+    SkBitmap bitmap;
+    bitmap.allocN32Pixels(w, h);
+    SkCanvas canvas(bitmap);
+    canvas.clipRect(SkRect::MakeWH(SkIntToScalar(FLAGS_tile), SkIntToScalar(FLAGS_tile)));
 
     printf("%s %s\n", FLAGS_optimize ? "optimized" : "not-optimized", name);
-    for (unsigned i = 0; i < record.count(); i++) {
-        printf("%*d ", digits, i);
-        record.visit<void>(i, dumper);
+
+    for (Dumper dumper(&canvas, record.count()); dumper.index() < record.count(); dumper.next()) {
+        record.visit<void>(dumper.index(), dumper);
     }
 }
 
@@ -109,16 +140,18 @@ int tool_main(int argc, char** argv) {
             SkDebugf("Could not read %s as an SkPicture.\n", FLAGS_skps[i]);
             exit(1);
         }
+        const int w = src->width(), h = src->height();
 
         SkRecord record;
-        SkRecorder canvas(SkRecorder::kWriteOnly_Mode, &record, src->width(), src->height());
+        SkRecorder canvas(SkRecorder::kWriteOnly_Mode, &record, w, h);
         src->draw(&canvas);
 
+
         if (FLAGS_optimize) {
             SkRecordOptimize(&record);
         }
 
-        dump(FLAGS_skps[i], record);
+        dump(FLAGS_skps[i], w, h, record);
     }
 
     return 0;