DEV/flutter_flutter
1
0
Fork 0
mirror of https://github.com/flutter/flutter.git synced 2026-02-20 02:29:02 +08:00
Code Issues Packages Projects Releases Wiki Activity

[pipeline] Add trace event for lag between target and display times (flutter/engine#17384)

Browse Source 
This change also adds TimeRecorder which records time at the start
of each frame to capture the latest vsync target display time and
wires it in to the rasterizer to add trace events when there is a lag.
This commit is contained in:
Kaushik Iska 2020-04-02 17:15:45 -07:00 committed by GitHub
parent f1a58638ad
commit ce0ec9042f
11 changed files with 147 additions and 37 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
engine/src/flutter/fml/time/time_delta.h
View File

@ -55,6 +55,10 @@ class TimeDelta {
return FromNanoseconds(seconds * (1000.0 * 1000.0 * 1000.0));
}
static constexpr TimeDelta FromMillisecondsF(double millis) {
return FromNanoseconds(millis * (1000.0 * 1000.0));
}
constexpr int64_t ToNanoseconds() const { return delta_; }
constexpr int64_t ToMicroseconds() const { return ToNanoseconds() / 1000; }
constexpr int64_t ToMilliseconds() const { return ToMicroseconds() / 1000; }

55
engine/src/flutter/fml/trace_event.cc
View File

@ -51,6 +51,7 @@ size_t TraceNonce() {
void TraceTimelineEvent(TraceArg category_group,
TraceArg name,
int64_t timestamp_micros,
TraceIDArg identifier,
Dart_Timeline_Event_Type type,
const std::vector<const char*>& c_names,
@ -66,7 +67,7 @@ void TraceTimelineEvent(TraceArg category_group,
FlutterTimelineEvent(
name, // label
Dart_TimelineGetMicros(), // timestamp0
timestamp_micros, // timestamp0
identifier, // timestamp1_or_async_id
type, // event type
argument_count, // argument_count
@ -75,6 +76,22 @@ void TraceTimelineEvent(TraceArg category_group,
);
}
void TraceTimelineEvent(TraceArg category_group,
TraceArg name,
TraceIDArg identifier,
Dart_Timeline_Event_Type type,
const std::vector<const char*>& c_names,
const std::vector<std::string>& values) {
TraceTimelineEvent(category_group, // group
name, // name
Dart_TimelineGetMicros(), // timestamp_micros
identifier, // identifier
type, // type
c_names, // names
values // values
);
}
void TraceEvent0(TraceArg category_group, TraceArg name) {
FlutterTimelineEvent(name, // label
Dart_TimelineGetMicros(), // timestamp0
@ -131,34 +148,6 @@ void TraceEventEnd(TraceArg name) {
);
}
void TraceEventAsyncComplete(TraceArg category_group,
TraceArg name,
TimePoint begin,
TimePoint end) {
auto identifier = TraceNonce();
if (begin > end) {
std::swap(begin, end);
}
FlutterTimelineEvent(name, // label
begin.ToEpochDelta().ToMicroseconds(), // timestamp0
identifier, // timestamp1_or_async_id
Dart_Timeline_Event_Async_Begin, // event type
0, // argument_count
nullptr, // argument_names
nullptr // argument_values
);
FlutterTimelineEvent(name, // label
end.ToEpochDelta().ToMicroseconds(), // timestamp0
identifier, // timestamp1_or_async_id
Dart_Timeline_Event_Async_End, // event type
0, // argument_count
nullptr, // argument_names
nullptr // argument_values
);
}
void TraceEventAsyncBegin0(TraceArg category_group,
TraceArg name,
TraceIDArg id) {
@ -275,6 +264,14 @@ size_t TraceNonce() {
return 0;
}
void TraceTimelineEvent(TraceArg category_group,
TraceArg name,
int64_t timestamp_micros,
TraceIDArg identifier,
Dart_Timeline_Event_Type type,
const std::vector<const char*>& c_names,
const std::vector<std::string>& values) {}
void TraceTimelineEvent(TraceArg category_group,
TraceArg name,
TraceIDArg identifier,

40
engine/src/flutter/fml/trace_event.h
View File

@ -114,6 +114,14 @@ using TraceIDArg = int64_t;
void TraceSetWhitelist(const std::vector<std::string>& whitelist);
void TraceTimelineEvent(TraceArg category_group,
TraceArg name,
int64_t timestamp_micros,
TraceIDArg id,
Dart_Timeline_Event_Type type,
const std::vector<const char*>& names,
const std::vector<std::string>& values);
void TraceTimelineEvent(TraceArg category_group,
TraceArg name,
TraceIDArg id,
@ -209,10 +217,40 @@ void TraceEvent2(TraceArg category_group,
void TraceEventEnd(TraceArg name);
template <typename... Args>
void TraceEventAsyncComplete(TraceArg category_group,
TraceArg name,
TimePoint begin,
TimePoint end);
TimePoint end,
Args... args) {
auto identifier = TraceNonce();
const auto split = SplitArguments(args...);
if (begin > end) {
std::swap(begin, end);
}
const int64_t begin_micros = begin.ToEpochDelta().ToMicroseconds();
const int64_t end_micros = end.ToEpochDelta().ToMicroseconds();
TraceTimelineEvent(category_group, // group
name, // name
begin_micros, // timestamp_micros
identifier, // identifier
Dart_Timeline_Event_Async_Begin, // type
split.first, // names
split.second // values
);
TraceTimelineEvent(category_group, // group
name, // name
end_micros, // timestamp_micros
identifier, // identifier
Dart_Timeline_Event_Async_End, // type
split.first, // names
split.second // values
);
}
void TraceEventAsyncBegin0(TraceArg category_group,
TraceArg name,

2
engine/src/flutter/shell/common/animator.h
View File

@ -30,7 +30,7 @@ class Animator final {
public:
class Delegate {
public:
virtual void OnAnimatorBeginFrame(fml::TimePoint frame_time) = 0;
virtual void OnAnimatorBeginFrame(fml::TimePoint frame_target_time) = 0;
virtual void OnAnimatorNotifyIdle(int64_t deadline) = 0;

8
engine/src/flutter/shell/common/animator_unittests.cc
View File

@ -84,10 +84,14 @@ TEST_F(ShellTest, VSyncTargetTime) {
});
on_target_time_latch.Wait();
ASSERT_EQ(ConstantFiringVsyncWaiter::frame_target_time.ToEpochDelta()
.ToMicroseconds(),
const auto vsync_waiter_target_time =
ConstantFiringVsyncWaiter::frame_target_time;
ASSERT_EQ(vsync_waiter_target_time.ToEpochDelta().ToMicroseconds(),
target_time);
// validate that the latest target time has also been updated.
ASSERT_EQ(GetLatestFrameTargetTime(shell.get()), vsync_waiter_target_time);
// teardown.
DestroyShell(std::move(shell), std::move(task_runners));
ASSERT_FALSE(DartVMRef::IsInstanceRunning());

32
engine/src/flutter/shell/common/rasterizer.cc
View File

@ -8,6 +8,8 @@
#include <utility>
#include "fml/time/time_delta.h"
#include "fml/time/time_point.h"
#include "third_party/skia/include/core/SkEncodedImageFormat.h"
#include "third_party/skia/include/core/SkImageEncoder.h"
#include "third_party/skia/include/core/SkPictureRecorder.h"
@ -240,6 +242,7 @@ RasterStatus Rasterizer::DoDraw(
}
FrameTiming timing;
const fml::TimePoint frame_target_time = layer_tree->target_time();
timing.Set(FrameTiming::kBuildStart, layer_tree->build_start());
timing.Set(FrameTiming::kBuildFinish, layer_tree->build_finish());
timing.Set(FrameTiming::kRasterStart, fml::TimePoint::Now());
@ -265,9 +268,36 @@ RasterStatus Rasterizer::DoDraw(
// TODO(liyuqian): in Fuchsia, the rasterization doesn't finish when
// Rasterizer::DoDraw finishes. Future work is needed to adapt the timestamp
// for Fuchsia to capture SceneUpdateContext::ExecutePaintTasks.
timing.Set(FrameTiming::kRasterFinish, fml::TimePoint::Now());
const auto raster_finish_time = fml::TimePoint::Now();
timing.Set(FrameTiming::kRasterFinish, raster_finish_time);
delegate_.OnFrameRasterized(timing);
if (raster_finish_time > frame_target_time) {
fml::TimePoint latest_frame_target_time =
delegate_.GetLatestFrameTargetTime();
const auto frame_budget_millis = delegate_.GetFrameBudget().count();
if (latest_frame_target_time < raster_finish_time) {
latest_frame_target_time =
latest_frame_target_time +
fml::TimeDelta::FromMillisecondsF(frame_budget_millis);
}
const auto frame_lag =
(latest_frame_target_time - frame_target_time).ToMillisecondsF();
const int vsync_transitions_missed = round(frame_lag / frame_budget_millis);
fml::tracing::TraceEventAsyncComplete(
"flutter", // category
"SceneDisplayLag", // name
frame_target_time, // begin_time
raster_finish_time, // end_time
"frame_target_time", // arg_key_1
frame_target_time, // arg_val_1
"current_frame_target_time", // arg_key_2
latest_frame_target_time, // arg_val_2
"vsync_transitions_missed", // arg_key_3
vsync_transitions_missed // arg_val_3
);
}
// Pipeline pressure is applied from a couple of places:
// rasterizer: When there are more items as of the time of Consume.
// animator (via shell): Frame gets produces every vsync.

11
engine/src/flutter/shell/common/rasterizer.h
View File

@ -19,6 +19,8 @@
#include "flutter/lib/ui/snapshot_delegate.h"
#include "flutter/shell/common/pipeline.h"
#include "flutter/shell/common/surface.h"
#include "fml/time/time_delta.h"
#include "fml/time/time_point.h"
namespace flutter {
@ -67,6 +69,10 @@ class Rasterizer final : public SnapshotDelegate {
/// Time limit for a smooth frame. See `Engine::GetDisplayRefreshRate`.
virtual fml::Milliseconds GetFrameBudget() = 0;
/// Target time for the latest frame. See also `Shell::OnAnimatorBeginFrame`
/// for when this time gets updated.
virtual fml::TimePoint GetLatestFrameTargetTime() const = 0;
};
// TODO(dnfield): remove once embedders have caught up.
@ -75,6 +81,11 @@ class Rasterizer final : public SnapshotDelegate {
fml::Milliseconds GetFrameBudget() override {
return fml::kDefaultFrameBudget;
}
// Returning a time in the past so we don't add additional trace
// events when exceeding the frame budget for other embedders.
fml::TimePoint GetLatestFrameTargetTime() const override {
return fml::TimePoint::FromEpochDelta(fml::TimeDelta::Zero());
}
};
//----------------------------------------------------------------------------

16
engine/src/flutter/shell/common/shell.cc
View File

@ -931,12 +931,17 @@ void Shell::OnPlatformViewSetNextFrameCallback(const fml::closure& closure) {
}
// |Animator::Delegate|
void Shell::OnAnimatorBeginFrame(fml::TimePoint frame_time) {
void Shell::OnAnimatorBeginFrame(fml::TimePoint frame_target_time) {
FML_DCHECK(is_setup_);
FML_DCHECK(task_runners_.GetUITaskRunner()->RunsTasksOnCurrentThread());
// record the target time for use by rasterizer.
{
std::scoped_lock time_recorder_lock(time_recorder_mutex_);
latest_frame_target_time_.emplace(frame_target_time);
}
if (engine_) {
engine_->BeginFrame(frame_time);
engine_->BeginFrame(frame_target_time);
}
}
@ -1165,6 +1170,13 @@ fml::Milliseconds Shell::GetFrameBudget() {
}
}
fml::TimePoint Shell::GetLatestFrameTargetTime() const {
std::scoped_lock time_recorder_lock(time_recorder_mutex_);
FML_CHECK(latest_frame_target_time_.has_value())
<< "GetLatestFrameTargetTime called before OnAnimatorBeginFrame";
return latest_frame_target_time_.value();
}
// |ServiceProtocol::Handler|
fml::RefPtr<fml::TaskRunner> Shell::GetServiceProtocolHandlerTaskRunner(
std::string_view method) const {

9
engine/src/flutter/shell/common/shell.h
View File

@ -6,6 +6,7 @@
#define SHELL_COMMON_SHELL_H_
#include <functional>
#include <mutex>
#include <string_view>
#include <unordered_map>
@ -32,6 +33,7 @@
#include "flutter/shell/common/rasterizer.h"
#include "flutter/shell/common/shell_io_manager.h"
#include "flutter/shell/common/surface.h"
#include "fml/time/time_point.h"
namespace flutter {
@ -368,6 +370,8 @@ class Shell final : public PlatformView::Delegate,
const TaskRunners task_runners_;
const Settings settings_;
DartVMRef vm_;
mutable std::mutex time_recorder_mutex_;
std::optional<fml::TimePoint> latest_frame_target_time_;
std::unique_ptr<PlatformView> platform_view_; // on platform task runner
std::unique_ptr<Engine> engine_; // on UI task runner
std::unique_ptr<Rasterizer> rasterizer_; // on GPU task runner
@ -478,7 +482,7 @@ class Shell final : public PlatformView::Delegate,
void OnPlatformViewSetNextFrameCallback(const fml::closure& closure) override;
// |Animator::Delegate|
void OnAnimatorBeginFrame(fml::TimePoint frame_time) override;
void OnAnimatorBeginFrame(fml::TimePoint frame_target_time) override;
// |Animator::Delegate|
void OnAnimatorNotifyIdle(int64_t deadline) override;
@ -517,6 +521,9 @@ class Shell final : public PlatformView::Delegate,
// |Rasterizer::Delegate|
fml::Milliseconds GetFrameBudget() override;
// |Rasterizer::Delegate|
fml::TimePoint GetLatestFrameTargetTime() const override;
// |ServiceProtocol::Handler|
fml::RefPtr<fml::TaskRunner> GetServiceProtocolHandlerTaskRunner(
std::string_view method) const override;

4
engine/src/flutter/shell/common/shell_test.cc
View File

@ -250,6 +250,10 @@ TaskRunners ShellTest::GetTaskRunnersForFixture() {
};
}
fml::TimePoint ShellTest::GetLatestFrameTargetTime(Shell* shell) const {
return shell->GetLatestFrameTargetTime();
}
std::unique_ptr<Shell> ShellTest::CreateShell(Settings settings,
bool simulate_vsync) {
return CreateShell(std::move(settings), GetTaskRunnersForFixture(),

3
engine/src/flutter/shell/common/shell_test.h
View File

@ -19,6 +19,7 @@
#include "flutter/testing/elf_loader.h"
#include "flutter/testing/test_dart_native_resolver.h"
#include "flutter/testing/thread_test.h"
#include "fml/time/time_point.h"
namespace flutter {
namespace testing {
@ -37,6 +38,8 @@ class ShellTest : public ThreadTest {
void DestroyShell(std::unique_ptr<Shell> shell, TaskRunners task_runners);
TaskRunners GetTaskRunnersForFixture();
fml::TimePoint GetLatestFrameTargetTime(Shell* shell) const;
void SendEnginePlatformMessage(Shell* shell,
fml::RefPtr<PlatformMessage> message);