cc: Increased robustness of rasterize and record benchmark.

- 'protected' relevent trace events from changes, by putting argument strings
  as constants into separate file.
- fixed a bug in the collection of raster times, that would output wrong 
  statistics for layers with multiple pictures in a pile.
- Added command line parameters to set number of raster and record repeats,
  wait time before starting the benchmark, and wait time before taking the
  measurements. 
- Reduced the default number of raster and record repeats from 100 to 20. 
  This increases variance, but improves overall robustness (e.g. avoiding
  event buffer overflows)
- Added command line option to print statistics after every page run.

R=nduca@chromium.org,tengs@chromium.org
BUG=226489

Review URL: https://chromiumcodereview.appspot.com/18048006

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@211728 0039d316-1c4b-4281-b951-d872f2087c98

12 files changed, 130 insertions, 74 deletions

diff --git a/cc/debug/OWNERS b/cc/debug/OWNERS
new file mode 100644
index 0000000..a46edee
--- /dev/null
+++ b/cc/debug/OWNERS
@@ -0,0 +1,4 @@
+# Changes to this file may break telemetry benchmarks
+per-file benchmark_instrumentation.h=set noparent
+per-file benchmark_instrumentation.h=ernstm@chromium.org
+per-file benchmark_instrumentation.h=nduca@chromium.org
diff --git a/cc/debug/benchmark_instrumentation.h b/cc/debug/benchmark_instrumentation.h
new file mode 100644
index 0000000..006bdf7
--- /dev/null
+++ b/cc/debug/benchmark_instrumentation.h
@@ -0,0 +1,33 @@
+// Copyright 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef CC_DEBUG_BENCHMARK_INSTRUMENTATION_H_
+#define CC_DEBUG_BENCHMARK_INSTRUMENTATION_H_
+
+#include "base/debug/trace_event.h"
+
+namespace cc {
+namespace benchmark_instrumentation {
+// Please do not change the string constants in this file (or the TRACE_EVENT
+// calls that use them) without updating
+// tools/perf/perf_tools/rasterize_and_record_benchmark.py accordingly.
+// The benchmark searches for events and their arguments by name.
+const char kCategory[] = "cc,benchmark";
+const char kCommitNumber[] = "commit_number";
+const char kSourceFrameNumber[] = "source_frame_number";
+const char kData[] = "data";
+const char kWidth[] = "width";
+const char kHeight[] = "height";
+const char kNumPixelsRasterized[] = "num_pixels_rasterized";
+const char kLayerTreeHostUpdateLayers[] = "LayerTreeHost::UpdateLayers";
+const char kPictureLayerUpdate[] = "PictureLayer::Update";
+const char kRunRasterOnThread[] = "RasterWorkerPoolTaskImpl::RunRasterOnThread";
+const char kRecordLoop[] = "RecordLoop";
+const char kRasterLoop[] = "RasterLoop";
+const char kPictureRecord[] = "Picture::Record";
+const char kPictureRaster[] = "Picture::Raster";
+}  // namespace benchmark_instrumentation
+}  // namespace cc
+
+#endif  // CC_DEBUG_BENCHMARK_INSTRUMENTATION_H_
diff --git a/cc/layers/picture_layer.cc b/cc/layers/picture_layer.cc
index 1a155f6..acd2bf6 100644
--- a/cc/layers/picture_layer.cc
+++ b/cc/layers/picture_layer.cc
@@ -4,6 +4,7 @@
 
 #include "cc/layers/picture_layer.h"
 
+#include "cc/debug/benchmark_instrumentation.h"
 #include "cc/debug/devtools_instrumentation.h"
 #include "cc/layers/picture_layer_impl.h"
 #include "cc/trees/layer_tree_impl.h"
