diff --git a/flow/frame_timings.h b/flow/frame_timings.h index 76b9281357407..e477a80b8f955 100644 --- a/flow/frame_timings.h +++ b/flow/frame_timings.h @@ -14,9 +14,11 @@ #include "flutter/fml/time/time_delta.h" #include "flutter/fml/time/time_point.h" -#define TRACE_EVENT_WITH_FRAME_NUMBER(recorder, category_group, name) \ - TRACE_EVENT1(category_group, name, "frame_number", \ - recorder->GetFrameNumberTraceArg()) +#define TRACE_EVENT_WITH_FRAME_NUMBER(recorder, category_group, name, \ + flow_id_count, flow_ids) \ + TRACE_EVENT1_WITH_FLOW_IDS(category_group, name, flow_id_count, flow_ids, \ + "frame_number", \ + recorder->GetFrameNumberTraceArg()) namespace flutter { diff --git a/fml/trace_event.cc b/fml/trace_event.cc index 7ec9adbab3118..28e7105f0aec0 100644 --- a/fml/trace_event.cc +++ b/fml/trace_event.cc @@ -30,6 +30,8 @@ std::atomic gTimelineMicrosSource = DefaultMicrosSource; inline void FlutterTimelineEvent(const char* label, int64_t timestamp0, int64_t timestamp1_or_async_id, + intptr_t flow_id_count, + const int64_t* flow_ids, Dart_Timeline_Event_Type type, intptr_t argument_count, const char** argument_names, @@ -37,8 +39,8 @@ inline void FlutterTimelineEvent(const char* label, TimelineEventHandler handler = gTimelineEventHandler.load(std::memory_order_relaxed); if (handler && gAllowlist.Query(label)) { - handler(label, timestamp0, timestamp1_or_async_id, type, argument_count, - argument_names, argument_values); + handler(label, timestamp0, timestamp1_or_async_id, flow_id_count, flow_ids, + type, argument_count, argument_names, argument_values); } } } // namespace @@ -73,6 +75,8 @@ void TraceTimelineEvent(TraceArg category_group, TraceArg name, int64_t timestamp_micros, TraceIDArg identifier, + size_t flow_id_count, + const uint64_t* flow_ids, Dart_Timeline_Event_Type type, const std::vector& c_names, const std::vector& values) { @@ -86,19 +90,23 @@ void TraceTimelineEvent(TraceArg category_group, } FlutterTimelineEvent( - name, // label - timestamp_micros, // timestamp0 - identifier, // timestamp1_or_async_id - type, // event type - argument_count, // argument_count - const_cast(c_names.data()), // argument_names - c_values.data() // argument_values + name, // label + timestamp_micros, // timestamp0 + identifier, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids + type, // event type + argument_count, // argument_count + const_cast(c_names.data()), // argument_names + c_values.data() // argument_values ); } void TraceTimelineEvent(TraceArg category_group, TraceArg name, TraceIDArg identifier, + size_t flow_id_count, + const uint64_t* flow_ids, Dart_Timeline_Event_Type type, const std::vector& c_names, const std::vector& values) { @@ -106,16 +114,23 @@ void TraceTimelineEvent(TraceArg category_group, name, // name gTimelineMicrosSource.load()(), // timestamp_micros identifier, // identifier + flow_id_count, // flow_id_count + flow_ids, // flow_ids type, // type c_names, // names values // values ); } -void TraceEvent0(TraceArg category_group, TraceArg name) { +void TraceEvent0(TraceArg category_group, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids) { FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - 0, // timestamp1_or_async_id + 0, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Begin, // event type 0, // argument_count nullptr, // argument_names @@ -125,13 +140,17 @@ void TraceEvent0(TraceArg category_group, TraceArg name) { void TraceEvent1(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val) { const char* arg_names[] = {arg1_name}; const char* arg_values[] = {arg1_val}; FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - 0, // timestamp1_or_async_id + 0, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Begin, // event type 1, // argument_count arg_names, // argument_names @@ -141,6 +160,8 @@ void TraceEvent1(TraceArg category_group, void TraceEvent2(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val, TraceArg arg2_name, @@ -149,7 +170,9 @@ void TraceEvent2(TraceArg category_group, const char* arg_values[] = {arg1_val, arg2_val}; FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - 0, // timestamp1_or_async_id + 0, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Begin, // event type 2, // argument_count arg_names, // argument_names @@ -161,6 +184,8 @@ void TraceEventEnd(TraceArg name) { FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 0, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_End, // event type 0, // argument_count nullptr, // argument_names @@ -170,10 +195,14 @@ void TraceEventEnd(TraceArg name) { void TraceEventAsyncBegin0(TraceArg category_group, TraceArg name, - TraceIDArg id) { + TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids) { FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - id, // timestamp1_or_async_id + id, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Async_Begin, // event type 0, // argument_count nullptr, // argument_names @@ -187,6 +216,8 @@ void TraceEventAsyncEnd0(TraceArg category_group, FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 id, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Async_End, // event type 0, // argument_count nullptr, // argument_names @@ -197,13 +228,17 @@ void TraceEventAsyncEnd0(TraceArg category_group, void TraceEventAsyncBegin1(TraceArg category_group, TraceArg name, TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val) { const char* arg_names[] = {arg1_name}; const char* arg_values[] = {arg1_val}; FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - id, // timestamp1_or_async_id + id, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Async_Begin, // event type 1, // argument_count arg_names, // argument_names @@ -221,6 +256,8 @@ void TraceEventAsyncEnd1(TraceArg category_group, FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 id, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Async_End, // event type 1, // argument_count arg_names, // argument_names @@ -228,10 +265,15 @@ void TraceEventAsyncEnd1(TraceArg category_group, ); } -void TraceEventInstant0(TraceArg category_group, TraceArg name) { +void TraceEventInstant0(TraceArg category_group, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids) { FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - 0, // timestamp1_or_async_id + 0, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Instant, // event type 0, // argument_count nullptr, // argument_names @@ -241,13 +283,17 @@ void TraceEventInstant0(TraceArg category_group, TraceArg name) { void TraceEventInstant1(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val) { const char* arg_names[] = {arg1_name}; const char* arg_values[] = {arg1_val}; FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - 0, // timestamp1_or_async_id + 0, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Instant, // event type 1, // argument_count arg_names, // argument_names @@ -257,6 +303,8 @@ void TraceEventInstant1(TraceArg category_group, void TraceEventInstant2(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val, TraceArg arg2_name, @@ -265,7 +313,9 @@ void TraceEventInstant2(TraceArg category_group, const char* arg_values[] = {arg1_val, arg2_val}; FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - 0, // timestamp1_or_async_id + 0, // timestamp1_or_async_id + flow_id_count, // flow_id_count + reinterpret_cast(flow_ids), // flow_ids Dart_Timeline_Event_Instant, // event type 2, // argument_count arg_names, // argument_names @@ -278,7 +328,9 @@ void TraceEventFlowBegin0(TraceArg category_group, TraceIDArg id) { FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 - id, // timestamp1_or_async_id + id, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Flow_Begin, // event type 0, // argument_count nullptr, // argument_names @@ -292,6 +344,8 @@ void TraceEventFlowStep0(TraceArg category_group, FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 id, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Flow_Step, // event type 0, // argument_count nullptr, // argument_names @@ -303,6 +357,8 @@ void TraceEventFlowEnd0(TraceArg category_group, TraceArg name, TraceIDArg id) { FlutterTimelineEvent(name, // label gTimelineMicrosSource.load()(), // timestamp0 id, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Flow_End, // event type 0, // argument_count nullptr, // argument_names @@ -334,6 +390,8 @@ void TraceTimelineEvent(TraceArg category_group, TraceArg name, int64_t timestamp_micros, TraceIDArg identifier, + size_t flow_id_count, + const uint64_t* flow_ids, Dart_Timeline_Event_Type type, const std::vector& c_names, const std::vector& values) {} @@ -341,19 +399,28 @@ void TraceTimelineEvent(TraceArg category_group, void TraceTimelineEvent(TraceArg category_group, TraceArg name, TraceIDArg identifier, + size_t flow_id_count, + const uint64_t* flow_ids, Dart_Timeline_Event_Type type, const std::vector& c_names, const std::vector& values) {} -void TraceEvent0(TraceArg category_group, TraceArg name) {} +void TraceEvent0(TraceArg category_group, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids) {} void TraceEvent1(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val) {} void TraceEvent2(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val, TraceArg arg2_name, @@ -368,7 +435,9 @@ void TraceEventAsyncComplete(TraceArg category_group, void TraceEventAsyncBegin0(TraceArg category_group, TraceArg name, - TraceIDArg id) {} + TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids) {} void TraceEventAsyncEnd0(TraceArg category_group, TraceArg name, @@ -377,6 +446,8 @@ void TraceEventAsyncEnd0(TraceArg category_group, void TraceEventAsyncBegin1(TraceArg category_group, TraceArg name, TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val) {} @@ -386,15 +457,22 @@ void TraceEventAsyncEnd1(TraceArg category_group, TraceArg arg1_name, TraceArg arg1_val) {} -void TraceEventInstant0(TraceArg category_group, TraceArg name) {} +void TraceEventInstant0(TraceArg category_group, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids) {} void TraceEventInstant1(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val) {} void TraceEventInstant2(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val, TraceArg arg2_name, diff --git a/fml/trace_event.h b/fml/trace_event.h index 378b037101b57..415fad05aaccb 100644 --- a/fml/trace_event.h +++ b/fml/trace_event.h @@ -21,11 +21,27 @@ ::fml::tracing::TraceCounterNopHACK((a), (b), (c), (arg1), __VA_ARGS__); #define FML_TRACE_EVENT(a, b, args...) TRACE_DURATION(a, b) +// On Fuchsia, the flow_id arguments to this macro are ignored. +#define FML_TRACE_EVENT_WITH_FLOW_IDS(category_group, name, flow_id_count, \ + flow_ids, ...) \ + FML_TRACE_EVENT(category_group, name) #define TRACE_EVENT0(a, b) TRACE_DURATION(a, b) +// On Fuchsia, the flow_id arguments to this macro are ignored. +#define TRACE_EVENT0_WITH_FLOW_IDS(category_group, name, flow_id_count, \ + flow_ids) \ + TRACE_EVENT0(category_group, name) #define TRACE_EVENT1(a, b, c, d) TRACE_DURATION(a, b, c, d) +// On Fuchsia, the flow_id arguments to this macro are ignored. +#define TRACE_EVENT1_WITH_FLOW_IDS(category_group, name, flow_id_count, \ + flow_ids, arg1_name, arg1_val) \ + TRACE_EVENT1(category_group, name, arg1_name, arg1_val) #define TRACE_EVENT2(a, b, c, d, e, f) TRACE_DURATION(a, b, c, d, e, f) #define TRACE_EVENT_ASYNC_BEGIN0(a, b, c) TRACE_ASYNC_BEGIN(a, b, c) +// On Fuchsia, the flow_id arguments to this macro are ignored. +#define TRACE_EVENT_ASYNC_BEGIN0_WITH_FLOW_IDS(category_group, name, id, \ + flow_id_count, flow_ids) \ + TRACE_EVENT_ASYNC_BEGIN0(category_group, name, id) #define TRACE_EVENT_ASYNC_END0(a, b, c) TRACE_ASYNC_END(a, b, c) #define TRACE_EVENT_ASYNC_BEGIN1(a, b, c, d, e) TRACE_ASYNC_BEGIN(a, b, c, d, e) #define TRACE_EVENT_ASYNC_END1(a, b, c, d, e) TRACE_ASYNC_END(a, b, c, d, e) @@ -83,49 +99,93 @@ // ``` // // Instead, either use different `name` or `arg1` parameter names. -#define FML_TRACE_EVENT(category_group, name, ...) \ - ::fml::tracing::TraceEvent((category_group), (name), __VA_ARGS__); \ +#define FML_TRACE_EVENT_WITH_FLOW_IDS(category_group, name, flow_id_count, \ + flow_ids, ...) \ + ::fml::tracing::TraceEvent((category_group), (name), (flow_id_count), \ + (flow_ids), __VA_ARGS__); \ __FML__AUTO_TRACE_END(name) -#define TRACE_EVENT0(category_group, name) \ - ::fml::tracing::TraceEvent0(category_group, name); \ +// Avoid using the same `name` and `argX_name` for nested traces, which can +// lead to double free errors. E.g. the following code should be avoided: +// +// ```cpp +// { +// TRACE_EVENT1("flutter", "Foo::Bar", "count", "initial_count_value"); +// ... +// TRACE_EVENT_INSTANT1("flutter", "Foo::Bar", +// "count", "updated_count_value"); +// } +// ``` +// +// Instead, either use different `name` or `arg1` parameter names. +#define FML_TRACE_EVENT(category_group, name, ...) \ + FML_TRACE_EVENT_WITH_FLOW_IDS((category_group), (name), \ + /*flow_id_count=*/(0), /*flow_ids=*/(nullptr), \ + __VA_ARGS__) + +#define TRACE_EVENT0_WITH_FLOW_IDS(category_group, name, flow_id_count, \ + flow_ids) \ + ::fml::tracing::TraceEvent0(category_group, name, flow_id_count, flow_ids); \ __FML__AUTO_TRACE_END(name) -#define TRACE_EVENT1(category_group, name, arg1_name, arg1_val) \ - ::fml::tracing::TraceEvent1(category_group, name, arg1_name, arg1_val); \ +#define TRACE_EVENT0(category_group, name) \ + TRACE_EVENT0_WITH_FLOW_IDS(category_group, name, /*flow_id_count=*/0, \ + /*flow_ids=*/nullptr) + +#define TRACE_EVENT1_WITH_FLOW_IDS(category_group, name, flow_id_count, \ + flow_ids, arg1_name, arg1_val) \ + ::fml::tracing::TraceEvent1(category_group, name, flow_id_count, flow_ids, \ + arg1_name, arg1_val); \ __FML__AUTO_TRACE_END(name) +#define TRACE_EVENT1(category_group, name, arg1_name, arg1_val) \ + TRACE_EVENT1_WITH_FLOW_IDS(category_group, name, /*flow_id_count=*/0, \ + /*flow_ids=*/nullptr, arg1_name, arg1_val) + #define TRACE_EVENT2(category_group, name, arg1_name, arg1_val, arg2_name, \ arg2_val) \ - ::fml::tracing::TraceEvent2(category_group, name, arg1_name, arg1_val, \ + ::fml::tracing::TraceEvent2(category_group, name, /*flow_id_count=*/0, \ + /*flow_ids=*/nullptr, arg1_name, arg1_val, \ arg2_name, arg2_val); \ __FML__AUTO_TRACE_END(name) +#define TRACE_EVENT_ASYNC_BEGIN0_WITH_FLOW_IDS(category_group, name, id, \ + flow_id_count, flow_ids) \ + ::fml::tracing::TraceEventAsyncBegin0(category_group, name, id, \ + flow_id_count, flow_ids); + #define TRACE_EVENT_ASYNC_BEGIN0(category_group, name, id) \ - ::fml::tracing::TraceEventAsyncBegin0(category_group, name, id); + TRACE_EVENT_ASYNC_BEGIN0_WITH_FLOW_IDS( \ + category_group, name, id, /*flow_id_count=*/0, /*flow_ids=*/nullptr) #define TRACE_EVENT_ASYNC_END0(category_group, name, id) \ ::fml::tracing::TraceEventAsyncEnd0(category_group, name, id); -#define TRACE_EVENT_ASYNC_BEGIN1(category_group, name, id, arg1_name, \ - arg1_val) \ - ::fml::tracing::TraceEventAsyncBegin1(category_group, name, id, arg1_name, \ - arg1_val); +#define TRACE_EVENT_ASYNC_BEGIN1(category_group, name, id, arg1_name, \ + arg1_val) \ + ::fml::tracing::TraceEventAsyncBegin1( \ + category_group, name, id, /*flow_id_count=*/0, /*flow_ids=*/nullptr, \ + arg1_name, arg1_val); #define TRACE_EVENT_ASYNC_END1(category_group, name, id, arg1_name, arg1_val) \ - ::fml::tracing::TraceEventAsyncEnd1(category_group, name, id, arg1_name, \ - arg1_val); + ::fml::tracing::TraceEventAsyncEnd1( \ + category_group, name, id, /*flow_id_count=*/0, /*flow_ids=*/nullptr, \ + arg1_name, arg1_val); #define TRACE_EVENT_INSTANT0(category_group, name) \ - ::fml::tracing::TraceEventInstant0(category_group, name); + ::fml::tracing::TraceEventInstant0( \ + category_group, name, /*flow_id_count=*/0, /*flow_ids=*/nullptr); #define TRACE_EVENT_INSTANT1(category_group, name, arg1_name, arg1_val) \ - ::fml::tracing::TraceEventInstant1(category_group, name, arg1_name, arg1_val); + ::fml::tracing::TraceEventInstant1( \ + category_group, name, /*flow_id_count=*/0, /*flow_ids=*/nullptr, \ + arg1_name, arg1_val); #define TRACE_EVENT_INSTANT2(category_group, name, arg1_name, arg1_val, \ arg2_name, arg2_val) \ - ::fml::tracing::TraceEventInstant2(category_group, name, arg1_name, \ - arg1_val, arg2_name, arg2_val); + ::fml::tracing::TraceEventInstant2( \ + category_group, name, /*flow_id_count=*/0, /*flow_ids=*/nullptr, \ + arg1_name, arg1_val, arg2_name, arg2_val); #define TRACE_FLOW_BEGIN(category, name, id) \ ::fml::tracing::TraceEventFlowBegin0(category, name, id); @@ -157,6 +217,8 @@ void TraceSetAllowlist(const std::vector& allowlist); typedef void (*TimelineEventHandler)(const char*, int64_t, int64_t, + intptr_t, + const int64_t*, Dart_Timeline_Event_Type, intptr_t, const char**, @@ -176,6 +238,8 @@ void TraceTimelineEvent(TraceArg category_group, TraceArg name, int64_t timestamp_micros, TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids, Dart_Timeline_Event_Type type, const std::vector& names, const std::vector& values); @@ -183,6 +247,8 @@ void TraceTimelineEvent(TraceArg category_group, void TraceTimelineEvent(TraceArg category_group, TraceArg name, TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids, Dart_Timeline_Event_Type type, const std::vector& names, const std::vector& values); @@ -241,7 +307,8 @@ void TraceCounter(TraceArg category, Args... args) { #if FLUTTER_TIMELINE_ENABLED auto split = SplitArguments(args...); - TraceTimelineEvent(category, name, identifier, Dart_Timeline_Event_Counter, + TraceTimelineEvent(category, name, identifier, /*flow_id_count=*/0, + /*flow_ids=*/nullptr, Dart_Timeline_Event_Counter, split.first, split.second); #endif // FLUTTER_TIMELINE_ENABLED } @@ -255,23 +322,34 @@ void TraceCounterNopHACK(TraceArg category, Args... args) {} template -void TraceEvent(TraceArg category, TraceArg name, Args... args) { +void TraceEvent(TraceArg category, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, + Args... args) { #if FLUTTER_TIMELINE_ENABLED auto split = SplitArguments(args...); - TraceTimelineEvent(category, name, 0, Dart_Timeline_Event_Begin, split.first, - split.second); + TraceTimelineEvent(category, name, 0, flow_id_count, flow_ids, + Dart_Timeline_Event_Begin, split.first, split.second); #endif // FLUTTER_TIMELINE_ENABLED } -void TraceEvent0(TraceArg category_group, TraceArg name); +void TraceEvent0(TraceArg category_group, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids); void TraceEvent1(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val); void TraceEvent2(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val, TraceArg arg2_name, @@ -300,6 +378,8 @@ void TraceEventAsyncComplete(TraceArg category_group, name, // name begin_micros, // timestamp_micros identifier, // identifier + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Async_Begin, // type split.first, // names split.second // values @@ -309,6 +389,8 @@ void TraceEventAsyncComplete(TraceArg category_group, name, // name end_micros, // timestamp_micros identifier, // identifier + 0, // flow_id_count + nullptr, // flow_ids Dart_Timeline_Event_Async_End, // type split.first, // names split.second // values @@ -318,13 +400,17 @@ void TraceEventAsyncComplete(TraceArg category_group, void TraceEventAsyncBegin0(TraceArg category_group, TraceArg name, - TraceIDArg id); + TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids); void TraceEventAsyncEnd0(TraceArg category_group, TraceArg name, TraceIDArg id); void TraceEventAsyncBegin1(TraceArg category_group, TraceArg name, TraceIDArg id, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val); @@ -334,15 +420,22 @@ void TraceEventAsyncEnd1(TraceArg category_group, TraceArg arg1_name, TraceArg arg1_val); -void TraceEventInstant0(TraceArg category_group, TraceArg name); +void TraceEventInstant0(TraceArg category_group, + TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids); void TraceEventInstant1(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val); void TraceEventInstant2(TraceArg category_group, TraceArg name, + size_t flow_id_count, + const uint64_t* flow_ids, TraceArg arg1_name, TraceArg arg1_val, TraceArg arg2_name, @@ -376,7 +469,10 @@ class ScopedInstantEnd { class TraceFlow { public: explicit TraceFlow(const char* label) : label_(label), nonce_(TraceNonce()) { + TraceEvent0("flutter", label_, /*flow_id_count=*/1, + /*flow_ids=*/&nonce_); TraceEventFlowBegin0("flutter", label_, nonce_); + TraceEventEnd(label_); } ~TraceFlow() { End(label_); } @@ -386,19 +482,25 @@ class TraceFlow { } void Step(const char* label = nullptr) const { + TraceEvent0("flutter", label ? label : label_, /*flow_id_count=*/1, + /*flow_ids=*/&nonce_); TraceEventFlowStep0("flutter", label ? label : label_, nonce_); + TraceEventEnd(label ? label : label_); } void End(const char* label = nullptr) { if (nonce_ != 0) { + TraceEvent0("flutter", label ? label : label_, /*flow_id_count=*/1, + /*flow_ids=*/&nonce_); TraceEventFlowEnd0("flutter", label ? label : label_, nonce_); + TraceEventEnd(label ? label : label_); nonce_ = 0; } } private: const char* label_; - size_t nonce_; + uint64_t nonce_; FML_DISALLOW_COPY_AND_ASSIGN(TraceFlow); }; diff --git a/runtime/dart_vm.cc b/runtime/dart_vm.cc index b8b75719b3e4e..9a61f6bb11fb1 100644 --- a/runtime/dart_vm.cc +++ b/runtime/dart_vm.cc @@ -472,13 +472,15 @@ DartVM::DartVM(const std::shared_ptr& vm_data, // As this call is immediately after initialization of the Dart VM, // we are interested in only one timestamp. int64_t micros = Dart_TimelineGetMicros(); - Dart_TimelineEvent("FlutterEngineMainEnter", // label - micros, // timestamp0 - micros, // timestamp1_or_async_id - Dart_Timeline_Event_Instant, // event type - 0, // argument_count - nullptr, // argument_names - nullptr // argument_values + Dart_RecordTimelineEvent("FlutterEngineMainEnter", // label + micros, // timestamp0 + micros, // timestamp1_or_async_id + 0, // flow_id_count + nullptr, // flow_ids + Dart_Timeline_Event_Instant, // event type + 0, // argument_count + nullptr, // argument_names + nullptr // argument_values ); } diff --git a/runtime/dart_vm_initializer.cc b/runtime/dart_vm_initializer.cc index 521b26d04eb8e..fbd941d11f8ce 100644 --- a/runtime/dart_vm_initializer.cc +++ b/runtime/dart_vm_initializer.cc @@ -113,17 +113,17 @@ void DartVMInitializer::Initialize(Dart_InitializeParams* params, void DartVMInitializer::Cleanup() { FML_DCHECK(gDartInitialized); - // Dart_TimelineEvent is unsafe during a concurrent call to Dart_Cleanup + // Dart_RecordTimelineEvent is unsafe during a concurrent call to Dart_Cleanup // because Dart_Cleanup will destroy the timeline recorder. Clear the // initialized flag so that future calls to LogDartTimelineEvent will not - // call Dart_TimelineEvent. + // call Dart_RecordTimelineEvent. // // Note that this is inherently racy. If a thread sees that gDartInitialized - // is set and proceeds to call Dart_TimelineEvent shortly before another - // thread calls Dart_Cleanup, then the Dart_TimelineEvent call may crash - // if Dart_Cleanup deletes the timeline before Dart_TimelineEvent completes. - // In practice this is unlikely because Dart_Cleanup does significant other - // work before deleting the timeline. + // is set and proceeds to call Dart_RecordTimelineEvent shortly before another + // thread calls Dart_Cleanup, then the Dart_RecordTimelineEvent call may crash + // if Dart_Cleanup deletes the timeline before Dart_RecordTimelineEvent + // completes. In practice this is unlikely because Dart_Cleanup does + // significant other work before deleting the timeline. // // The engine can not safely guard Dart_Cleanup and LogDartTimelineEvent with // a lock due to the risk of deadlocks. Dart_Cleanup waits for various @@ -142,12 +142,15 @@ void DartVMInitializer::Cleanup() { void DartVMInitializer::LogDartTimelineEvent(const char* label, int64_t timestamp0, int64_t timestamp1_or_async_id, + intptr_t flow_id_count, + const int64_t* flow_ids, Dart_Timeline_Event_Type type, intptr_t argument_count, const char** argument_names, const char** argument_values) { if (gDartInitialized) { - Dart_TimelineEvent(label, timestamp0, timestamp1_or_async_id, type, - argument_count, argument_names, argument_values); + Dart_RecordTimelineEvent(label, timestamp0, timestamp1_or_async_id, + flow_id_count, flow_ids, type, argument_count, + argument_names, argument_values); } } diff --git a/runtime/dart_vm_initializer.h b/runtime/dart_vm_initializer.h index 861a1b54c407f..9889d2402ce40 100644 --- a/runtime/dart_vm_initializer.h +++ b/runtime/dart_vm_initializer.h @@ -19,6 +19,8 @@ class DartVMInitializer { static void LogDartTimelineEvent(const char* label, int64_t timestamp0, int64_t timestamp1_or_async_id, + intptr_t flow_id_count, + const int64_t* flow_ids, Dart_Timeline_Event_Type type, intptr_t argument_count, const char** argument_names, diff --git a/shell/common/animator.cc b/shell/common/animator.cc index bb4c131cdff68..29c21c1ae5592 100644 --- a/shell/common/animator.cc +++ b/shell/common/animator.cc @@ -66,8 +66,17 @@ void Animator::BeginFrame( frame_timings_recorder_ = std::move(frame_timings_recorder); frame_timings_recorder_->RecordBuildStart(fml::TimePoint::Now()); + size_t flow_id_count = trace_flow_ids_.size(); + std::unique_ptr flow_ids = + std::make_unique(flow_id_count); + for (size_t i = 0; i < flow_id_count; ++i) { + flow_ids.get()[i] = trace_flow_ids_.at(i); + } + TRACE_EVENT_WITH_FRAME_NUMBER(frame_timings_recorder_, "flutter", - "Animator::BeginFrame"); + "Animator::BeginFrame", flow_id_count, + flow_ids.get()); + while (!trace_flow_ids_.empty()) { uint64_t trace_flow_id = trace_flow_ids_.front(); TRACE_FLOW_END("flutter", "PointerEvent", trace_flow_id); @@ -142,7 +151,8 @@ void Animator::Render(std::unique_ptr layer_tree, } TRACE_EVENT_WITH_FRAME_NUMBER(frame_timings_recorder_, "flutter", - "Animator::Render"); + "Animator::Render", /*flow_id_count=*/0, + /*flow_ids=*/nullptr); frame_timings_recorder_->RecordBuildEnd(fml::TimePoint::Now()); delegate_.OnAnimatorUpdateLatestFrameTargetTime( @@ -259,8 +269,17 @@ void Animator::ScheduleMaybeClearTraceFlowIds() { return; } if (!self->frame_scheduled_ && !self->trace_flow_ids_.empty()) { - TRACE_EVENT0("flutter", - "Animator::ScheduleMaybeClearTraceFlowIds - callback"); + size_t flow_id_count = self->trace_flow_ids_.size(); + std::unique_ptr flow_ids = + std::make_unique(flow_id_count); + for (size_t i = 0; i < flow_id_count; ++i) { + flow_ids.get()[i] = self->trace_flow_ids_.at(i); + } + + TRACE_EVENT0_WITH_FLOW_IDS( + "flutter", "Animator::ScheduleMaybeClearTraceFlowIds - callback", + flow_id_count, flow_ids.get()); + while (!self->trace_flow_ids_.empty()) { auto flow_id = self->trace_flow_ids_.front(); TRACE_FLOW_END("flutter", "PointerEvent", flow_id); diff --git a/shell/common/engine.cc b/shell/common/engine.cc index 33d8e52baf40d..829e3fd60bed0 100644 --- a/shell/common/engine.cc +++ b/shell/common/engine.cc @@ -418,7 +418,9 @@ void Engine::HandleSettingsPlatformMessage(PlatformMessage* message) { void Engine::DispatchPointerDataPacket( std::unique_ptr packet, uint64_t trace_flow_id) { - TRACE_EVENT0("flutter", "Engine::DispatchPointerDataPacket"); + TRACE_EVENT0_WITH_FLOW_IDS("flutter", "Engine::DispatchPointerDataPacket", + /*flow_id_count=*/1, + /*flow_ids=*/&trace_flow_id); TRACE_FLOW_STEP("flutter", "PointerEvent", trace_flow_id); pointer_data_dispatcher_->DispatchPacket(std::move(packet), trace_flow_id); } diff --git a/shell/common/pipeline.h b/shell/common/pipeline.h index 00e67d1a4261f..c76ccbedbcd49 100644 --- a/shell/common/pipeline.h +++ b/shell/common/pipeline.h @@ -112,12 +112,14 @@ class Pipeline { std::function; Continuation continuation_; - size_t trace_id_; + uint64_t trace_id_; - ProducerContinuation(const Continuation& continuation, size_t trace_id) + ProducerContinuation(const Continuation& continuation, uint64_t trace_id) : continuation_(continuation), trace_id_(trace_id) { + TRACE_EVENT_ASYNC_BEGIN0_WITH_FLOW_IDS("flutter", "PipelineItem", + trace_id_, /*flow_id_count=*/1, + /*flow_ids=*/&trace_id); TRACE_FLOW_BEGIN("flutter", "PipelineItem", trace_id_); - TRACE_EVENT_ASYNC_BEGIN0("flutter", "PipelineItem", trace_id_); TRACE_EVENT_ASYNC_BEGIN0("flutter", "PipelineProduce", trace_id_); } diff --git a/shell/common/pointer_data_dispatcher.cc b/shell/common/pointer_data_dispatcher.cc index 78346a9d0ced3..58bf4b110b78c 100644 --- a/shell/common/pointer_data_dispatcher.cc +++ b/shell/common/pointer_data_dispatcher.cc @@ -18,7 +18,9 @@ SmoothPointerDataDispatcher::~SmoothPointerDataDispatcher() = default; void DefaultPointerDataDispatcher::DispatchPacket( std::unique_ptr packet, uint64_t trace_flow_id) { - TRACE_EVENT0("flutter", "DefaultPointerDataDispatcher::DispatchPacket"); + TRACE_EVENT0_WITH_FLOW_IDS("flutter", + "DefaultPointerDataDispatcher::DispatchPacket", + /*flow_id_count=*/1, &trace_flow_id); TRACE_FLOW_STEP("flutter", "PointerEvent", trace_flow_id); delegate_.DoDispatchPacket(std::move(packet), trace_flow_id); } @@ -26,7 +28,9 @@ void DefaultPointerDataDispatcher::DispatchPacket( void SmoothPointerDataDispatcher::DispatchPacket( std::unique_ptr packet, uint64_t trace_flow_id) { - TRACE_EVENT0("flutter", "SmoothPointerDataDispatcher::DispatchPacket"); + TRACE_EVENT0_WITH_FLOW_IDS("flutter", + "SmoothPointerDataDispatcher::DispatchPacket", + /*flow_id_count=*/1, &trace_flow_id); TRACE_FLOW_STEP("flutter", "PointerEvent", trace_flow_id); if (is_pointer_data_in_progress_) { diff --git a/shell/common/rasterizer.cc b/shell/common/rasterizer.cc index 07de96e39f7f3..d7d1338c1a533 100644 --- a/shell/common/rasterizer.cc +++ b/shell/common/rasterizer.cc @@ -386,7 +386,8 @@ RasterStatus Rasterizer::DoDraw( std::unique_ptr layer_tree, float device_pixel_ratio) { TRACE_EVENT_WITH_FRAME_NUMBER(frame_timings_recorder, "flutter", - "Rasterizer::DoDraw"); + "Rasterizer::DoDraw", /*flow_id_count=*/0, + /*flow_ids=*/nullptr); FML_DCHECK(delegate_.GetTaskRunners() .GetRasterTaskRunner() ->RunsTasksOnCurrentThread()); diff --git a/shell/common/shell.cc b/shell/common/shell.cc index aae9a456f3c91..d6e94c6345362 100644 --- a/shell/common/shell.cc +++ b/shell/common/shell.cc @@ -1029,7 +1029,9 @@ void Shell::OnPlatformViewDispatchPlatformMessage( // |PlatformView::Delegate| void Shell::OnPlatformViewDispatchPointerDataPacket( std::unique_ptr packet) { - TRACE_EVENT0("flutter", "Shell::OnPlatformViewDispatchPointerDataPacket"); + TRACE_EVENT0_WITH_FLOW_IDS( + "flutter", "Shell::OnPlatformViewDispatchPointerDataPacket", + /*flow_id_count=*/1, /*flow_ids=*/&next_pointer_flow_id_); TRACE_FLOW_BEGIN("flutter", "PointerEvent", next_pointer_flow_id_); FML_DCHECK(is_set_up_); FML_DCHECK(task_runners_.GetPlatformTaskRunner()->RunsTasksOnCurrentThread()); diff --git a/shell/common/skia_event_tracer_impl.cc b/shell/common/skia_event_tracer_impl.cc index 83a620dc9c5b0..e7c15f4c7e766 100644 --- a/shell/common/skia_event_tracer_impl.cc +++ b/shell/common/skia_event_tracer_impl.cc @@ -220,10 +220,12 @@ class FlutterEventTracer : public SkEventTracer { case TRACE_EVENT_PHASE_BEGIN: case TRACE_EVENT_PHASE_COMPLETE: if (devtoolsTag) { - fml::tracing::TraceEvent1(kSkiaTag, name, kDevtoolsTagArg, + fml::tracing::TraceEvent1(kSkiaTag, name, /*flow_id_count=*/0, + /*flow_ids=*/nullptr, kDevtoolsTagArg, devtoolsTag); } else { - fml::tracing::TraceEvent0(kSkiaTag, name); + fml::tracing::TraceEvent0(kSkiaTag, name, /*flow_id_count=*/0, + /*flow_ids=*/nullptr); } break; case TRACE_EVENT_PHASE_END: @@ -231,18 +233,26 @@ class FlutterEventTracer : public SkEventTracer { break; case TRACE_EVENT_PHASE_INSTANT: if (devtoolsTag) { - fml::tracing::TraceEventInstant1(kSkiaTag, name, kDevtoolsTagArg, - devtoolsTag); + fml::tracing::TraceEventInstant1(kSkiaTag, name, + /*flow_id_count=*/0, + /*flow_ids=*/nullptr, + kDevtoolsTagArg, devtoolsTag); } else { - fml::tracing::TraceEventInstant0(kSkiaTag, name); + fml::tracing::TraceEventInstant0(kSkiaTag, name, + /*flow_id_count=*/0, + /*flow_ids=*/nullptr); } break; case TRACE_EVENT_PHASE_ASYNC_BEGIN: if (devtoolsTag) { fml::tracing::TraceEventAsyncBegin1(kSkiaTag, name, id, + /*flow_id_count=*/0, + /*flow_ids=*/nullptr, kDevtoolsTagArg, devtoolsTag); } else { - fml::tracing::TraceEventAsyncBegin0(kSkiaTag, name, id); + fml::tracing::TraceEventAsyncBegin0(kSkiaTag, name, id, + /*flow_id_count=*/0, + /*flow_ids=*/nullptr); } break; case TRACE_EVENT_PHASE_ASYNC_END: diff --git a/shell/common/vsync_waiter.cc b/shell/common/vsync_waiter.cc index 5ee04ef530b08..326e51a33462b 100644 --- a/shell/common/vsync_waiter.cc +++ b/shell/common/vsync_waiter.cc @@ -110,7 +110,7 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time, } if (callback) { - auto flow_identifier = fml::tracing::TraceNonce(); + const uint64_t flow_identifier = fml::tracing::TraceNonce(); if (pause_secondary_tasks) { PauseDartMicroTasks(); } @@ -119,7 +119,9 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time, // 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_EVENT0_WITH_FLOW_IDS("flutter", "VsyncFireCallback", + /*flow_id_count=*/1, + /*flow_ids=*/&flow_identifier); TRACE_FLOW_BEGIN("flutter", kVsyncFlowName, flow_identifier); @@ -129,8 +131,10 @@ void VsyncWaiter::FireCallback(fml::TimePoint frame_start_time, task_runners_.GetUITaskRunner()->PostTask( [ui_task_queue_id, callback, flow_identifier, frame_start_time, frame_target_time, pause_secondary_tasks]() { - FML_TRACE_EVENT("flutter", kVsyncTraceName, "StartTime", - frame_start_time, "TargetTime", frame_target_time); + FML_TRACE_EVENT_WITH_FLOW_IDS( + "flutter", kVsyncTraceName, /*flow_id_count=*/1, + /*flow_ids=*/&flow_identifier, "StartTime", frame_start_time, + "TargetTime", frame_target_time); std::unique_ptr frame_timings_recorder = std::make_unique(); frame_timings_recorder->RecordVsync(frame_start_time, diff --git a/shell/platform/embedder/embedder.cc b/shell/platform/embedder/embedder.cc index 5f99ffbc2fddd..53c71d1c4d697 100644 --- a/shell/platform/embedder/embedder.cc +++ b/shell/platform/embedder/embedder.cc @@ -2884,7 +2884,8 @@ FlutterEngineResult FlutterEngineReloadSystemFonts( } void FlutterEngineTraceEventDurationBegin(const char* name) { - fml::tracing::TraceEvent0("flutter", name); + fml::tracing::TraceEvent0("flutter", name, /*flow_id_count=*/0, + /*flow_id=*/nullptr); } void FlutterEngineTraceEventDurationEnd(const char* name) { @@ -2892,7 +2893,8 @@ void FlutterEngineTraceEventDurationEnd(const char* name) { } void FlutterEngineTraceEventInstant(const char* name) { - fml::tracing::TraceEventInstant0("flutter", name); + fml::tracing::TraceEventInstant0("flutter", name, /*flow_id_count=*/0, + /*flow_id=*/nullptr); } FlutterEngineResult FlutterEnginePostRenderThreadTask( diff --git a/shell/testing/tester_main.cc b/shell/testing/tester_main.cc index 3bb48710c8bb1..310ce62e01430 100644 --- a/shell/testing/tester_main.cc +++ b/shell/testing/tester_main.cc @@ -399,6 +399,8 @@ int main(int argc, char* argv[]) { return EXIT_FAILURE; } + settings.leak_vm = false; + if (settings.icu_data_path.empty()) { settings.icu_data_path = "icudtl.dat"; } diff --git a/testing/dart/observatory/tracing_test.dart b/testing/dart/observatory/tracing_test.dart index 9c9f961f42a4c..1937c9b11df1e 100644 --- a/testing/dart/observatory/tracing_test.dart +++ b/testing/dart/observatory/tracing_test.dart @@ -3,12 +3,65 @@ // found in the LICENSE file. import 'dart:async'; +import 'dart:convert' show base64Decode; import 'dart:developer' as developer; import 'dart:ui'; import 'package:litetest/litetest.dart'; import 'package:vm_service/vm_service.dart' as vms; import 'package:vm_service/vm_service_io.dart'; +import 'package:vm_service_protos/vm_service_protos.dart'; + +Future _testChromeFormatTrace(vms.VmService vmService) async { + final vms.Timeline timeline = await vmService.getVMTimeline(); + + int saveLayerRecordCount = 0; + int saveLayerCount = 0; + int flowEventCount = 0; + for (final vms.TimelineEvent event in timeline.traceEvents!) { + final Map json = event.json!; + if (json['ph'] == 'B') { + if (json['name'] == 'ui.Canvas::saveLayer (Recorded)') { + saveLayerRecordCount += 1; + } + if (json['name'] == 'Canvas::saveLayer') { + saveLayerCount += 1; + } + } else if (json['ph'] == 's' || json['ph'] == 't' || json['ph'] == 'f') { + flowEventCount += 1; + } + } + expect(saveLayerRecordCount, 3); + expect(saveLayerCount, 3); + expect(flowEventCount, 5); +} + +Future _testPerfettoFormatTrace(vms.VmService vmService) async { + final vms.PerfettoTimeline response = await vmService.getPerfettoVMTimeline(); + final List packets = + Trace.fromBuffer(base64Decode(response.trace!)).packet; + final Iterable events = packets + .where((TracePacket packet) => packet.hasTrackEvent()) + .map((TracePacket packet) => packet.trackEvent); + + int saveLayerRecordCount = 0; + int saveLayerCount = 0; + int flowIdCount = 0; + for (final TrackEvent event in events) { + if (event.type == TrackEvent_Type.TYPE_SLICE_BEGIN) { + if (event.name == 'ui.Canvas::saveLayer (Recorded)') { + saveLayerRecordCount += 1; + } + if (event.name == 'Canvas::saveLayer') { + saveLayerCount += 1; + } + flowIdCount += event.flowIds.length; + } + } + expect(saveLayerRecordCount, 3); + expect(saveLayerCount, 3); + expect(flowIdCount, 5); +} void main() { test('Canvas.saveLayer emits tracing', () async { @@ -48,23 +101,8 @@ void main() { PlatformDispatcher.instance.scheduleFrame(); await completer.future; - final vms.Timeline timeline = await vmService.getVMTimeline(); + await _testChromeFormatTrace(vmService); + await _testPerfettoFormatTrace(vmService); await vmService.dispose(); - - int saveLayerRecordCount = 0; - int saveLayerCount = 0; - for (final vms.TimelineEvent event in timeline.traceEvents!) { - final Map json = event.json!; - if (json['ph'] == 'B') { - if (json['name'] == 'ui.Canvas::saveLayer (Recorded)') { - saveLayerRecordCount += 1; - } - if (json['name'] == 'Canvas::saveLayer') { - saveLayerCount += 1; - } - } - } - expect(saveLayerRecordCount, 3); - expect(saveLayerCount, 3); }); } diff --git a/testing/dart/pubspec.yaml b/testing/dart/pubspec.yaml index 58bf819d4e0f5..2c2a9a3d6a835 100644 --- a/testing/dart/pubspec.yaml +++ b/testing/dart/pubspec.yaml @@ -22,6 +22,7 @@ dependencies: sky_engine: any vector_math: any vm_service: any + vm_service_protos: any dependency_overrides: async_helper: @@ -48,3 +49,5 @@ dependency_overrides: path: ../../../third_party/pkg/vector_math vm_service: path: ../../../third_party/dart/pkg/vm_service + vm_service_protos: + path: ../../../third_party/dart/pkg/vm_service_protos