Streamline frame timings recording (flutter#25892)

ci/firebase_testlab.sh

@@ -32,4 +32,4 @@ gcloud --project flutter-infra firebase test android run \
   --timeout 2m \
   --results-bucket=gs://flutter_firebase_testlab \
   --results-dir="engine_scenario_test/$GIT_REVISION/$BUILD_ID" \
-  --device model=flame,version=29 
+  --device model=flame,version=29

ci/licenses_golden/licenses_flutter

@@ -42,6 +42,9 @@ FILE: ../../../flutter/flow/embedded_views.h
 FILE: ../../../flutter/flow/flow_run_all_unittests.cc
 FILE: ../../../flutter/flow/flow_test_utils.cc
 FILE: ../../../flutter/flow/flow_test_utils.h
+FILE: ../../../flutter/flow/frame_timings.cc
+FILE: ../../../flutter/flow/frame_timings.h
+FILE: ../../../flutter/flow/frame_timings_recorder_unittests.cc
 FILE: ../../../flutter/flow/gl_context_switch_unittests.cc
 FILE: ../../../flutter/flow/instrumentation.cc
 FILE: ../../../flutter/flow/instrumentation.h

flow/BUILD.gn

@@ -14,6 +14,8 @@ source_set("flow") {
     "diff_context.h",
     "embedded_views.cc",
     "embedded_views.h",
+    "frame_timings.cc",
+    "frame_timings.h",
     "instrumentation.cc",
     "instrumentation.h",
     "layers/backdrop_filter_layer.cc",
@@ -143,6 +145,7 @@ if (enable_unittests) {
       "flow_run_all_unittests.cc",
       "flow_test_utils.cc",
       "flow_test_utils.h",
+      "frame_timings_recorder_unittests.cc",
       "gl_context_switch_unittests.cc",
       "layers/backdrop_filter_layer_unittests.cc",
       "layers/checkerboard_layertree_unittests.cc",

flow/frame_timings.cc

@@ -0,0 +1,135 @@
+// Copyright 2013 The Flutter Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "flutter/flow/frame_timings.h"
+
+#include <memory>
+
+#include "flutter/common/settings.h"
+#include "flutter/fml/logging.h"
+
+namespace flutter {
+
+FrameTimingsRecorder::FrameTimingsRecorder() = default;
+
+FrameTimingsRecorder::~FrameTimingsRecorder() = default;
+
+fml::TimePoint FrameTimingsRecorder::GetVsyncStartTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kVsync);
+  return vsync_start_;
+}
+
+fml::TimePoint FrameTimingsRecorder::GetVsyncTargetTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kVsync);
+  return vsync_target_;
+}
+
+fml::TimePoint FrameTimingsRecorder::GetBuildStartTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kBuildStart);
+  return build_start_;
+}
+
+fml::TimePoint FrameTimingsRecorder::GetBuildEndTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kBuildEnd);
+  return build_end_;
+}
+
+fml::TimePoint FrameTimingsRecorder::GetRasterStartTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterStart);
+  return raster_start_;
+}
+
+fml::TimePoint FrameTimingsRecorder::GetRasterEndTime() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kRasterEnd);
+  return raster_end_;
+}
+
+fml::TimeDelta FrameTimingsRecorder::GetBuildDuration() const {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ >= State::kBuildEnd);
+  return build_end_ - build_start_;
+}
+
+void FrameTimingsRecorder::RecordVsync(fml::TimePoint vsync_start,
+                                       fml::TimePoint vsync_target) {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ == State::kUninitialized);
+  state_ = State::kVsync;
+  vsync_start_ = vsync_start;
+  vsync_target_ = vsync_target;
+}
+
+void FrameTimingsRecorder::RecordBuildStart(fml::TimePoint build_start) {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ == State::kVsync);
+  state_ = State::kBuildStart;
+  build_start_ = build_start;
+}
+
+void FrameTimingsRecorder::RecordBuildEnd(fml::TimePoint build_end) {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ == State::kBuildStart);
+  state_ = State::kBuildEnd;
+  build_end_ = build_end;
+}
+
+void FrameTimingsRecorder::RecordRasterStart(fml::TimePoint raster_start) {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ == State::kBuildEnd);
+  state_ = State::kRasterStart;
+  raster_start_ = raster_start;
+}
+
+FrameTiming FrameTimingsRecorder::RecordRasterEnd(fml::TimePoint raster_end) {
+  std::scoped_lock state_lock(state_mutex_);
+  FML_DCHECK(state_ == State::kRasterStart);
+  state_ = State::kRasterEnd;
+  raster_end_ = raster_end;
+  FrameTiming timing;
+  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_);
+  return timing;
+}
+
+std::unique_ptr<FrameTimingsRecorder> FrameTimingsRecorder::CloneUntil(
+    State state) {
+  std::scoped_lock state_lock(state_mutex_);
+  std::unique_ptr<FrameTimingsRecorder> recorder =
+      std::make_unique<FrameTimingsRecorder>();
+  recorder->state_ = state;
+
+  if (state >= State::kVsync) {
+    recorder->vsync_start_ = vsync_start_;
+    recorder->vsync_target_ = vsync_target_;
+  }
+
+  if (state >= State::kBuildStart) {
+    recorder->build_start_ = build_start_;
+  }
+
+  if (state >= State::kRasterEnd) {
+    recorder->build_end_ = build_end_;
+  }
+
+  if (state >= State::kRasterStart) {
+    recorder->raster_start_ = raster_start_;
+  }
+
+  if (state >= State::kRasterEnd) {
+    recorder->raster_end_ = raster_end_;
+  }
+
+  return recorder;
+}
+
+}  // namespace flutter

