Improved measurement of rasterize time and pixels rasterized.

 - Reporting minimum rasterize time out of multiple runs excludes
   time when the raster thread is de-scheduled and it excludes cache effects.
   In order for this to work reliably, slow-down-raster-scale-factor needs to
   be set to a large value (e.g. 100).
 - Fixed computation of number of pixels rasterized to use the intersection
   of content_clip and canvas_rect, instead of content_clip.
 - The improved measurements are designed for a new rasterize and paint
   benchmark that will be committed in a spearate CL.
- Separated paint time (direct rasterization without prior recording to an SkPicture) from record time
    
BUG=226489

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

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

15 files changed, 129 insertions, 58 deletions

diff --git a/cc/debug/rendering_stats.cc b/cc/debug/rendering_stats.cc
index 6b43169..480aa88 100644
--- a/cc/debug/rendering_stats.cc
+++ b/cc/debug/rendering_stats.cc
@@ -12,6 +12,7 @@ RenderingStats::RenderingStats()
       dropped_frame_count(0),
       total_commit_count(0),
       total_pixels_painted(0),
+      total_pixels_recorded(0),
       total_pixels_rasterized(0),
       num_impl_thread_scrolls(0),
       num_main_thread_scrolls(0),
@@ -27,6 +28,8 @@ void RenderingStats::EnumerateFields(Enumerator* enumerator) const {
   enumerator->AddInt64("droppedFrameCount", dropped_frame_count);
   enumerator->AddDouble("totalPaintTimeInSeconds",
                         total_paint_time.InSecondsF());
+  enumerator->AddDouble("totalRecordTimeInSeconds",
+                        total_record_time.InSecondsF());
   enumerator->AddDouble("totalRasterizeTimeInSeconds",
                         total_rasterize_time.InSecondsF());
   enumerator->AddDouble(
@@ -34,8 +37,11 @@ void RenderingStats::EnumerateFields(Enumerator* enumerator) const {
       total_rasterize_time_for_now_bins_on_pending_tree.InSecondsF());
   enumerator->AddDouble("totalCommitTimeInSeconds",
                         total_commit_time.InSecondsF());
+  enumerator->AddDouble("bestRasterizeTimeInSeconds",
+                        best_rasterize_time.InSecondsF());
   enumerator->AddInt64("totalCommitCount", total_commit_count);
   enumerator->AddInt64("totalPixelsPainted", total_pixels_painted);
+  enumerator->AddInt64("totalPixelsRecorded", total_pixels_recorded);
   enumerator->AddInt64("totalPixelsRasterized", total_pixels_rasterized);
   enumerator->AddInt64("numImplThreadScrolls", num_impl_thread_scrolls);
   enumerator->AddInt64("numMainThreadScrolls", num_main_thread_scrolls);
@@ -58,12 +64,15 @@ void RenderingStats::Add(const RenderingStats& other) {
   screen_frame_count += other.screen_frame_count;
   dropped_frame_count += other.dropped_frame_count;
   total_paint_time += other.total_paint_time;
+  total_record_time += other.total_record_time;
   total_rasterize_time += other.total_rasterize_time;
   total_rasterize_time_for_now_bins_on_pending_tree +=
       other.total_rasterize_time_for_now_bins_on_pending_tree;
   total_commit_time += other.total_commit_time;
+  best_rasterize_time += other.best_rasterize_time;
   total_commit_count += other.total_commit_count;
   total_pixels_painted += other.total_pixels_painted;
+  total_pixels_recorded += other.total_pixels_recorded;
   total_pixels_rasterized += other.total_pixels_rasterized;
   num_impl_thread_scrolls += other.num_impl_thread_scrolls;
   num_main_thread_scrolls += other.num_main_thread_scrolls;
diff --git a/cc/debug/rendering_stats.h b/cc/debug/rendering_stats.h
index 675af68..a95f4fc 100644
--- a/cc/debug/rendering_stats.h
+++ b/cc/debug/rendering_stats.h
@@ -16,11 +16,14 @@ struct CC_EXPORT RenderingStats {
   int64 screen_frame_count;
   int64 dropped_frame_count;
   base::TimeDelta total_paint_time;
+  base::TimeDelta total_record_time;
   base::TimeDelta total_rasterize_time;
   base::TimeDelta total_rasterize_time_for_now_bins_on_pending_tree;
   base::TimeDelta total_commit_time;
+  base::TimeDelta best_rasterize_time;
   int64 total_commit_count;
   int64 total_pixels_painted;
+  int64 total_pixels_recorded;
   int64 total_pixels_rasterized;
   int64 num_impl_thread_scrolls;
   int64 num_main_thread_scrolls;
diff --git a/cc/debug/rendering_stats_instrumentation.cc b/cc/debug/rendering_stats_instrumentation.cc
index f19daae..e2b071c 100644
--- a/cc/debug/rendering_stats_instrumentation.cc
+++ b/cc/debug/rendering_stats_instrumentation.cc
@@ -87,19 +87,31 @@ void RenderingStatsInstrumentation::AddPaint(base::TimeDelta duration,
   rendering_stats_.total_pixels_painted += pixels;
 }
 
-void RenderingStatsInstrumentation::AddRaster(base::TimeDelta duration,
+void RenderingStatsInstrumentation::AddRecord(base::TimeDelta duration,
+                                              int64 pixels) {
+  if (!record_rendering_stats_)
+    return;
+
+  base::AutoLock scoped_lock(lock_);
+  rendering_stats_.total_record_time += duration;
+  rendering_stats_.total_pixels_recorded += pixels;
+}
+
+void RenderingStatsInstrumentation::AddRaster(base::TimeDelta total_duration,
+                                              base::TimeDelta best_duration,
                                               int64 pixels,
                                               bool is_in_pending_tree_now_bin) {
   if (!record_rendering_stats_)
     return;
 
   base::AutoLock scoped_lock(lock_);
-  rendering_stats_.total_rasterize_time += duration;
+  rendering_stats_.total_rasterize_time += total_duration;
+  rendering_stats_.best_rasterize_time += best_duration;
   rendering_stats_.total_pixels_rasterized += pixels;
 
   if (is_in_pending_tree_now_bin) {
     rendering_stats_.total_rasterize_time_for_now_bins_on_pending_tree +=
-        duration;
+        total_duration;
   }
 }
 
diff --git a/cc/debug/rendering_stats_instrumentation.h b/cc/debug/rendering_stats_instrumentation.h
index c3ec320..f4240e7 100644
--- a/cc/debug/rendering_stats_instrumentation.h
+++ b/cc/debug/rendering_stats_instrumentation.h
@@ -42,7 +42,9 @@ class CC_EXPORT RenderingStatsInstrumentation {
 
   void AddCommit(base::TimeDelta duration);
   void AddPaint(base::TimeDelta duration, int64 pixels);
-  void AddRaster(base::TimeDelta duration,
+  void AddRecord(base::TimeDelta duration, int64 pixels);
+  void AddRaster(base::TimeDelta total_duraction,
+                 base::TimeDelta best_duration,
                  int64 pixels,
                  bool is_in_pending_tree_now_bin);
 
diff --git a/cc/layers/picture_layer_impl_unittest.cc b/cc/layers/picture_layer_impl_unittest.cc
index 8f73c4c..ee21993 100644
--- a/cc/layers/picture_layer_impl_unittest.cc
+++ b/cc/layers/picture_layer_impl_unittest.cc
@@ -200,7 +200,10 @@ class PictureLayerImplTest : public testing::Test {
     std::vector<SkRect>::const_iterator rect_iter = rects.begin();
     for (tile_iter = tiles.begin(); tile_iter < tiles.end(); tile_iter++) {
       MockCanvas mock_canvas(&device);
-      active_pile->Raster(&mock_canvas, (*tile_iter)->content_rect(), 1.0f);
+      active_pile->Raster(&mock_canvas,
+                          (*tile_iter)->content_rect(),
+                          1.0f,
+                          NULL);
 
       // This test verifies that when drawing the contents of a specific tile
       // at content scale 1.0, the playback canvas never receives content from
diff --git a/cc/output/gl_renderer.cc b/cc/output/gl_renderer.cc
index 4a0c7ba..adfcf47 100644
--- a/cc/output/gl_renderer.cc
+++ b/cc/output/gl_renderer.cc
@@ -1467,7 +1467,8 @@ void GLRenderer::DrawPictureQuad(const DrawingFrame* frame,
   SkDevice device(on_demand_tile_raster_bitmap_);
   SkCanvas canvas(&device);
 
-  quad->picture_pile->Raster(&canvas, quad->content_rect, quad->contents_scale);
+  quad->picture_pile->Raster(&canvas, quad->content_rect, quad->contents_scale,
+                             NULL);
 
   resource_provider_->SetPixels(
       on_demand_tile_raster_resource_id_,
diff --git a/cc/resources/bitmap_content_layer_updater.cc b/cc/resources/bitmap_content_layer_updater.cc
index 35d3bb5..cb3817b 100644
--- a/cc/resources/bitmap_content_layer_updater.cc
+++ b/cc/resources/bitmap_content_layer_updater.cc
@@ -63,17 +63,19 @@ void BitmapContentLayerUpdater::PrepareToUpdate(
         canvas_size_.width(), canvas_size_.height(), opaque_));
   }
 
-  if (stats) {
-    stats->total_pixels_rasterized +=
-        content_rect.width() * content_rect.height();
-  }
-
+  base::TimeTicks paint_start_time;
+  if (stats)
+    paint_start_time = base::TimeTicks::HighResNow();
   PaintContents(canvas_.get(),
                 content_rect,
                 contents_width_scale,
                 contents_height_scale,
                 resulting_opaque_rect,
                 stats);
+  if (stats) {
+    stats->total_paint_time += base::TimeTicks::HighResNow() - paint_start_time;
+    stats->total_pixels_painted += content_rect.width() * content_rect.height();
+  }
 }
 
 void BitmapContentLayerUpdater::UpdateTexture(ResourceUpdateQueue* queue,
diff --git a/cc/resources/bitmap_skpicture_content_layer_updater.cc b/cc/resources/bitmap_skpicture_content_layer_updater.cc
index 1a2ebee..48e67db 100644
--- a/cc/resources/bitmap_skpicture_content_layer_updater.cc
+++ b/cc/resources/bitmap_skpicture_content_layer_updater.cc
@@ -31,12 +31,7 @@ void BitmapSkPictureContentLayerUpdater::Resource::Update(
   bitmap_.setIsOpaque(updater_->layer_is_opaque());
   SkDevice device(bitmap_);
   SkCanvas canvas(&device);
-  base::TimeTicks paint_begin_time;
-  if (stats)
-    paint_begin_time = base::TimeTicks::Now();
   updater_->PaintContentsRect(&canvas, source_rect, stats);
-  if (stats)
-    stats->total_paint_time += base::TimeTicks::Now() - paint_begin_time;
 
   ResourceUpdate upload = ResourceUpdate::Create(
       texture(), &bitmap_, source_rect, source_rect, dest_offset);
diff --git a/cc/resources/content_layer_updater.cc b/cc/resources/content_layer_updater.cc
index 9607ec6..e267398 100644
--- a/cc/resources/content_layer_updater.cc
+++ b/cc/resources/content_layer_updater.cc
@@ -56,14 +56,7 @@ void ContentLayerUpdater::PaintContents(SkCanvas* canvas,
   canvas->clipRect(layer_sk_rect);
 
   gfx::RectF opaque_layer_rect;
-  base::TimeTicks paint_begin_time;
-  if (stats)
-    paint_begin_time = base::TimeTicks::Now();
   painter_->Paint(canvas, layer_rect, &opaque_layer_rect);
-  if (stats) {
-    stats->total_paint_time += base::TimeTicks::Now() - paint_begin_time;
-    stats->total_pixels_painted += content_rect.width() * content_rect.height();
-  }
   canvas->restore();
 
   gfx::RectF opaque_content_rect = gfx::ScaleRect(
diff --git a/cc/resources/picture.cc b/cc/resources/picture.cc
index e0c6630d..199f947 100644
--- a/cc/resources/picture.cc
+++ b/cc/resources/picture.cc
@@ -178,13 +178,13 @@ void Picture::Record(ContentLayerClient* painter,
   canvas->drawRect(layer_skrect, paint);
 
   gfx::RectF opaque_layer_rect;
-  base::TimeTicks begin_paint_time;
+  base::TimeTicks begin_record_time;
   if (stats)
-    begin_paint_time = base::TimeTicks::Now();
+    begin_record_time = base::TimeTicks::Now();
   painter->PaintContents(canvas, layer_rect_, &opaque_layer_rect);
   if (stats) {
-    stats->total_paint_time += base::TimeTicks::Now() - begin_paint_time;
-    stats->total_pixels_painted +=
+    stats->total_record_time += base::TimeTicks::Now() - begin_record_time;
+    stats->total_pixels_recorded +=
         layer_rect_.width() * layer_rect_.height();
   }
 
diff --git a/cc/resources/picture_pile_impl.cc b/cc/resources/picture_pile_impl.cc
index 6559f24..7db0ecf 100644
--- a/cc/resources/picture_pile_impl.cc
+++ b/cc/resources/picture_pile_impl.cc
@@ -2,6 +2,9 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+#include <algorithm>
+#include <limits>
+
 #include "base/debug/trace_event.h"
 #include "cc/base/region.h"
 #include "cc/debug/debug_colors.h"
@@ -71,10 +74,11 @@ PicturePileImpl* PicturePileImpl::GetCloneForDrawingOnThread(
   return clones_for_drawing_.clones_[thread_index];
 }
 
-int64 PicturePileImpl::Raster(
+void PicturePileImpl::Raster(
     SkCanvas* canvas,
     gfx::Rect canvas_rect,
-    float contents_scale) {
+    float contents_scale,
+    RasterStats* raster_stats) {
 
   DCHECK(contents_scale >= min_contents_scale_);
 
@@ -120,7 +124,12 @@ int64 PicturePileImpl::Raster(
                    SkRegion::kReplace_Op);
   Region unclipped(content_rect);
 
-  int64 total_pixels_rasterized = 0;
+  if (raster_stats) {
+    raster_stats->total_pixels_rasterized = 0;
+    raster_stats->total_rasterize_time = base::TimeDelta::FromSeconds(0);
+    raster_stats->best_rasterize_time = base::TimeDelta::FromSeconds(0);
+  }
+
   for (TilingData::Iterator tile_iter(&tiling_, layer_rect);
        tile_iter; ++tile_iter) {
     PictureListMap::iterator map_iter =
@@ -146,11 +155,33 @@ int64 PicturePileImpl::Raster(
       if (!unclipped.Intersects(content_clip))
         continue;
 
-      if (slow_down_raster_scale_factor_for_debug_) {
-        for (int j = 0; j < slow_down_raster_scale_factor_for_debug_; ++j)
-          (*i)->Raster(canvas, content_clip, contents_scale, enable_lcd_text_);
-      } else {
+      base::TimeDelta total_duration =
+          base::TimeDelta::FromInternalValue(0);
+      base::TimeDelta best_duration =
+          base::TimeDelta::FromInternalValue(std::numeric_limits<int64>::max());
+      int repeat_count = std::max(1, slow_down_raster_scale_factor_for_debug_);
+
+      for (int j = 0; j < repeat_count; ++j) {
+        base::TimeTicks start_time;
+        if (raster_stats)
+          start_time = base::TimeTicks::HighResNow();
+
         (*i)->Raster(canvas, content_clip, contents_scale, enable_lcd_text_);
+
+        if (raster_stats) {
+          base::TimeDelta duration = base::TimeTicks::HighResNow() - start_time;
+          total_duration += duration;
+          best_duration = std::min(best_duration, duration);
+        }
+      }
+
+      if (raster_stats) {
+        gfx::Rect raster_rect = canvas_rect;
+        raster_rect.Intersect(content_clip);
+        raster_stats->total_pixels_rasterized +=
+            repeat_count * raster_rect.width() * raster_rect.height();
+        raster_stats->total_rasterize_time += total_duration;
+        raster_stats->best_rasterize_time += best_duration;
       }
 
       if (show_debug_picture_borders_) {
@@ -174,9 +205,6 @@ int64 PicturePileImpl::Raster(
           gfx::RectToSkRect(content_clip),
           SkRegion::kDifference_Op);
       unclipped.Subtract(content_clip);
-
-      total_pixels_rasterized +=
-          content_clip.width() * content_clip.height();
     }
   }
 
@@ -194,8 +222,6 @@ int64 PicturePileImpl::Raster(
   DCHECK(!unclipped.Contains(content_rect));
 
   canvas->restore();
-
-  return total_pixels_rasterized;
 }
 
 skia::RefPtr<SkPicture> PicturePileImpl::GetFlattenedPicture() {
@@ -211,7 +237,7 @@ skia::RefPtr<SkPicture> PicturePileImpl::GetFlattenedPicture() {
       layer_rect.height(),
       SkPicture::kUsePathBoundsForClip_RecordingFlag);
 
-  Raster(canvas, layer_rect, 1.0);
+  Raster(canvas, layer_rect, 1.0, NULL);
   picture->endRecording();
 
   return picture;
@@ -233,7 +259,7 @@ void PicturePileImpl::AnalyzeInRect(gfx::Rect content_rect,
   skia::AnalysisDevice device(empty_bitmap);
   skia::AnalysisCanvas canvas(&device);
 
-  Raster(&canvas, content_rect, contents_scale);
+  Raster(&canvas, content_rect, contents_scale, NULL);
 
   analysis->is_transparent = canvas.isTransparent();
   analysis->is_solid_color = canvas.getColorIfSolid(&analysis->solid_color);
diff --git a/cc/resources/picture_pile_impl.h b/cc/resources/picture_pile_impl.h
index d151bf3..d1ad2de 100644
--- a/cc/resources/picture_pile_impl.h
+++ b/cc/resources/picture_pile_impl.h
@@ -9,6 +9,7 @@
 #include <map>
 #include <vector>
 
+#include "base/time.h"
 #include "cc/base/cc_export.h"
 #include "cc/resources/picture_pile_base.h"
 #include "skia/ext/analysis_canvas.h"
@@ -28,14 +29,29 @@ class CC_EXPORT PicturePileImpl : public PicturePileBase {
   // Get paint-safe version of this picture for a specific thread.
   PicturePileImpl* GetCloneForDrawingOnThread(unsigned thread_index) const;
 
+  struct CC_EXPORT RasterStats {
+    // Minimum rasterize time from N runs
+    // N=max(1,slow-down-raster-scale-factor)
+    base::TimeDelta best_rasterize_time;
+    // Total rasterize time for all N runs
+    base::TimeDelta total_rasterize_time;
+    // Total number of pixels rasterize in all N runs
+    int64 total_pixels_rasterized;
+  };
+
   // Raster a subrect of this PicturePileImpl into the given canvas.
-  // It's only safe to call paint on a cloned version.
-  // It is assumed that contents_scale has already been applied to this canvas.
-  // Return value is the total number of pixels rasterized.
-  int64 Raster(
+  // It's only safe to call paint on a cloned version.  It is assumed
+  // that contents_scale has already been applied to this canvas.
+  // Writes the total number of pixels rasterized and the time spent
+  // rasterizing to the stats if the respective pointer is not
+  // NULL. When slow-down-raster-scale-factor is set to a value
+  // greater than 1, the reported rasterize time is the minimum
+  // measured value over all runs.
+  void Raster(
       SkCanvas* canvas,
       gfx::Rect canvas_rect,
-      float contents_scale);
+      float contents_scale,
+      RasterStats* raster_stats);
 
   skia::RefPtr<SkPicture> GetFlattenedPicture();
 
diff --git a/cc/resources/skpicture_content_layer_updater.cc b/cc/resources/skpicture_content_layer_updater.cc
index 4276a1e..5010aa9 100644
--- a/cc/resources/skpicture_content_layer_updater.cc
+++ b/cc/resources/skpicture_content_layer_updater.cc
@@ -5,6 +5,7 @@
 #include "cc/resources/skpicture_content_layer_updater.h"
 
 #include "base/debug/trace_event.h"
+#include "cc/debug/rendering_stats.h"
 #include "cc/resources/layer_painter.h"
 #include "cc/resources/prioritized_resource.h"
 #include "cc/resources/resource_update_queue.h"
@@ -59,12 +60,21 @@ void SkPictureContentLayerUpdater::PrepareToUpdate(
     RenderingStats* stats) {
   SkCanvas* canvas =
       picture_.beginRecording(content_rect.width(), content_rect.height());
+  base::TimeTicks record_start_time;
+  if (stats)
+    record_start_time = base::TimeTicks::HighResNow();
   PaintContents(canvas,
                 content_rect,
                 contents_width_scale,
                 contents_height_scale,
                 resulting_opaque_rect,
                 stats);
+  if (stats) {
+    stats->total_record_time +=
+        base::TimeTicks::HighResNow() - record_start_time;
+    stats->total_pixels_recorded +=
+        content_rect.width() * content_rect.height();
+  }
   picture_.endRecording();
 }
 
diff --git a/cc/resources/tile_manager.cc b/cc/resources/tile_manager.cc
index 3fe431d..b0c54c8 100644
--- a/cc/resources/tile_manager.cc
+++ b/cc/resources/tile_manager.cc
@@ -925,20 +925,16 @@ void TileManager::RunRasterTask(
   SkDevice device(bitmap);
   SkCanvas canvas(&device);
 
-  base::TimeTicks start_time = stats_instrumentation->StartRecording();
-
-  int64 total_pixels_rasterized =
-      picture_pile->Raster(&canvas, rect, contents_scale);
-
-  base::TimeDelta duration = stats_instrumentation->EndRecording(start_time);
-
   if (stats_instrumentation->record_rendering_stats()) {
-    stats_instrumentation->AddRaster(duration,
-                                     total_pixels_rasterized,
+    PicturePileImpl::RasterStats raster_stats;
+    picture_pile->Raster(&canvas, rect, contents_scale, &raster_stats);
+    stats_instrumentation->AddRaster(raster_stats.total_rasterize_time,
+                                     raster_stats.best_rasterize_time,
+                                     raster_stats.total_pixels_rasterized,
                                      metadata.is_tile_in_pending_tree_now_bin);
 
     HISTOGRAM_CUSTOM_COUNTS("Renderer4.PictureRasterTimeUS",
-                            duration.InMicroseconds(),
+                            raster_stats.total_rasterize_time.InMicroseconds(),
                             0,
                             100000,
                             100);
@@ -947,7 +943,8 @@ void TileManager::RunRasterTask(
       PicturePileImpl::Analysis analysis;
       picture_pile->AnalyzeInRect(rect, contents_scale, &analysis);
       bool is_predicted_cheap = analysis.is_cheap_to_raster;
-      bool is_actually_cheap = duration.InMillisecondsF() <= 1.0f;
+      bool is_actually_cheap =
+          raster_stats.best_rasterize_time.InMillisecondsF() <= 1.0f;
       RecordCheapnessPredictorResults(is_predicted_cheap, is_actually_cheap);
 
       DCHECK_EQ(bitmap.rowBytes(),
@@ -960,6 +957,8 @@ void TileManager::RunRasterTask(
           analysis.solid_color,
           analysis.is_transparent);
     }
+  } else {
+    picture_pile->Raster(&canvas, rect, contents_scale, NULL);
   }
 }
 
diff --git a/cc/trees/layer_tree_host_impl.cc b/cc/trees/layer_tree_host_impl.cc
index d05f610..d2944ee 100644
--- a/cc/trees/layer_tree_host_impl.cc
+++ b/cc/trees/layer_tree_host_impl.cc
@@ -1312,7 +1312,7 @@ void LayerTreeHostImpl::ActivatePendingTree() {
     const RenderingStats& stats =
         rendering_stats_instrumentation_->GetRenderingStats();
     paint_time_counter_->SavePaintTime(
-        stats.total_paint_time +
+        stats.total_paint_time + stats.total_record_time +
             stats.total_rasterize_time_for_now_bins_on_pending_tree);
   }
 }