Add RasterCache metrics to the FrameTimings (flutter#28439)

common/settings.h

@@ -37,17 +37,36 @@ class FrameTiming {
       kVsyncStart,  kBuildStart,   kBuildFinish,
       kRasterStart, kRasterFinish, kRasterFinishWallTime};
 
+  static constexpr int kStatisticsCount = kCount + 5;
+
   fml::TimePoint Get(Phase phase) const { return data_[phase]; }
   fml::TimePoint Set(Phase phase, fml::TimePoint value) {
     return data_[phase] = value;
   }
 
   uint64_t GetFrameNumber() const { return frame_number_; }
   void SetFrameNumber(uint64_t frame_number) { frame_number_ = frame_number; }
+  uint64_t GetLayerCacheCount() const { return layer_cache_count_; }
+  uint64_t GetLayerCacheBytes() const { return layer_cache_bytes_; }
+  uint64_t GetPictureCacheCount() const { return picture_cache_count_; }
+  uint64_t GetPictureCacheBytes() const { return picture_cache_bytes_; }
+  void SetRasterCacheStatistics(size_t layer_cache_count,
+                                size_t layer_cache_bytes,
+                                size_t picture_cache_count,
+                                size_t picture_cache_bytes) {
+    layer_cache_count_ = layer_cache_count;
+    layer_cache_bytes_ = layer_cache_bytes;
+    picture_cache_count_ = picture_cache_count;
+    picture_cache_bytes_ = picture_cache_bytes;
+  }
 
  private:
   fml::TimePoint data_[kCount];
   uint64_t frame_number_;
+  size_t layer_cache_count_;
+  size_t layer_cache_bytes_;
+  size_t picture_cache_count_;
+  size_t picture_cache_bytes_;
 };
 
 using TaskObserverAdd =

flow/frame_timings.cc

@@ -79,6 +79,34 @@ fml::TimeDelta FrameTimingsRecorder::GetBuildDuration() const {
   return build_end_ - build_start_;
 }
 