flow/frame_timings.h

@@ -0,0 +1,98 @@
+// Copyright 2013 The Flutter 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 FLUTTER_FLOW_FRAME_TIMINGS_H_
+#define FLUTTER_FLOW_FRAME_TIMINGS_H_
+
+#include <mutex>
+
+#include "flutter/common/settings.h"
+#include "flutter/fml/macros.h"
+#include "flutter/fml/time/time_delta.h"
+#include "flutter/fml/time/time_point.h"
+
+namespace flutter {
+
+/// Records timestamps for various phases of a frame rendering process.
+///
+/// Recorder is created on vsync and destroyed after the rasterization of the
+/// frame. This class is thread safe and doesn't require additional
+/// synchronization.
+class FrameTimingsRecorder {
+ public:
+  /// Various states that the recorder can be in. When created the recorder is
+  /// in an unitialized state and transtions in sequential order of the states.
+  enum class State : uint32_t {
+    kUninitialized,
+    kVsync,
+    kBuildStart,
+    kBuildEnd,
+    kRasterStart,
+    kRasterEnd,
+  };
+
+  /// Default constructor, initializes the recorder with State::kUninitialized.
+  FrameTimingsRecorder();
+
+  ~FrameTimingsRecorder();
+
+  /// Timestamp of the vsync signal.
+  fml::TimePoint GetVsyncStartTime() const;
+
+  /// Timestamp of when the frame was targeted to be presented.
+  ///
+  /// This is typically the next vsync signal timestamp.
+  fml::TimePoint GetVsyncTargetTime() const;
+
+  /// Timestamp of when the frame building started.
+  fml::TimePoint GetBuildStartTime() const;
+
+  /// Timestamp of when the frame was finished building.
+  fml::TimePoint GetBuildEndTime() const;
+
+  /// Timestamp of when the frame rasterization started.
+  fml::TimePoint GetRasterStartTime() const;
+
+  /// Timestamp of when the frame rasterization finished.
+  fml::TimePoint GetRasterEndTime() const;
+
+  /// Duration of the frame build time.
+  fml::TimeDelta GetBuildDuration() const;
+
+  /// Records a vsync event.
+  void RecordVsync(fml::TimePoint vsync_start, fml::TimePoint vsync_target);
+
+  /// Records a build start event.
+  void RecordBuildStart(fml::TimePoint build_start);
+
+  /// Records a build end event.
+  void RecordBuildEnd(fml::TimePoint build_end);
+
+  /// Records a raster start event.
+  void RecordRasterStart(fml::TimePoint raster_start);
+
+  /// 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(fml::TimePoint raster_end);
+
+ private:
+  mutable std::mutex state_mutex_;
+  State state_ = State::kUninitialized;
+
+  fml::TimePoint vsync_start_;
+  fml::TimePoint vsync_target_;
+  fml::TimePoint build_start_;
+  fml::TimePoint build_end_;
+  fml::TimePoint raster_start_;
+  fml::TimePoint raster_end_;
+
+  FML_DISALLOW_COPY_ASSIGN_AND_MOVE(FrameTimingsRecorder);
+};
+
+}  // namespace flutter
+
+#endif  // FLUTTER_FLOW_FRAME_TIMINGS_H_

