From 9ada55b844bbe2ec0b573bc31e84415abbd6baa5 Mon Sep 17 00:00:00 2001 From: Chinmay Garde Date: Thu, 14 Mar 2019 16:48:01 -0700 Subject: [PATCH] Add frame and target time metadata to vsync events and connect platform vsync events using flows. (flutter/engine#8172) This will allow us to easily visualize the time the platform informed the engine of a vsync event, its arguments, and when the engine began its UI thread workload using this information. --- engine/src/flutter/fml/trace_event.cc | 6 +++ engine/src/flutter/fml/trace_event.h | 18 +++++++++ .../src/flutter/shell/common/vsync_waiter.cc | 39 +++++++++++++------ .../shell/platform/embedder/embedder.cc | 2 + .../shell/platform/embedder/embedder.h | 2 + 5 files changed, 55 insertions(+), 12 deletions(-) diff --git a/engine/src/flutter/fml/trace_event.cc b/engine/src/flutter/fml/trace_event.cc index 434e7883d9..843aa6b6d5 100644 --- a/engine/src/flutter/fml/trace_event.cc +++ b/engine/src/flutter/fml/trace_event.cc @@ -5,6 +5,7 @@ #include "flutter/fml/trace_event.h" #include +#include #include "flutter/fml/build_config.h" #include "flutter/fml/logging.h" @@ -31,6 +32,11 @@ namespace fml { namespace tracing { +size_t TraceNonce() { + static std::atomic_size_t gLastItem; + return ++gLastItem; +} + void TraceTimelineEvent(TraceArg category_group, TraceArg name, TraceIDArg identifier, diff --git a/engine/src/flutter/fml/trace_event.h b/engine/src/flutter/fml/trace_event.h index 1f979d4e35..45221a09c4 100644 --- a/engine/src/flutter/fml/trace_event.h +++ b/engine/src/flutter/fml/trace_event.h @@ -30,6 +30,7 @@ #include #include "flutter/fml/macros.h" +#include "flutter/fml/time/time_point.h" #include "third_party/dart/runtime/include/dart_tools_api.h" #if !defined(OS_FUCHSIA) @@ -50,6 +51,10 @@ ::fml::tracing::TraceCounter((category_group), (name), (counter_id), (arg1), \ __VA_ARGS__); +#define FML_TRACE_EVENT(category_group, name, ...) \ + ::fml::tracing::TraceEvent((category_group), (name), __VA_ARGS__); \ + __FML__AUTO_TRACE_END(name) + #define TRACE_EVENT0(category_group, name) \ ::fml::tracing::TraceEvent0(category_group, name); \ __FML__AUTO_TRACE_END(name) @@ -116,6 +121,10 @@ inline std::string TraceToString(std::string string) { return string; } +inline std::string TraceToString(TimePoint point) { + return std::to_string(point.ToEpochDelta().ToNanoseconds()); +} + template ::value>> std::string TraceToString(T string) { return std::to_string(string); @@ -149,6 +158,8 @@ SplitArguments(Key key, Value value, Args... args) { return std::make_pair(std::move(keys), std::move(values)); } +size_t TraceNonce(); + template void TraceCounter(TraceArg category, TraceArg name, @@ -159,6 +170,13 @@ void TraceCounter(TraceArg category, split.first, split.second); } +template +void TraceEvent(TraceArg category, TraceArg name, Args... args) { + auto split = SplitArguments(args...); + TraceTimelineEvent(category, name, 0, Dart_Timeline_Event_Begin, split.first, + split.second); +} + void TraceEvent0(TraceArg category_group, TraceArg name); void TraceEvent1(TraceArg category_group, diff --git a/engine/src/flutter/shell/common/vsync_waiter.cc b/engine/src/flutter/shell/common/vsync_waiter.cc index a117c7fff5..b6b55df11b 100644 --- a/engine/src/flutter/shell/common/vsync_waiter.cc +++ b/engine/src/flutter/shell/common/vsync_waiter.cc @@ -9,6 +9,20 @@ namespace shell { +#if defined(OS_FUCHSIA) +// In general, traces on Fuchsia are recorded across the whole system. +// Because of this, emitting a "VSYNC" event per flutter process is +// undesirable, as the events will collide with each other. We +// instead let another area of the system emit them. +static constexpr const char* kVsyncTraceName = "vsync callback"; +#else // defined(OS_FUCHSIA) +// Note: The tag name must be "VSYNC" (it is special) so that the +// "Highlight Vsync" checkbox in the timeline can be enabled. +static constexpr const char* kVsyncTraceName = "VSYNC"; +#endif // defined(OS_FUCHSIA) + +static constexpr const char* kVsyncFlowName = "VsyncFlow"; + VsyncWaiter::VsyncWaiter(blink::TaskRunners task_runners) : task_runners_(std::move(task_runners)) {} @@ -35,19 +49,20 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time, return; } + auto flow_identifier = fml::tracing::TraceNonce(); + + // The base trace ensures that flows have a root to begin from if one does not + // exist. The trace viewer will ignore traces that have no base event trace. + // While all our message loops insert a base trace trace + // (MessageLoop::RunExpiredTasks), embedders may not. + TRACE_EVENT0("flutter", "VsyncFireCallback"); + TRACE_FLOW_BEGIN("flutter", kVsyncFlowName, flow_identifier); + task_runners_.GetUITaskRunner()->PostTaskForTime( - [callback, frame_start_time, frame_target_time]() { -#if defined(OS_FUCHSIA) - // In general, traces on Fuchsia are recorded across the whole system. - // Because of this, emitting a "VSYNC" event per flutter process is - // undesirable, as the events will collide with each other. We - // instead let another area of the system emit them. - TRACE_EVENT0("flutter", "vsync callback"); -#else - // Note: The tag name must be "VSYNC" (it is special) so that the - // "Highlight Vsync" checkbox in the timeline can be enabled. - TRACE_EVENT0("flutter", "VSYNC"); -#endif + [callback, flow_identifier, frame_start_time, frame_target_time]() { + FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime", + frame_start_time, "TargetTime", frame_target_time); + TRACE_FLOW_END("flutter", kVsyncFlowName, flow_identifier); callback(frame_start_time, frame_target_time); }, frame_start_time); diff --git a/engine/src/flutter/shell/platform/embedder/embedder.cc b/engine/src/flutter/shell/platform/embedder/embedder.cc index 09933a32a0..65aa88808f 100644 --- a/engine/src/flutter/shell/platform/embedder/embedder.cc +++ b/engine/src/flutter/shell/platform/embedder/embedder.cc @@ -888,6 +888,8 @@ FlutterEngineResult FlutterEngineOnVsync(FlutterEngine engine, return LOG_EMBEDDER_ERROR(kInvalidArguments); } + TRACE_EVENT0("flutter", "FlutterEngineOnVsync"); + auto start_time = fml::TimePoint::FromEpochDelta( fml::TimeDelta::FromNanoseconds(frame_start_time_nanos)); diff --git a/engine/src/flutter/shell/platform/embedder/embedder.h b/engine/src/flutter/shell/platform/embedder/embedder.h index 8f24538672..6127681c55 100644 --- a/engine/src/flutter/shell/platform/embedder/embedder.h +++ b/engine/src/flutter/shell/platform/embedder/embedder.h @@ -664,6 +664,8 @@ FlutterEngineResult FlutterEngineDispatchSemanticsAction( // garbage collection in periods in which the various threads are most likely to // be idle. For example, for a 60Hz display, embedders should add 16.6 * 1e6 to // the frame time field. The system monotonic clock is used as the timebase. +// +// That frame timepoints are in nanoseconds. FLUTTER_EXPORT FlutterEngineResult FlutterEngineOnVsync(FlutterEngine engine, intptr_t baton,