+/// Count of the layer cache entries
+size_t FrameTimingsRecorder::GetLayerCacheCount() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterEnd);
+  return layer_cache_count_;
+}
+
+/// Total bytes in all layer cache entries
+size_t FrameTimingsRecorder::GetLayerCacheBytes() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterEnd);
+  return layer_cache_bytes_;
+}
+
+/// Count of the picture cache entries
+size_t FrameTimingsRecorder::GetPictureCacheCount() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterEnd);
+  return picture_cache_count_;
+}
+
+/// Total bytes in all picture cache entries
+size_t FrameTimingsRecorder::GetPictureCacheBytes() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterEnd);
+  return picture_cache_bytes_;
+}
+
 void FrameTimingsRecorder::RecordVsync(fml::TimePoint vsync_start,
                                        fml::TimePoint vsync_target) {
   std::scoped_lock state_lock(state_mutex_);
@@ -102,26 +130,41 @@ void FrameTimingsRecorder::RecordBuildEnd(fml::TimePoint build_end) {
   build_end_ = build_end;
 }
 
-void FrameTimingsRecorder::RecordRasterStart(fml::TimePoint raster_start) {
+void FrameTimingsRecorder::RecordRasterStart(fml::TimePoint raster_start,
+                                             const RasterCache* cache) {
   std::scoped_lock state_lock(state_mutex_);
   FML_DCHECK(state_ == State::kBuildEnd);
   state_ = State::kRasterStart;
   raster_start_ = raster_start;
+  sweep_count_at_raster_start_ = cache ? cache->sweep_count() : -1;
 }
 
-FrameTiming FrameTimingsRecorder::RecordRasterEnd() {
+FrameTiming FrameTimingsRecorder::RecordRasterEnd(const RasterCache* cache) {
   std::scoped_lock state_lock(state_mutex_);
   FML_DCHECK(state_ == State::kRasterStart);
+  FML_DCHECK(sweep_count_at_raster_start_ ==
+             (cache ? cache->sweep_count() : -1));
   state_ = State::kRasterEnd;
   raster_end_ = fml::TimePoint::Now();
   raster_end_wall_time_ = fml::TimePoint::CurrentWallTime();
+  if (cache) {
+    layer_cache_count_ = cache->GetLayerCachedEntriesCount();
+    layer_cache_bytes_ = cache->EstimateLayerCacheByteSize();
+    picture_cache_count_ = cache->GetPictureCachedEntriesCount();
+    picture_cache_bytes_ = cache->EstimatePictureCacheByteSize();
+  } else {
+    layer_cache_count_ = layer_cache_bytes_ = picture_cache_count_ =
+        picture_cache_bytes_ = 0;
+  }
   timing_.Set(FrameTiming::kVsyncStart, vsync_start_);
   timing_.Set(FrameTiming::kBuildStart, build_start_);
   timing_.Set(FrameTiming::kBuildFinish, build_end_);
   timing_.Set(FrameTiming::kRasterStart, raster_start_);
   timing_.Set(FrameTiming::kRasterFinish, raster_end_);
   timing_.Set(FrameTiming::kRasterFinishWallTime, raster_end_wall_time_);
   timing_.SetFrameNumber(GetFrameNumber());
+  timing_.SetRasterCacheStatistics(layer_cache_count_, layer_cache_bytes_,
+                                   picture_cache_count_, picture_cache_bytes_);
   return timing_;
 }
 
@@ -154,11 +197,16 @@ std::unique_ptr<FrameTimingsRecorder> FrameTimingsRecorder::CloneUntil(
 
   if (state >= State::kRasterStart) {
     recorder->raster_start_ = raster_start_;
+    recorder->sweep_count_at_raster_start_ = sweep_count_at_raster_start_;
   }
 
   if (state >= State::kRasterEnd) {
     recorder->raster_end_ = raster_end_;
     recorder->raster_end_wall_time_ = raster_end_wall_time_;
+    recorder->layer_cache_count_ = layer_cache_count_;
+    recorder->layer_cache_bytes_ = layer_cache_bytes_;
+    recorder->picture_cache_count_ = picture_cache_count_;
+    recorder->picture_cache_bytes_ = picture_cache_bytes_;
   }
 
   return recorder;

flow/frame_timings.h

@@ -8,6 +8,7 @@
 #include <mutex>
 
 #include "flutter/common/settings.h"
+#include "flutter/flow/raster_cache.h"
 #include "flutter/fml/macros.h"
 #include "flutter/fml/time/time_delta.h"
 #include "flutter/fml/time/time_point.h"
@@ -70,6 +71,18 @@ class FrameTimingsRecorder {
   /// Duration of the frame build time.
   fml::TimeDelta GetBuildDuration() const;
 
+  /// Count of the layer cache entries
+  size_t GetLayerCacheCount() const;
+
+  /// Total Bytes in all layer cache entries
+  size_t GetLayerCacheBytes() const;
+
+  /// Count of the picture cache entries
+  size_t GetPictureCacheCount() const;
+
+  /// Total Bytes in all picture cache entries
+  size_t GetPictureCacheBytes() const;
+
   /// Records a vsync event.
   void RecordVsync(fml::TimePoint vsync_start, fml::TimePoint vsync_target);
 
@@ -80,14 +93,15 @@ class FrameTimingsRecorder {
   void RecordBuildEnd(fml::TimePoint build_end);
 
   /// Records a raster start event.
-  void RecordRasterStart(fml::TimePoint raster_start);
+  void RecordRasterStart(fml::TimePoint raster_start,
+                         const RasterCache* cache = nullptr);
 
   /// Clones the recorder until (and including) the specified state.
   std::unique_ptr<FrameTimingsRecorder> CloneUntil(State state);
 
   /// Records a raster end event, and builds a `FrameTiming` that summarizes all
   /// the events. This summary is sent to the framework.
-  FrameTiming RecordRasterEnd();
+  FrameTiming RecordRasterEnd(const RasterCache* cache = nullptr);
 
   /// Returns the frame number. Frame number is unique per frame and a frame
   /// built earlier will have a frame number less than a frame that has been
@@ -117,6 +131,12 @@ class FrameTimingsRecorder {
   fml::TimePoint raster_end_;
   fml::TimePoint raster_end_wall_time_;
 
+  int sweep_count_at_raster_start_;
+  size_t layer_cache_count_;
+  size_t layer_cache_bytes_;
+  size_t picture_cache_count_;
+  size_t picture_cache_bytes_;
+
   // Set when `RecordRasterEnd` is called. Cannot be reset once set.
   FrameTiming timing_;
 

flow/frame_timings_recorder_unittests.cc

@@ -3,6 +3,10 @@
 // found in the LICENSE file.
 
 #include "flutter/flow/frame_timings.h"
+#include "flutter/flow/testing/layer_test.h"
+#include "flutter/flow/testing/mock_layer.h"
+#include "flutter/flow/testing/mock_raster_cache.h"
+#include "third_party/skia/include/core/SkPictureRecorder.h"
 
 #include <thread>
 
@@ -66,12 +70,85 @@ TEST(FrameTimingsRecorderTest, RecordRasterTimes) {
   ASSERT_GT(recorder->GetRasterEndWallTime(), before_raster_end_wall_time);
   ASSERT_LT(recorder->GetRasterEndWallTime(), after_raster_end_wall_time);
   ASSERT_EQ(recorder->GetFrameNumber(), timing.GetFrameNumber());
+  ASSERT_EQ(recorder->GetLayerCacheCount(), 0u);
+  ASSERT_EQ(recorder->GetLayerCacheBytes(), 0u);
+  ASSERT_EQ(recorder->GetPictureCacheCount(), 0u);
+  ASSERT_EQ(recorder->GetPictureCacheBytes(), 0u);
+}
+
+TEST(FrameTimingsRecorderTest, RecordRasterTimesWithCache) {
+  auto recorder = std::make_unique<FrameTimingsRecorder>();
+
+  const auto st = fml::TimePoint::Now();
+  const auto en = st + fml::TimeDelta::FromMillisecondsF(16);
+  recorder->RecordVsync(st, en);
+
+  const auto build_start = fml::TimePoint::Now();
+  const auto build_end = build_start + fml::TimeDelta::FromMillisecondsF(16);
+  recorder->RecordBuildStart(build_start);
+  recorder->RecordBuildEnd(build_end);
+
+  using namespace std::chrono_literals;
+
+  MockRasterCache cache(1, 10);
+  cache.SweepAfterFrame();
+
+  const auto raster_start = fml::TimePoint::Now();
+  recorder->RecordRasterStart(raster_start, &cache);
+
+  cache.AddMockLayer(100, 100);
+  size_t layer_bytes = cache.EstimateLayerCacheByteSize();
+  EXPECT_GT(layer_bytes, 0u);
+  cache.AddMockPicture(100, 100);
+  size_t picture_bytes = cache.EstimatePictureCacheByteSize();
+  EXPECT_GT(picture_bytes, 0u);
+
+  const auto before_raster_end_wall_time = fml::TimePoint::CurrentWallTime();
+  std::this_thread::sleep_for(1ms);
+  const auto timing = recorder->RecordRasterEnd(&cache);
+  std::this_thread::sleep_for(1ms);
+  const auto after_raster_end_wall_time = fml::TimePoint::CurrentWallTime();
+
+  ASSERT_EQ(raster_start, recorder->GetRasterStartTime());
+  ASSERT_GT(recorder->GetRasterEndWallTime(), before_raster_end_wall_time);
+  ASSERT_LT(recorder->GetRasterEndWallTime(), after_raster_end_wall_time);
+  ASSERT_EQ(recorder->GetFrameNumber(), timing.GetFrameNumber());
+  ASSERT_EQ(recorder->GetLayerCacheCount(), 1u);
+  ASSERT_EQ(recorder->GetLayerCacheBytes(), layer_bytes);
+  ASSERT_EQ(recorder->GetPictureCacheCount(), 1u);
+  ASSERT_EQ(recorder->GetPictureCacheBytes(), picture_bytes);
 }
 
 // Windows and Fuchsia don't allow testing with killed by signal.
 #if !defined(OS_FUCHSIA) && !defined(OS_WIN) && \
     (FLUTTER_RUNTIME_MODE == FLUTTER_RUNTIME_MODE_DEBUG)
 
+TEST(FrameTimingsRecorderTest, ThrowAfterUnexpectedCacheSweep) {
+  auto recorder = std::make_unique<FrameTimingsRecorder>();
+
+  const auto st = fml::TimePoint::Now();
+  const auto en = st + fml::TimeDelta::FromMillisecondsF(16);
+  recorder->RecordVsync(st, en);
+
+  const auto build_start = fml::TimePoint::Now();
+  const auto build_end = build_start + fml::TimeDelta::FromMillisecondsF(16);
+  recorder->RecordBuildStart(build_start);
+  recorder->RecordBuildEnd(build_end);
+
+  using namespace std::chrono_literals;
+
+  MockRasterCache cache;
+
+  const auto raster_start = fml::TimePoint::Now();
+  recorder->RecordRasterStart(raster_start, &cache);
+  std::this_thread::sleep_for(1ms);
+  cache.SweepAfterFrame();
+  EXPECT_EXIT(recorder->RecordRasterEnd(&cache),
+              ::testing::KilledBySignal(SIGABRT),
+              "Check failed: sweep_count_at_raster_start_ == \\(cache \\? "
+              "cache->sweep_count\\(\\) : -1\\).");
+}
+
 TEST(FrameTimingsRecorderTest, ThrowWhenRecordBuildBeforeVsync) {
   auto recorder = std::make_unique<FrameTimingsRecorder>();
 
@@ -190,6 +267,45 @@ TEST(FrameTimingsRecorderTest, ClonedHasSameRasterEnd) {
   ASSERT_EQ(recorder->GetRasterStartTime(), cloned->GetRasterStartTime());
   ASSERT_EQ(recorder->GetRasterEndTime(), cloned->GetRasterEndTime());
   ASSERT_EQ(recorder->GetRasterEndWallTime(), cloned->GetRasterEndWallTime());
+  ASSERT_EQ(recorder->GetLayerCacheCount(), cloned->GetLayerCacheCount());
+  ASSERT_EQ(recorder->GetLayerCacheBytes(), cloned->GetLayerCacheBytes());
+  ASSERT_EQ(recorder->GetPictureCacheCount(), cloned->GetPictureCacheCount());
+  ASSERT_EQ(recorder->GetPictureCacheBytes(), cloned->GetPictureCacheBytes());
+}
+
+TEST(FrameTimingsRecorderTest, ClonedHasSameRasterEndWithCache) {
+  auto recorder = std::make_unique<FrameTimingsRecorder>();
+  MockRasterCache cache(1, 10);
+  cache.SweepAfterFrame();
+
+  const auto now = fml::TimePoint::Now();
+  recorder->RecordVsync(now, now + fml::TimeDelta::FromMilliseconds(16));
+  recorder->RecordBuildStart(fml::TimePoint::Now());
+  recorder->RecordBuildEnd(fml::TimePoint::Now());
+  recorder->RecordRasterStart(fml::TimePoint::Now(), &cache);
+
+  cache.AddMockLayer(100, 100);
+  size_t layer_bytes = cache.EstimateLayerCacheByteSize();
+  EXPECT_GT(layer_bytes, 0u);
+  cache.AddMockPicture(100, 100);
+  size_t picture_bytes = cache.EstimatePictureCacheByteSize();
+  EXPECT_GT(picture_bytes, 0u);
+
+  recorder->RecordRasterEnd(&cache);
+
+  auto cloned = recorder->CloneUntil(FrameTimingsRecorder::State::kRasterEnd);
+  ASSERT_EQ(recorder->GetFrameNumber(), cloned->GetFrameNumber());
+  ASSERT_EQ(recorder->GetVsyncStartTime(), cloned->GetVsyncStartTime());
+  ASSERT_EQ(recorder->GetVsyncTargetTime(), cloned->GetVsyncTargetTime());
+  ASSERT_EQ(recorder->GetBuildStartTime(), cloned->GetBuildStartTime());
+  ASSERT_EQ(recorder->GetBuildEndTime(), cloned->GetBuildEndTime());
+  ASSERT_EQ(recorder->GetRasterStartTime(), cloned->GetRasterStartTime());
+  ASSERT_EQ(recorder->GetRasterEndTime(), cloned->GetRasterEndTime());
+  ASSERT_EQ(recorder->GetRasterEndWallTime(), cloned->GetRasterEndWallTime());
+  ASSERT_EQ(recorder->GetLayerCacheCount(), cloned->GetLayerCacheCount());
+  ASSERT_EQ(recorder->GetLayerCacheBytes(), cloned->GetLayerCacheBytes());
+  ASSERT_EQ(recorder->GetPictureCacheCount(), cloned->GetPictureCacheCount());
+  ASSERT_EQ(recorder->GetPictureCacheBytes(), cloned->GetPictureCacheBytes());
 }
 
 TEST(FrameTimingsRecorderTest, FrameNumberTraceArgIsValid) {

flow/raster_cache.cc

@@ -390,11 +390,12 @@ bool RasterCache::Draw(const Layer* layer,
 }
 
 void RasterCache::SweepAfterFrame() {
+  TraceStatsToTimeline();
   SweepOneCacheAfterFrame(picture_cache_);
   SweepOneCacheAfterFrame(display_list_cache_);
   SweepOneCacheAfterFrame(layer_cache_);
   picture_cached_this_frame_ = 0;
-  TraceStatsToTimeline();
+  sweep_count_++;
 }
 
 void RasterCache::Clear() {

flow/raster_cache.h

@@ -207,6 +207,25 @@ class RasterCache {
    */
   size_t EstimateLayerCacheByteSize() const;
 
+  /**
+   * @brief Return the count of cache sweeps that have occured.
+   *
+   * The sweep count will help to determine if a sweep of the cache may have
+   * removed expired entries since the last time the method was called.
+   * The count will increment even if the sweep performs no evictions.
+   */
+  int sweep_count() const { return sweep_count_; }
+
+  /**
+   * @brief Return the number of frames that a picture must be prepared
+   * before it will be cached. If the number is 0, then no picture will
+   * ever be cached.
+   *
+   * If the number is one, then it must be prepared and drawn on 1 frame
+   * and it will then be cached on the next frame if it is prepared.
+   */
+  int access_threshold() const { return access_threshold_; }
+
  private:
   struct Entry {
     bool used_this_frame = false;
@@ -234,6 +253,7 @@ class RasterCache {
   const size_t access_threshold_;
   const size_t picture_cache_limit_per_frame_;
   size_t picture_cached_this_frame_ = 0;
+  int sweep_count_ = 0;
   mutable PictureRasterCacheKey::Map<Entry> picture_cache_;
   mutable DisplayListRasterCacheKey::Map<Entry> display_list_cache_;
   mutable LayerRasterCacheKey::Map<Entry> layer_cache_;