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

8 files changed, 92 insertions, 51 deletions

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);
   }
 }