flow/frame_timings_recorder_unittests.cc

@@ -0,0 +1,91 @@
+// Copyright 2013 The Flutter Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "flutter/flow/frame_timings.h"
+
+#include "flutter/fml/time/time_delta.h"
+#include "flutter/fml/time/time_point.h"
+
+#include "gtest/gtest.h"
+
+namespace flutter {
+namespace testing {
+
+TEST(FrameTimingsRecorderTest, RecordVsync) {
+  auto recorder = std::make_unique<FrameTimingsRecorder>();
+  const auto st = fml::TimePoint::Now();
+  const auto en = st + fml::TimeDelta::FromMillisecondsF(16);
+  recorder->RecordVsync(st, en);
+
+  ASSERT_EQ(st, recorder->GetVsyncStartTime());
+  ASSERT_EQ(en, recorder->GetVsyncTargetTime());
+}
+
+TEST(FrameTimingsRecorderTest, RecordBuildTimes) {
+  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);
+
+  ASSERT_EQ(build_start, recorder->GetBuildStartTime());
+  ASSERT_EQ(build_end, recorder->GetBuildEndTime());
+}
+
+TEST(FrameTimingsRecorderTest, RecordRasterTimes) {
+  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);
+
+  const auto raster_start = fml::TimePoint::Now();
+  const auto raster_end = raster_start + fml::TimeDelta::FromMillisecondsF(16);
+  recorder->RecordRasterStart(raster_start);
+  recorder->RecordRasterEnd(raster_end);
+
+  ASSERT_EQ(raster_start, recorder->GetRasterStartTime());
+  ASSERT_EQ(raster_end, recorder->GetRasterEndTime());
+}
+
+// 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, ThrowWhenRecordBuildBeforeVsync) {
+  auto recorder = std::make_unique<FrameTimingsRecorder>();
+
+  const auto build_start = fml::TimePoint::Now();
+  EXPECT_EXIT(recorder->RecordBuildStart(build_start),
+              ::testing::KilledBySignal(SIGABRT),
+              "Check failed: state_ == State::kVsync.");
+}
+
+TEST(FrameTimingsRecorderTest, ThrowWhenRecordRasterBeforeBuildEnd) {
+  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 raster_start = fml::TimePoint::Now();
+  EXPECT_EXIT(recorder->RecordRasterStart(raster_start),
+              ::testing::KilledBySignal(SIGABRT),
+              "Check failed: state_ == State::kBuildEnd.");
+}
+
+#endif
+
+}  // namespace testing
+}  // namespace flutter

flow/layers/layer_tree.cc

@@ -4,7 +4,9 @@
 
 #include "flutter/flow/layers/layer_tree.h"
 
+#include "flutter/flow/frame_timings.h"
 #include "flutter/flow/layers/layer.h"
+#include "flutter/fml/time/time_point.h"
 #include "flutter/fml/trace_event.h"
 #include "third_party/skia/include/core/SkPictureRecorder.h"
 #include "third_party/skia/include/utils/SkNWayCanvas.h"
@@ -20,15 +22,6 @@ LayerTree::LayerTree(const SkISize& frame_size, float device_pixel_ratio)
   FML_CHECK(device_pixel_ratio_ != 0.0f);
 }
 
-void LayerTree::RecordBuildTime(fml::TimePoint vsync_start,
-                                fml::TimePoint build_start,
-                                fml::TimePoint target_time) {
-  vsync_start_ = vsync_start;
-  build_start_ = build_start;
-  target_time_ = target_time;
-  build_finish_ = fml::TimePoint::Now();
-}
-
 bool LayerTree::Preroll(CompositorContext::ScopedFrame& frame,
                         bool ignore_raster_cache) {
   TRACE_EVENT0("flutter", "LayerTree::Preroll");