@@ -84,6 +85,11 @@ bool PictureLayer::Update(ResourceUpdateQueue*,
   // Do not early-out of this function so that PicturePile::Update has a chance
   // to record pictures due to changing visibility of this layer.
 
+  TRACE_EVENT1(benchmark_instrumentation::kCategory,
+               benchmark_instrumentation::kPictureLayerUpdate,
+               benchmark_instrumentation::kCommitNumber,
+               layer_tree_host()->commit_number());
+
   pile_->Resize(paint_properties().bounds);
 
   // Calling paint in WebKit can sometimes cause invalidations, so save
@@ -100,8 +106,7 @@ bool PictureLayer::Update(ResourceUpdateQueue*,
                                contents_opaque(),
                                pile_invalidation_,
                                visible_layer_rect,
-                               rendering_stats_instrumentation(),
-                               layer_tree_host()->commit_number());
+                               rendering_stats_instrumentation());
   if (!updated) {
     // If this invalidation did not affect the pile, then it can be cleared as
     // an optimization.
diff --git a/cc/resources/picture.cc b/cc/resources/picture.cc
index af0e35c..a21db75 100644
--- a/cc/resources/picture.cc
+++ b/cc/resources/picture.cc
@@ -13,6 +13,7 @@
 #include "base/values.h"
 #include "cc/base/math_util.h"
 #include "cc/base/util.h"
+#include "cc/debug/benchmark_instrumentation.h"
 #include "cc/debug/rendering_stats_instrumentation.h"
 #include "cc/debug/traced_picture.h"
 #include "cc/debug/traced_value.h"
@@ -184,11 +185,10 @@ void Picture::CloneForDrawing(int num_threads) {
 void Picture::Record(ContentLayerClient* painter,
                      const SkTileGridPicture::TileGridInfo& tile_grid_info,
                      RenderingStatsInstrumentation* stats_instrumentation) {
-  // If you change the name of this event or its arguments, please update
-  // tools/perf/perf_tools/rasterize_and_record_benchmark.py as well.
-  TRACE_EVENT2("cc", "Picture::Record",
-               "width", layer_rect_.width(),
-               "height", layer_rect_.height());
+  TRACE_EVENT2(benchmark_instrumentation::kCategory,
+               benchmark_instrumentation::kPictureRecord,
+               benchmark_instrumentation::kWidth, layer_rect_.width(),
+               benchmark_instrumentation::kHeight, layer_rect_.height());
 
   DCHECK(!tile_grid_info.fTileInterval.isEmpty());
   picture_ = skia::AdoptRef(new SkTileGridPicture(
@@ -291,10 +291,10 @@ void Picture::Raster(
     SkDrawPictureCallback* callback,
     gfx::Rect content_rect,
     float contents_scale) {
-  // If you change the name of this event or its arguments, please update
-  // tools/perf/perf_tools/rasterize_and_record_benchmark.py as well.
-  TRACE_EVENT_BEGIN1("cc", "Picture::Raster",
-    "data", AsTraceableRasterData(content_rect, contents_scale));
+  TRACE_EVENT_BEGIN1(benchmark_instrumentation::kCategory,
+                     benchmark_instrumentation::kPictureRaster,
+                     "data",
+                     AsTraceableRasterData(content_rect, contents_scale));
 
   DCHECK(picture_);
 
@@ -306,10 +306,10 @@ void Picture::Raster(
   SkIRect bounds;
   canvas->getClipDeviceBounds(&bounds);
   canvas->restore();
-  // If you change the name of this event or its arguments, please update
-  // tools/perf/perf_tools/rasterize_and_record_benchmark.py as well.
-  TRACE_EVENT_END1("cc", "Picture::Raster",
-                   "num_pixels_rasterized", bounds.width() * bounds.height());
+  TRACE_EVENT_END1(benchmark_instrumentation::kCategory,
+                   benchmark_instrumentation::kPictureRaster,
+                   benchmark_instrumentation::kNumPixelsRasterized,
+                   bounds.width() * bounds.height());
 }
 
 void Picture::Replay(SkCanvas* canvas) {
diff --git a/cc/resources/picture_pile.cc b/cc/resources/picture_pile.cc
index b6c41ba..17283dd 100644
--- a/cc/resources/picture_pile.cc
+++ b/cc/resources/picture_pile.cc
@@ -8,6 +8,7 @@
 #include <vector>
 
 #include "cc/base/region.h"
+#include "cc/debug/benchmark_instrumentation.h"
 #include "cc/resources/picture_pile_impl.h"
 
 namespace {
@@ -37,8 +38,7 @@ bool PicturePile::Update(
     bool contents_opaque,
     const Region& invalidation,
     gfx::Rect visible_layer_rect,
-    RenderingStatsInstrumentation* stats_instrumentation,
-    int commit_number) {
+    RenderingStatsInstrumentation* stats_instrumentation) {
   background_color_ = background_color;
   contents_opaque_ = contents_opaque;
 
@@ -112,10 +112,8 @@ bool PicturePile::Update(
          pic != pic_list.end(); ++pic) {
       if (!(*pic)->HasRecording()) {
         modified_pile = true;
-        // If you change the name of this event or its arguments, please update
-        // tools/perf/perf_tools/rasterize_and_record_benchmark.py as well.
-        TRACE_EVENT1("cc", "PicturePile::Update recording loop",
-                     "commit_number", commit_number);
+        TRACE_EVENT0(benchmark_instrumentation::kCategory,
+                     benchmark_instrumentation::kRecordLoop);
         for (int i = 0; i < repeat_count; i++)
           (*pic)->Record(painter, tile_grid_info_, stats_instrumentation);
         (*pic)->GatherPixelRefs(tile_grid_info_, stats_instrumentation);
diff --git a/cc/resources/picture_pile.h b/cc/resources/picture_pile.h
index 9aa88cc..7830a9e 100644
--- a/cc/resources/picture_pile.h
+++ b/cc/resources/picture_pile.h
@@ -26,8 +26,7 @@ class CC_EXPORT PicturePile : public PicturePileBase {
       bool contents_opaque,
       const Region& invalidation,
       gfx::Rect visible_layer_rect,
-      RenderingStatsInstrumentation* stats_instrumentation,
-      int commit_number);
+      RenderingStatsInstrumentation* stats_instrumentation);
 
   void set_num_raster_threads(int num_raster_threads) {
     num_raster_threads_ = num_raster_threads;
diff --git a/cc/resources/picture_pile_impl.cc b/cc/resources/picture_pile_impl.cc
index 99e7c46..42f3dab 100644
--- a/cc/resources/picture_pile_impl.cc
+++ b/cc/resources/picture_pile_impl.cc
@@ -7,6 +7,7 @@
 
 #include "base/debug/trace_event.h"
 #include "cc/base/region.h"
+#include "cc/debug/benchmark_instrumentation.h"
 #include "cc/debug/debug_colors.h"
 #include "cc/resources/picture_pile_impl.h"
 #include "skia/ext/analysis_canvas.h"
@@ -197,6 +198,8 @@ void PicturePileImpl::RasterCommon(
           base::TimeDelta::FromInternalValue(std::numeric_limits<int64>::max());
       int repeat_count = std::max(1, slow_down_raster_scale_factor_for_debug_);
 
+      TRACE_EVENT0(benchmark_instrumentation::kCategory,
+                   benchmark_instrumentation::kRasterLoop);
       for (int j = 0; j < repeat_count; ++j) {
         base::TimeTicks start_time;
         if (raster_stats)
diff --git a/cc/resources/picture_pile_unittest.cc b/cc/resources/picture_pile_unittest.cc
index 0ed19f9..1eeb5ad 100644
--- a/cc/resources/picture_pile_unittest.cc
+++ b/cc/resources/picture_pile_unittest.cc
@@ -46,8 +46,7 @@ TEST(PicturePileTest, SmallInvalidateInflated) {
                false,
                gfx::Rect(layer_size),
                gfx::Rect(layer_size),
-               &stats_instrumentation,
-               0);
+               &stats_instrumentation);
 
   // Invalidate something inside a tile.
   gfx::Rect invalidate_rect(50, 50, 1, 1);
@@ -56,8 +55,7 @@ TEST(PicturePileTest, SmallInvalidateInflated) {
                false,
                invalidate_rect,
                gfx::Rect(layer_size),
-               &stats_instrumentation,
-               0);
+               &stats_instrumentation);
 
   EXPECT_EQ(1, pile->tiling().num_tiles_x());
   EXPECT_EQ(1, pile->tiling().num_tiles_y());
@@ -100,8 +98,7 @@ TEST(PicturePileTest, LargeInvalidateInflated) {
                false,
                gfx::Rect(layer_size),
                gfx::Rect(layer_size),
-               &stats_instrumentation,
-               0);
+               &stats_instrumentation);
 
   // Invalidate something inside a tile.
   gfx::Rect invalidate_rect(50, 50, 100, 100);
@@ -110,8 +107,7 @@ TEST(PicturePileTest, LargeInvalidateInflated) {
                false,
                invalidate_rect,
                gfx::Rect(layer_size),
-               &stats_instrumentation,
-               0);
+               &stats_instrumentation);
 
   EXPECT_EQ(1, pile->tiling().num_tiles_x());
   EXPECT_EQ(1, pile->tiling().num_tiles_y());
@@ -165,8 +161,7 @@ TEST(PicturePileTest, InvalidateOnTileBoundaryInflated) {
                false,
                gfx::Rect(layer_size),
                gfx::Rect(layer_size),
-               &stats_instrumentation,
-               0);
+               &stats_instrumentation);
 
   // Invalidate something just over a tile boundary by a single pixel.
   // This will invalidate the tile (1, 1), as well as 1 row of pixels in (1, 0).
@@ -180,8 +175,7 @@ TEST(PicturePileTest, InvalidateOnTileBoundaryInflated) {
                false,
                invalidate_rect,
                gfx::Rect(layer_size),
-               &stats_instrumentation,
-               0);
+               &stats_instrumentation);
 
   for (int i = 0; i < pile->tiling().num_tiles_x(); ++i) {
     for (int j = 0; j < pile->tiling().num_tiles_y(); ++j) {
diff --git a/cc/resources/raster_worker_pool.cc b/cc/resources/raster_worker_pool.cc
index ce3c987..aced03f 100644
--- a/cc/resources/raster_worker_pool.cc
+++ b/cc/resources/raster_worker_pool.cc
@@ -7,6 +7,7 @@
 #include "base/json/json_writer.h"
 #include "base/metrics/histogram.h"
 #include "base/values.h"
+#include "cc/debug/benchmark_instrumentation.h"
 #include "cc/debug/devtools_instrumentation.h"
 #include "cc/debug/traced_value.h"
 #include "cc/resources/picture_pile_impl.h"
@@ -89,12 +90,10 @@ class RasterWorkerPoolTaskImpl : public internal::RasterWorkerPoolTask {
   }
 
   bool RunRasterOnThread(SkDevice* device, unsigned thread_index) {
-    // If you change the name of this event or its arguments, please update
-    // tools/perf/perf_tools/rasterize_and_record_benchmark.py as well.
     TRACE_EVENT2(
-        "cc",
-        "RasterWorkerPoolTaskImpl::RunRasterOnThread",
-        "data",
+        benchmark_instrumentation::kCategory,
+        benchmark_instrumentation::kRunRasterOnThread,
+        benchmark_instrumentation::kData,
         TracedValue::FromValue(DataAsValue().release()),
         "raster_mode",
         TracedValue::FromValue(RasterModeAsValue(raster_mode_).release()));
diff --git a/cc/trees/layer_tree_host.cc b/cc/trees/layer_tree_host.cc
index af751dd..a4ff570 100644
--- a/cc/trees/layer_tree_host.cc
+++ b/cc/trees/layer_tree_host.cc
@@ -17,6 +17,7 @@
 #include "cc/animation/animation_registrar.h"
 #include "cc/animation/layer_animation_controller.h"
 #include "cc/base/math_util.h"
+#include "cc/debug/benchmark_instrumentation.h"
 #include "cc/debug/overdraw_metrics.h"
 #include "cc/debug/rendering_stats_instrumentation.h"
 #include "cc/input/top_controls_manager.h"
@@ -690,10 +691,10 @@ bool LayerTreeHost::UsingSharedMemoryResources() {
 
 bool LayerTreeHost::UpdateLayers(Layer* root_layer,
                                  ResourceUpdateQueue* queue) {
-  // If you change the name of this event or its arguments, please update
-  // tools/perf/perf_tools/rasterize_and_record_benchmark.py as well.
-  TRACE_EVENT1("cc", "LayerTreeHost::UpdateLayers",
-               "SourceFrameNumber", commit_number());
+  TRACE_EVENT1(benchmark_instrumentation::kCategory,
+               benchmark_instrumentation::kLayerTreeHostUpdateLayers,
+               benchmark_instrumentation::kCommitNumber,
+               commit_number());
 
   LayerList update_list;
   {
diff --git a/tools/perf/perf_tools/rasterize_and_record_benchmark.py b/tools/perf/perf_tools/rasterize_and_record_benchmark.py
index 2dd5c5c..fb0f822 100644
--- a/tools/perf/perf_tools/rasterize_and_record_benchmark.py
+++ b/tools/perf/perf_tools/rasterize_and_record_benchmark.py
@@ -45,30 +45,32 @@ class StatsCollector(object):
     for event in self.timeline.GetAllEventsOfName(
         "RasterWorkerPoolTaskImpl::RunRasterOnThread"):
       if event.args["data"]["source_frame_number"] == frame_number:
-        best_rasterize_time = float("inf")
-        for child in event.GetAllSubSlices():
-          if child.name == "Picture::Raster":
-            best_rasterize_time = min(best_rasterize_time, child.duration)
-            if "num_pixels_rasterized" in child.args:
+        for raster_loop_event in event.GetAllSubSlicesOfName("RasterLoop"):
+          best_rasterize_time = float("inf")
+          for raster_event in raster_loop_event.GetAllSubSlicesOfName(
+              "Picture::Raster"):
+            if "num_pixels_rasterized" in raster_event.args:
+              best_rasterize_time = min(best_rasterize_time,
+                                        raster_event.duration)
               self.total_pixels_rasterized += \
-                  child.args["num_pixels_rasterized"]
-        if best_rasterize_time == float('inf'):
-          best_rasterize_time = 0
-        self.total_best_rasterize_time += best_rasterize_time
+                  raster_event.args["num_pixels_rasterized"]
+          if best_rasterize_time == float('inf'):
+            best_rasterize_time = 0
+          self.total_best_rasterize_time += best_rasterize_time
 
   def GatherRecordStats(self, frame_number):
-    for event in self.timeline.GetAllEventsOfName(
-        "PicturePile::Update recording loop"):
+    for event in self.timeline.GetAllEventsOfName("PictureLayer::Update"):
       if event.args["commit_number"] == frame_number:
-        best_record_time = float('inf')
-        for child in event.GetAllSubSlices():
-          if child.name == "Picture::Record":
-            best_record_time = min(best_record_time, child.duration)
-            self.total_pixels_recorded += \
-                child.args["width"] * child.args["height"]
-        if best_record_time == float('inf'):
-          best_record_time = 0
-        self.total_best_record_time += best_record_time
+        for record_loop_event in event.GetAllSubSlicesOfName("RecordLoop"):
+          best_record_time = float('inf')
+          for record_event in record_loop_event.GetAllSubSlicesOfName(
+              "Picture::Record"):
+            best_record_time = min(best_record_time, record_event.duration)
+            self.total_pixels_recorded += (record_event.args["width"] *
+                                           record_event.args["height"])
+          if best_record_time == float('inf'):
+            best_record_time = 0
+          self.total_best_record_time += best_record_time
 
   def GatherRenderingStats(self):
     trigger_time = self.FindTriggerTime()
@@ -90,13 +92,27 @@ class RasterizeAndPaintMeasurement(page_measurement.PageMeasurement):
     parser.add_option('--report-all-results', dest='report_all_results',
                       action='store_true',
                       help='Reports all data collected')
+    parser.add_option('--raster-record-repeat', dest='raster_record_repeat',
+                      default=20,
+                      help='Repetitions in raster and record loops.' +
+                      'Higher values reduce variance, but can cause' +
+                      'instability (timeouts, event buffer overflows, etc.).')
+    parser.add_option('--start-wait-time', dest='start_wait_time',
+                      default=2,
+                      help='Wait time before the benchmark is started ' +
+                      '(must be long enought to load all content)')
+    parser.add_option('--stop-wait-time', dest='stop_wait_time',
+                      default=5,
+                      help='Wait time before measurement is taken ' +
+                      '(must be long enough to render one frame)')
 
   def CustomizeBrowserOptions(self, options):
     options.extra_browser_args.append('--enable-gpu-benchmarking')
-    # Run each raster task 100 times. This allows us to report the time for the
+    # Run each raster task N times. This allows us to report the time for the
     # best run, effectively excluding cache effects and time when the thread is
     # de-scheduled.
-    options.extra_browser_args.append('--slow-down-raster-scale-factor=100')
+    options.extra_browser_args.append(
+        '--slow-down-raster-scale-factor=' + str(options.raster_record_repeat))
     # Enable impl-side-painting. Current version of benchmark only works for
     # this mode.
     options.extra_browser_args.append('--enable-impl-side-painting')
@@ -106,13 +122,13 @@ class RasterizeAndPaintMeasurement(page_measurement.PageMeasurement):
   def MeasurePage(self, page, tab, results):
     self._metrics = smoothness_metrics.SmoothnessMetrics(tab)
 
-    # Rasterize only what's visible
+    # Rasterize only what's visible.
     tab.ExecuteJavaScript(
         'chrome.gpuBenchmarking.setRasterizeOnlyVisibleContent();')
 
-    # Wait until the page has loaded and come to a somewhat steady state
-    # Empirical wait time for workstation. May need to adjust for other devices
-    time.sleep(5)
+    # Wait until the page has loaded and come to a somewhat steady state.
+    # Needs to be adjusted for every device (~2 seconds for workstation).
+    time.sleep(float(self.options.start_wait_time))
 
     # Render one frame before we start gathering a trace. On some pages, the
     # first frame requested has more variance in the number of pixels
@@ -125,7 +141,7 @@ class RasterizeAndPaintMeasurement(page_measurement.PageMeasurement):
         });
     """)
 
-    tab.browser.StartTracing('webkit,cc', 60)
+    tab.browser.StartTracing('webkit,benchmark', 60)
     self._metrics.Start()
 
     tab.ExecuteJavaScript("""
@@ -136,10 +152,11 @@ class RasterizeAndPaintMeasurement(page_measurement.PageMeasurement):
           window.__rafFired  = true;
         });
     """)
-    # Wait until the frame was drawn
-    # Empirical wait time for workstation. May need to adjust for other devices
+    # Wait until the frame was drawn.
+    # Needs to be adjusted for every device and for different
+    # raster_record_repeat counts.
     # TODO(ernstm): replace by call-back.
-    time.sleep(5)
+    time.sleep(float(self.options.stop_wait_time))
     tab.ExecuteJavaScript('console.timeEnd("measureNextFrame")')
 
     tab.browser.StopTracing()
diff --git a/tools/telemetry/telemetry/core/timeline/tracing/slice.py b/tools/telemetry/telemetry/core/timeline/tracing/slice.py
index cc41fc3..178b33a 100644
--- a/tools/telemetry/telemetry/core/timeline/tracing/slice.py
+++ b/tools/telemetry/telemetry/core/timeline/tracing/slice.py
@@ -35,3 +35,6 @@ class Slice(timeline_event.TimelineEvent):
 
   def GetAllSubSlices(self):
     return list(self._GetSubSlicesRecursive())
+
+  def GetAllSubSlicesOfName(self, name):
+    return [e for e in self.GetAllSubSlices() if e.name == name]