Added second "truncated" cpu/wall timer to bench

http://codereview.appspot.com/6476064/

This CL will increase the bench baselines across the board



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

4 files changed, 81 insertions, 15 deletions

diff --git a/bench/BenchTimer.cpp b/bench/BenchTimer.cpp
index 8ac08a70bc..4e0484459d 100644
--- a/bench/BenchTimer.cpp
+++ b/bench/BenchTimer.cpp
@@ -23,9 +23,12 @@
 BenchTimer::BenchTimer(SkGLContext* gl)
         : fCpu(-1.0)
         , fWall(-1.0)
+        , fTruncatedCpu(-1.0)
+        , fTruncatedWall(-1.0)
         , fGpu(-1.0)
 {
     fSysTimer = new BenchSysTimer();
+    fTruncatedSysTimer = new BenchSysTimer();
 #if SK_SUPPORT_GPU
     if (gl) {
         fGpuTimer = new BenchGpuTimer(gl);
@@ -37,6 +40,7 @@ BenchTimer::BenchTimer(SkGLContext* gl)
 
 BenchTimer::~BenchTimer() {
     delete fSysTimer;
+    delete fTruncatedSysTimer;
 #if SK_SUPPORT_GPU
     delete fGpuTimer;
 #endif
@@ -44,12 +48,14 @@ BenchTimer::~BenchTimer() {
 
 void BenchTimer::start() {
     fSysTimer->startWall();
+    fTruncatedSysTimer->startWall();
 #if SK_SUPPORT_GPU
     if (fGpuTimer) {
         fGpuTimer->startGpu();
     }
 #endif
     fSysTimer->startCpu();
+    fTruncatedSysTimer->startCpu();
 }
 
 void BenchTimer::end() {
@@ -63,3 +69,8 @@ void BenchTimer::end() {
 #endif
     fWall = fSysTimer->endWall();
 }
+
+void BenchTimer::truncatedEnd() {
+    fTruncatedCpu = fTruncatedSysTimer->endCpu();
+    fTruncatedWall = fTruncatedSysTimer->endWall();
+}
diff --git a/bench/BenchTimer.h b/bench/BenchTimer.h
index 70675ad17f..58773d403c 100644
--- a/bench/BenchTimer.h
+++ b/bench/BenchTimer.h
@@ -18,8 +18,12 @@ class SkGLContext;
 
 /**
  * SysTimers and GpuTimers are implemented orthogonally.
- * This class combines a SysTimer and a GpuTimer into one single,
- * platform specific, Timer with a simple interface.
+ * This class combines 2 SysTimers and a GpuTimer into one single,
+ * platform specific Timer with a simple interface. The truncated
+ * timer doesn't include the time required for the GPU to finish
+ * its rendering. It should always be <= the un-truncated system
+ * times and (for GPU configurations) can be used to roughly (very
+ * roughly) gauge the GPU load/backlog.
  */
 class BenchTimer {
 public:
@@ -27,12 +31,16 @@ public:
     ~BenchTimer();
     void start();
     void end();
+    void truncatedEnd();
     double fCpu;
     double fWall;
+    double fTruncatedCpu;
+    double fTruncatedWall;
     double fGpu;
 
 private:
     BenchSysTimer *fSysTimer;
+    BenchSysTimer *fTruncatedSysTimer;
 #if SK_SUPPORT_GPU
     BenchGpuTimer *fGpuTimer;
 #endif
diff --git a/bench/benchmain.cpp b/bench/benchmain.cpp
index dfd39fd5bd..dfde94a396 100644
--- a/bench/benchmain.cpp
+++ b/bench/benchmain.cpp
@@ -396,7 +396,7 @@ static bool skip_name(const SkTDArray<const char*> array, const char name[]) {
 
 static void help() {
     SkDebugf("Usage: bench [-o outDir] [-repeat nr] [-logPerIter 1|0] "
-                          "[-timers [wcg]*] [-rotate]\n"
+                          "[-timers [wcgWC]*] [-rotate]\n"
              "    [-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"
@@ -407,8 +407,8 @@ static void help() {
     SkDebugf("    -repeat nr : Each bench repeats for nr times.\n");
     SkDebugf("    -logPerIter 1|0 : "
              "Log each repeat timer instead of mean, default is disabled.\n");
-    SkDebugf("    -timers [wcg]* : "
-             "Display wall time, cpu time or gpu time for each bench.\n");
+    SkDebugf("    -timers [wcgWC]* : "
+             "Display wall, cpu, gpu, truncated wall or truncated cpu time for each bench.\n");
     SkDebugf("    -rotate : Rotate before each bench runs.\n");
     SkDebugf("    -scale : Scale before each bench runs.\n");
     SkDebugf("    -clip : Clip before each bench runs.\n");
@@ -455,7 +455,9 @@ int main (int argc, char * const argv[]) {
     bool forceFilter = false;
     SkTriState::State forceDither = SkTriState::kDefault;
     bool timerWall = false;
+    bool truncatedTimerWall = false;
     bool timerCpu = true;
+    bool truncatedTimerCpu = false;
     bool timerGpu = true;
     bool doScale = false;
     bool doRotate = false;
@@ -508,12 +510,16 @@ int main (int argc, char * const argv[]) {
             argv++;
             if (argv < stop) {
                 timerWall = false;
+                truncatedTimerWall = false;
                 timerCpu = false;
+                truncatedTimerCpu = false;
                 timerGpu = false;
                 for (char* t = *argv; *t; ++t) {
                     switch (*t) {
                     case 'w': timerWall = true; break;
                     case 'c': timerCpu = true; break;
+                    case 'W': truncatedTimerWall = true; break;
+                    case 'C': truncatedTimerCpu = true; break;
                     case 'g': timerGpu = true; break;
                     }
                 }
@@ -836,6 +842,12 @@ int main (int argc, char * const argv[]) {
 
             // warm up caches if needed
             if (repeatDraw > 1) {
+#if SK_SUPPORT_GPU
+                if (glHelper) {
+                    // purge the GPU resources to reduce variance
+                    glHelper->grContext()->freeGpuResources();
+                }
+#endif
                 SkAutoCanvasRestore acr(canvas, true);
                 if (benchMode == kPictureRecord_benchModes) {
                     pictureRecordFrom.draw(canvas);
@@ -853,10 +865,14 @@ 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;
             for (int i = 0; i < repeatDraw; i++) {
                 if ((benchMode == kRecord_benchModes
@@ -874,23 +890,36 @@ int main (int argc, char * const argv[]) {
                     bench->draw(canvas);
                 }
                 canvas->flush();
+
+                // stop the truncated timer after the last canvas call but
+                // don't wait for all the GL calls to complete
+                timer.truncatedEnd();
 #if SK_SUPPORT_GPU
                 if (glHelper) {
                     glHelper->grContext()->flush();
+                    SK_GL(*glHelper->glContext(), Finish());
                 }
 #endif
+                // stop the inclusive and gpu timers once all the GL calls
+                // 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(",");
                 }
@@ -898,22 +927,23 @@ int main (int argc, char * const argv[]) {
                 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);
                 }
 
                 fWallSum += timer.fWall;
                 fCpuSum += timer.fCpu;
+                fTruncatedWallSum += timer.fTruncatedWall;
+                fTruncatedCpuSum += timer.fTruncatedCpu;
                 fGpuSum += timer.fGpu;
             }
-#if SK_SUPPORT_GPU
-           if (glHelper) {
-                SK_GL(*glHelper->glContext(), Finish());
-           }
-#endif
             if (repeatDraw > 1) {
                 // output each repeat (no average) if logPerIter is set,
                 // otherwise output only the average
@@ -924,6 +954,12 @@ int main (int argc, char * const argv[]) {
                     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);
@@ -933,9 +969,15 @@ int main (int argc, char * const argv[]) {
                 if (timerWall) {
                     str += fWallStr;
                 }
+                if (truncatedTimerWall) {
+                    str += fTruncatedWallStr;
+                }
                 if (timerCpu) {
                     str += fCpuStr;
                 }
+                if (truncatedTimerCpu) {
+                    str += fTruncatedCpuStr;
+                }
                 if (timerGpu && glHelper && fGpuSum > 0) {
                     str += fGpuStr;
                 }
diff --git a/tools/PictureBenchmark.cpp b/tools/PictureBenchmark.cpp
index df30d5a561..164d3c356c 100644
--- a/tools/PictureBenchmark.cpp
+++ b/tools/PictureBenchmark.cpp
@@ -43,7 +43,7 @@ void PipePictureBenchmark::run(SkPicture* pict) {
     fRenderer.resetState();
 
     BenchTimer* timer = this->setupTimer();
-    double wall_time = 0;
+    double wall_time = 0, truncated_wall_time = 0;
 #if SK_SUPPORT_GPU
     double gpu_time = 0;
 #endif
@@ -55,6 +55,7 @@ void PipePictureBenchmark::run(SkPicture* pict) {
         fRenderer.resetState();
 
         wall_time += timer->fWall;
+        truncated_wall_time += timer->fTruncatedWall;
 #if SK_SUPPORT_GPU
         if (fRenderer.isUsingGpuDevice()) {
             gpu_time += timer->fGpu;
@@ -83,7 +84,7 @@ void RecordPictureBenchmark::run(SkPicture* pict) {
     }
 
     BenchTimer* timer = setupTimer();
-    double wall_time = 0;
+    double wall_time = 0, truncated_wall_time = 0;
 
     for (int i = 0; i < fRepeats + 1; ++i) {
         SkPicture replayer;
@@ -96,6 +97,7 @@ void RecordPictureBenchmark::run(SkPicture* pict) {
         // We want to ignore first time effects
         if (i > 0) {
             wall_time += timer->fWall;
+            truncated_wall_time += timer->fTruncatedWall;
         }
     }
 
@@ -121,7 +123,7 @@ void SimplePictureBenchmark::run(SkPicture* pict) {
 
 
     BenchTimer* timer = this->setupTimer();
-    double wall_time = 0;
+    double wall_time = 0, truncated_wall_time = 0;
 #if SK_SUPPORT_GPU
     double gpu_time = 0;
 #endif
@@ -133,6 +135,7 @@ void SimplePictureBenchmark::run(SkPicture* pict) {
         fRenderer.resetState();
 
         wall_time += timer->fWall;
+        truncated_wall_time += timer->fTruncatedWall;
 #if SK_SUPPORT_GPU
         if (fRenderer.isUsingGpuDevice()) {
             gpu_time += timer->fGpu;
@@ -169,7 +172,7 @@ void TiledPictureBenchmark::run(SkPicture* pict) {
     fRenderer.resetState();
 
     BenchTimer* timer = setupTimer();
-    double wall_time = 0;
+    double wall_time = 0, truncated_wall_time = 0;
 #if SK_SUPPORT_GPU
     double gpu_time = 0;
 #endif
@@ -181,6 +184,7 @@ void TiledPictureBenchmark::run(SkPicture* pict) {
         fRenderer.resetState();
 
         wall_time += timer->fWall;
+        truncated_wall_time += timer->fTruncatedWall;
 #if SK_SUPPORT_GPU
         if (fRenderer.isUsingGpuDevice()) {
             gpu_time += timer->fGpu;
@@ -216,7 +220,7 @@ void UnflattenPictureBenchmark::run(SkPicture* pict) {
     }
 
     BenchTimer* timer = setupTimer();
-    double wall_time = 0;
+    double wall_time = 0, truncated_wall_time = 0;
 
     for (int i = 0; i < fRepeats + 1; ++i) {
         SkPicture replayer;
@@ -231,6 +235,7 @@ void UnflattenPictureBenchmark::run(SkPicture* pict) {
         // We want to ignore first time effects
         if (i > 0) {
             wall_time += timer->fWall;
+            truncated_wall_time += timer->fTruncatedWall;
         }
     }