// Copyright (c) 2015, the Dart project authors. Please see the AUTHORS file // for details. All rights reserved. Use of this source code is governed by a // BSD-style license that can be found in the LICENSE file. #include "vm/globals.h" #if defined(SUPPORT_TIMELINE) #include "vm/timeline.h" #include #include #include #include #include #include #include #if defined(DART_HOST_OS_MACOS) #include #endif #include "platform/atomic.h" #include "platform/hashmap.h" #include "vm/image_snapshot.h" #include "vm/isolate.h" #include "vm/json_stream.h" #include "vm/lockers.h" #include "vm/log.h" #include "vm/object.h" #include "vm/reverse_pc_lookup_cache.h" #include "vm/service.h" #include "vm/service_event.h" #include "vm/thread.h" #if defined(SUPPORT_PERFETTO) #include "perfetto/ext/tracing/core/trace_packet.h" #include "third_party/perfetto/protos/perfetto/common/builtin_clock.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/clock_snapshot.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/trace_packet.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/debug_annotation.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/process_descriptor.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/thread_descriptor.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/track_descriptor.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/track_event.pbzero.h" #include "vm/perfetto_utils.h" #endif // defined(SUPPORT_PERFETTO) namespace dart { #if defined(PRODUCT) #define DEFAULT_TIMELINE_RECORDER "none" #define SUPPORTED_TIMELINE_RECORDERS "systrace, file, callback" #else #define DEFAULT_TIMELINE_RECORDER "ring" #if defined(SUPPORT_PERFETTO) #define SUPPORTED_TIMELINE_RECORDERS \ "ring, endless, startup, systrace, file, callback, perfettofile" #else #define SUPPORTED_TIMELINE_RECORDERS \ "ring, endless, startup, systrace, file, callback" #endif #endif DEFINE_FLAG(bool, complete_timeline, false, "Record the complete timeline"); DEFINE_FLAG(bool, startup_timeline, false, "Record the startup timeline"); // TODO(derekx): Remove this flag in Dart 3.4. DEFINE_FLAG( bool, systrace_timeline, false, "Record the timeline to the platform's tracing service if there is one"); DEFINE_FLAG(bool, trace_timeline, false, "Trace timeline backend"); DEFINE_FLAG(charp, timeline_dir, nullptr, "Enable all timeline trace streams and output VM global trace " "into specified directory. This flag is ignored by the file and " "perfetto recorders."); DEFINE_FLAG(charp, timeline_streams, nullptr, "Comma separated list of timeline streams to record. " "Valid values: all, API, Compiler, CompilerVerbose, Dart, " "Debugger, Embedder, GC, Isolate, Microtask, and VM."); DEFINE_FLAG(charp, timeline_recorder, DEFAULT_TIMELINE_RECORDER, "Select the timeline recorder used. " "Valid values: none, " SUPPORTED_TIMELINE_RECORDERS) DEFINE_FLAG(bool, intern_strings_when_writing_perfetto_timeline, false, "Intern strings when writing timeline in perfetto format.") // Implementation notes: // // Writing events: // |TimelineEvent|s are written into |TimelineEventBlock|s. Each |Thread| caches // a |TimelineEventBlock| object so that it can write events without // synchronizing with other threads in the system. Even though the |Thread| owns // the |TimelineEventBlock| the block may need to be reclaimed by the reporting // system. To support that, a |Thread| must hold its |timeline_block_lock_| // when operating on the |TimelineEventBlock|. This lock will only ever be // busy if blocks are being reclaimed by the reporting system. // // Reporting: // When requested, the timeline is serialized in either Chrome's JSON trace // format (https://goo.gl/hDZw5M) or Perfetto's proto trace format. In both // cases, it may be that a thread has a |TimelineEventBlock| cached in TLS // partially filled with events. In order to report a complete timeline, the // cached |TimelineEventBlock|s need to be reclaimed. // // Reclaiming open |TimelineEventBlock|s from threads: // // Each |Thread| can have one |TimelineEventBlock| cached in it. // // To reclaim blocks, we iterate over all threads and remove the cached // |TimelineEventBlock| from each thread. This is safe because we hold the // |Thread|'s |timeline_block_lock_| meaning the block can't be being modified. // When clearing the reclaimed blocks, or serializing the events in them, we // hold |TimelineEventRecorder::lock_| before reclaiming the blocks, to prevent // reclaimed blocks from being handed out again until we release it. // // Locking notes: // The following locks are used by the timeline system: // - |TimelineEventRecorder::lock_| This lock is held whenever a // |TimelineEventBlock| is being requested or reclaimed. // - |Thread::timeline_block_lock_| This lock is held whenever a |Thread|'s // cached block is being operated on. // - |Thread::thread_list_lock_| This lock is held when iterating over // |Thread|s. // // Locks must always be taken in the following order: // |Thread::thread_list_lock_| // |TimelineEventRecorder::lock_| // |Thread::timeline_block_lock_| // std::atomic RecorderSynchronizationLock::recorder_state_ = { RecorderSynchronizationLock::kUninitialized}; std::atomic RecorderSynchronizationLock::outstanding_event_writes_ = { 0}; static TimelineEventRecorder* CreateDefaultTimelineRecorder() { #if defined(PRODUCT) return new TimelineEventNopRecorder(); #else return new TimelineEventRingRecorder(); #endif } static TimelineEventRecorder* CreateSystraceTimelineRecorder() { #if defined(DART_HOST_OS_LINUX) || defined(DART_HOST_OS_ANDROID) return new TimelineEventSystraceRecorder(); #elif defined(DART_HOST_OS_MACOS) return new TimelineEventMacosRecorder(); #elif defined(DART_HOST_OS_FUCHSIA) return new TimelineEventFuchsiaRecorder(); #else return nullptr; #endif } #if defined(SUPPORT_PERFETTO) static TimelineEventRecorder* CreateTimelineEventPerfettoFileRecorder( const char* filename, bool intern_strings, const char** error); #endif static TimelineEventRecorder* CreateTimelineRecorder() { ASSERT(FLAG_timeline_recorder != nullptr); const char* flag = FLAG_timeline_recorder; if (FLAG_systrace_timeline) { OS::PrintErr( "Warning: the --systrace-timeline flag is deprecated and will " "be removed in Dart SDK v3.4. Please use --timeline-recorder=systrace " "instead.\n"); flag = "systrace"; } else if (FLAG_timeline_dir != nullptr || FLAG_complete_timeline) { // Some flags require that we use the endless recorder. flag = "endless"; } else if (FLAG_startup_timeline) { flag = "startup"; } if (strcmp("none", flag) == 0) { return new TimelineEventNopRecorder(); } // Systrace recorder. if (strcmp("systrace", flag) == 0) { const auto recorder = CreateSystraceTimelineRecorder(); if (recorder != nullptr) { return recorder; } // Fall-through to emit a warning about unsupported recorder. } if (Utils::StrStartsWith(flag, "file") && (flag[4] == '\0' || flag[4] == ':' || flag[4] == '=')) { const char* filename = flag[4] == '\0' ? "dart-timeline.json" : &flag[5]; free(const_cast(FLAG_timeline_dir)); FLAG_timeline_dir = nullptr; const char* error = nullptr; void* file = TimelineEventFileRecorderBase::OpenTimelineFileForWriting( filename, &error); if (file != nullptr) { return new TimelineEventFileRecorder(file); } OS::PrintErr( "Warning: failed to initialize file timeline recorder %s: %s\n", filename, error); return CreateDefaultTimelineRecorder(); } if (strcmp("callback", flag) == 0) { return new TimelineEventEmbedderCallbackRecorder(); } #if defined(SUPPORT_PERFETTO) { const intptr_t kPrefixLength = 12; if (Utils::StrStartsWith(flag, "perfettofile") && (flag[kPrefixLength] == '\0' || flag[kPrefixLength] == ':' || flag[kPrefixLength] == '=')) { const char* filename = flag[kPrefixLength] == '\0' ? "dart.perfetto-trace" : &flag[kPrefixLength + 1]; free(const_cast(FLAG_timeline_dir)); FLAG_timeline_dir = nullptr; const char* error = nullptr; auto recorder = CreateTimelineEventPerfettoFileRecorder( filename, FLAG_intern_strings_when_writing_perfetto_timeline, &error); if (recorder != nullptr) { return recorder; } OS::PrintErr( "Warning: failed to initialize perfetto file timeline recorder %s: " "%s\n", filename, error); return CreateDefaultTimelineRecorder(); } } #endif // defined(SUPPORT_PERFETTO) #if !defined(PRODUCT) // Recorders below do nothing useful in PRODUCT mode. You can't extract // information available in them without vm-service. if (strcmp("endless", flag) == 0) { return new TimelineEventEndlessRecorder(); } if (strcmp("startup", flag) == 0) { return new TimelineEventStartupRecorder(); } if (strcmp("ring", flag) == 0) { return new TimelineEventRingRecorder(); } #endif // !defined(PRODUCT) if (strlen(flag) > 0 && strcmp(flag, DEFAULT_TIMELINE_RECORDER) != 0) { OS::PrintErr( "Warning: requested %s timeline recorder which is not supported, " "defaulting to the " DEFAULT_TIMELINE_RECORDER " recorder\n", flag); } return CreateDefaultTimelineRecorder(); } // Returns a caller freed array of stream names in streams. static MallocGrowableArray* GetEnabledByDefaultTimelineStreams( const char* timeline_streams) { MallocGrowableArray* result = new MallocGrowableArray(); if (timeline_streams == nullptr) { // Nothing set. return result; } char* save_ptr; // Needed for strtok_r. // strtok modifies arg 1 so we make a copy of it. char* streams = Utils::StrDup(timeline_streams); char* token = strtok_r(streams, ",", &save_ptr); while (token != nullptr) { result->Add(Utils::StrDup(token)); token = strtok_r(nullptr, ",", &save_ptr); } free(streams); return result; } // Frees the result of |GetEnabledByDefaultTimelineStreams|. static void FreeEnabledByDefaultTimelineStreams( MallocGrowableArray* streams) { if (streams == nullptr) { return; } for (intptr_t i = 0; i < streams->length(); i++) { free((*streams)[i]); } delete streams; } // Returns true if |streams| contains |stream| or "all". Not case sensitive. static bool HasStream(MallocGrowableArray* streams, const char* stream) { if ((FLAG_timeline_dir != nullptr) || FLAG_complete_timeline || FLAG_startup_timeline) { return true; } for (intptr_t i = 0; i < streams->length(); i++) { const char* checked_stream = (*streams)[i]; if ((strstr(checked_stream, "all") != nullptr) || (strstr(checked_stream, stream) != nullptr)) { return true; } } return false; } void Timeline::Init() { InitWithRecorder(CreateTimelineRecorder(), FLAG_timeline_streams); } void Timeline::InitWithRecorder(TimelineEventRecorder* recorder, const char* timeline_streams) { ASSERT(recorder_ == nullptr); recorder_ = recorder; RecorderSynchronizationLock::Init(); // The following is needed to backfill information about any |OSThread|s that // were initialized before this point. OSThreadIterator it; while (it.HasNext()) { OSThread& thread = *it.Next(); recorder_->AddTrackMetadataBasedOnThread( OS::ProcessId(), OSThread::ThreadIdToIntPtr(thread.trace_id()), thread.name()); } if (FLAG_trace_timeline) { OS::PrintErr("Using the %s timeline recorder.\n", recorder_->name()); } ASSERT(recorder_ != nullptr); enabled_streams_ = GetEnabledByDefaultTimelineStreams(timeline_streams); // Global overrides. #define TIMELINE_STREAM_FLAG_DEFAULT(name, ...) \ stream_##name##_.set_enabled(HasStream(enabled_streams_, #name)); TIMELINE_STREAM_LIST(TIMELINE_STREAM_FLAG_DEFAULT) #undef TIMELINE_STREAM_FLAG_DEFAULT } void Timeline::Cleanup() { ASSERT(recorder_ != nullptr); #ifndef PRODUCT if (FLAG_timeline_dir != nullptr) { recorder_->WriteTo(FLAG_timeline_dir); } #endif // Disable global streams. #define TIMELINE_STREAM_DISABLE(name, ...) \ Timeline::stream_##name##_.set_enabled(false); TIMELINE_STREAM_LIST(TIMELINE_STREAM_DISABLE) #undef TIMELINE_STREAM_DISABLE RecorderSynchronizationLock::WaitForShutdown(); Timeline::Clear(); delete recorder_; recorder_ = nullptr; if (enabled_streams_ != nullptr) { FreeEnabledByDefaultTimelineStreams(enabled_streams_); enabled_streams_ = nullptr; } } void Timeline::ReclaimCachedBlocksFromThreads(OSThreadIterator* it) { RecorderSynchronizationLockScope ls; TimelineEventRecorder* recorder = Timeline::recorder(); if (recorder == nullptr || ls.IsUninitialized()) { return; } ASSERT(recorder != nullptr); // Iterate over threads. while (it->HasNext()) { OSThread* thread = it->Next(); MutexLocker ml(thread->timeline_block_lock()); // Grab block and clear it. TimelineEventBlock* block = thread->TimelineBlockLocked(); thread->SetTimelineBlockLocked(nullptr); recorder->FinishBlock(block); } } #ifndef PRODUCT void Timeline::PrintFlagsToJSONArray(JSONArray* arr) { #define ADD_RECORDED_STREAM_NAME(name, ...) \ if (stream_##name##_.enabled()) { \ arr->AddValue(#name); \ } TIMELINE_STREAM_LIST(ADD_RECORDED_STREAM_NAME); #undef ADD_RECORDED_STREAM_NAME } void Timeline::PrintFlagsToJSON(JSONStream* js) { JSONObject obj(js); obj.AddProperty("type", "TimelineFlags"); RecorderSynchronizationLockScope ls; TimelineEventRecorder* recorder = Timeline::recorder(); if (recorder == nullptr || !ls.IsActive()) { obj.AddProperty("recorderName", "null"); } else { obj.AddProperty("recorderName", recorder->name()); } { JSONArray availableStreams(&obj, "availableStreams"); #define ADD_STREAM_NAME(name, ...) availableStreams.AddValue(#name); TIMELINE_STREAM_LIST(ADD_STREAM_NAME); #undef ADD_STREAM_NAME } { JSONArray recordedStreams(&obj, "recordedStreams"); #define ADD_RECORDED_STREAM_NAME(name, ...) \ if (stream_##name##_.enabled()) { \ recordedStreams.AddValue(#name); \ } TIMELINE_STREAM_LIST(ADD_RECORDED_STREAM_NAME); #undef ADD_RECORDED_STREAM_NAME } } #endif void Timeline::Clear() { RecorderSynchronizationLockScope ls; TimelineEventRecorder* recorder = Timeline::recorder(); if (recorder == nullptr || ls.IsUninitialized()) { return; } ASSERT(recorder != nullptr); // Acquire the recorder's lock to prevent the reclaimed blocks from being // handed out again until they have been cleared. OSThreadIterator it; MutexLocker ml(&recorder->lock_); ReclaimCachedBlocksFromThreads(&it); recorder->ClearLocked(); } void TimelineEventArguments::SetNumArguments(intptr_t length) { if (length == length_) { return; } if (length == 0) { Free(); return; } if (buffer_ == nullptr) { // calloc already nullifies buffer_ = reinterpret_cast( calloc(sizeof(TimelineEventArgument), length)); } else { for (intptr_t i = length; i < length_; ++i) { free(buffer_[i].value); buffer_[i].value = nullptr; buffer_[i].name = nullptr; } buffer_ = reinterpret_cast( realloc(buffer_, sizeof(TimelineEventArgument) * length)); if (length > length_) { memset(buffer_ + length_, 0, sizeof(TimelineEventArgument) * (length - length_)); } } length_ = length; } void TimelineEventArguments::SetArgument(intptr_t i, const char* name, char* argument) { ASSERT(i >= 0); ASSERT(i < length_); buffer_[i].name = name; buffer_[i].value = argument; } void TimelineEventArguments::CopyArgument(intptr_t i, const char* name, const char* argument) { SetArgument(i, name, Utils::StrDup(argument)); } void TimelineEventArguments::FormatArgument(intptr_t i, const char* name, const char* fmt, va_list args) { ASSERT(i >= 0); ASSERT(i < length_); va_list measure_args; va_copy(measure_args, args); intptr_t len = Utils::VSNPrint(nullptr, 0, fmt, measure_args); va_end(measure_args); char* buffer = reinterpret_cast(malloc(len + 1)); va_list print_args; va_copy(print_args, args); Utils::VSNPrint(buffer, (len + 1), fmt, print_args); va_end(print_args); SetArgument(i, name, buffer); } void TimelineEventArguments::StealArguments(TimelineEventArguments* arguments) { Free(); length_ = arguments->length_; buffer_ = arguments->buffer_; arguments->length_ = 0; arguments->buffer_ = nullptr; } void TimelineEventArguments::Free() { if (buffer_ == nullptr) { return; } for (intptr_t i = 0; i < length_; i++) { free(buffer_[i].value); } free(buffer_); buffer_ = nullptr; length_ = 0; } TimelineEventRecorder* Timeline::recorder_ = nullptr; Dart_TimelineRecorderCallback Timeline::callback_ = nullptr; MallocGrowableArray* Timeline::enabled_streams_ = nullptr; bool Timeline::recorder_discards_clock_values_ = false; static std::atomic is_streaming_timeline{false}; static RelaxedAtomic streaming_start_micros = 0; static RelaxedAtomic streaming_stop_micros = kMaxInt64; #define TIMELINE_STREAM_DEFINE(name, fuchsia_name, static_labels) \ TimelineStream Timeline::stream_##name##_(#name, fuchsia_name, \ static_labels, false); TIMELINE_STREAM_LIST(TIMELINE_STREAM_DEFINE) #undef TIMELINE_STREAM_DEFINE TimelineEvent::TimelineEvent() : timestamp0_(0), timestamp1_or_id_(0), flow_id_count_(0), flow_ids_(), state_(0), label_(nullptr), stream_(nullptr), thread_(OSThread::kInvalidThreadId), isolate_id_(ILLEGAL_ISOLATE_ID), isolate_group_id_(ILLEGAL_ISOLATE_GROUP_ID) {} TimelineEvent::~TimelineEvent() { Reset(); } void TimelineEvent::Reset() { timestamp0_ = 0; timestamp1_or_id_ = 0; flow_id_count_ = 0; flow_ids_.reset(); if (owns_label() && label_ != nullptr) { free(const_cast(label_)); } label_ = nullptr; stream_ = nullptr; thread_ = OSThread::kInvalidThreadId; isolate_id_ = ILLEGAL_ISOLATE_ID; isolate_group_id_ = ILLEGAL_ISOLATE_GROUP_ID; arguments_.Free(); state_ = 0; } void TimelineEvent::AsyncBegin(const char* label, int64_t async_id, int64_t micros) { Init(kAsyncBegin, label); set_timestamp0(micros); // Overload timestamp1_ with the async_id. set_timestamp1_or_id(async_id); } void TimelineEvent::AsyncInstant(const char* label, int64_t async_id, int64_t micros) { Init(kAsyncInstant, label); set_timestamp0(micros); // Overload timestamp1_ with the async_id. set_timestamp1_or_id(async_id); } void TimelineEvent::AsyncEnd(const char* label, int64_t async_id, int64_t micros) { Init(kAsyncEnd, label); set_timestamp0(micros); // Overload timestamp1_ with the async_id. set_timestamp1_or_id(async_id); } void TimelineEvent::DurationBegin(const char* label, int64_t micros) { Init(kDuration, label); set_timestamp0(micros); } void TimelineEvent::Instant(const char* label, int64_t micros) { Init(kInstant, label); set_timestamp0(micros); } void TimelineEvent::Duration(const char* label, int64_t start_micros, int64_t end_micros) { Init(kDuration, label); set_timestamp0(start_micros); set_timestamp1_or_id(end_micros); } void TimelineEvent::Begin(const char* label, int64_t id, int64_t micros) { Init(kBegin, label); set_timestamp0(micros); // Overload timestamp1_ with the event ID. This is required for the MacOS // recorder to work. set_timestamp1_or_id(id); } void TimelineEvent::End(const char* label, int64_t id, int64_t micros) { Init(kEnd, label); set_timestamp0(micros); // Overload timestamp1_ with the event ID. This is required for the MacOS // recorder to work. set_timestamp1_or_id(id); } void TimelineEvent::Counter(const char* label, int64_t micros) { Init(kCounter, label); set_timestamp0(micros); } void TimelineEvent::FlowBegin(const char* label, int64_t id, int64_t micros) { Init(kFlowBegin, label); set_timestamp0(micros); // Overload timestamp1_ with the flow ID. set_timestamp1_or_id(id); } void TimelineEvent::FlowStep(const char* label, int64_t id, int64_t micros) { Init(kFlowStep, label); set_timestamp0(micros); // Overload timestamp1_ with the flow ID. set_timestamp1_or_id(id); } void TimelineEvent::FlowEnd(const char* label, int64_t id, int64_t micros) { Init(kFlowEnd, label); set_timestamp0(micros); // Overload timestamp1_ with the flow ID. set_timestamp1_or_id(id); } void TimelineEvent::Metadata(const char* label, int64_t micros) { Init(kMetadata, label); set_timestamp0(micros); } void TimelineEvent::CompleteWithPreSerializedArgs(char* args_json) { set_pre_serialized_args(true); SetNumArguments(1); SetArgument(0, "Dart Arguments", args_json); Complete(); } void TimelineEvent::FormatArgument(intptr_t i, const char* name, const char* fmt, ...) { va_list args; va_start(args, fmt); arguments_.FormatArgument(i, name, fmt, args); va_end(args); } void TimelineEvent::Complete() { TimelineEventRecorder* recorder = Timeline::recorder(); recorder->CompleteEvent(this); // Paired with |RecorderSynchronizationLock::EnterLock()| in // |TimelineStream::StartEvent()|. RecorderSynchronizationLock::ExitLock(); } void TimelineEvent::Init(EventType event_type, const char* label) { ASSERT(label != nullptr); state_ = 0; timestamp0_ = 0; timestamp1_or_id_ = 0; flow_id_count_ = 0; flow_ids_.reset(); OSThread* os_thread = OSThread::Current(); ASSERT(os_thread != nullptr); thread_ = os_thread->trace_id(); auto thread = Thread::Current(); auto isolate = thread != nullptr ? thread->isolate() : nullptr; auto isolate_group = thread != nullptr ? thread->isolate_group() : nullptr; isolate_id_ = (isolate != nullptr) ? isolate->main_port() : ILLEGAL_PORT; isolate_group_id_ = (isolate_group != nullptr) ? isolate_group->id() : 0; isolate_data_ = (isolate != nullptr) ? isolate->init_callback_data() : nullptr; isolate_group_data_ = (isolate_group != nullptr) ? isolate_group->embedder_data() : nullptr; label_ = label; arguments_.Free(); set_event_type(event_type); set_pre_serialized_args(false); set_owns_label(false); } bool TimelineEvent::Within(int64_t time_origin_micros, int64_t time_extent_micros) const { if ((time_origin_micros == -1) || (time_extent_micros == -1)) { // No time range specified. return true; } if (IsFinishedDuration()) { // Event is from e_t0 to e_t1. int64_t e_t0 = TimeOrigin(); int64_t e_t1 = TimeEnd(); ASSERT(e_t0 <= e_t1); // Range is from r_t0 to r_t1. int64_t r_t0 = time_origin_micros; int64_t r_t1 = time_origin_micros + time_extent_micros; ASSERT(r_t0 <= r_t1); return !((r_t1 < e_t0) || (e_t1 < r_t0)); } int64_t delta = TimeOrigin() - time_origin_micros; return (delta >= 0) && (delta <= time_extent_micros); } #ifndef PRODUCT void TimelineEvent::PrintJSON(JSONStream* stream) const { PrintJSON(stream->writer()); } #endif void TimelineEvent::PrintJSON(JSONWriter* writer) const { writer->OpenObject(); int64_t pid = OS::ProcessId(); int64_t tid = OSThread::ThreadIdToIntPtr(thread_); writer->PrintProperty("name", label_); writer->PrintProperty("cat", stream_ != nullptr ? stream_->name() : nullptr); writer->PrintProperty64("tid", tid); writer->PrintProperty64("pid", pid); writer->PrintProperty64("ts", TimeOrigin()); switch (event_type()) { case kBegin: { writer->PrintProperty("ph", "B"); } break; case kEnd: { writer->PrintProperty("ph", "E"); } break; case kDuration: { writer->PrintProperty("ph", "X"); writer->PrintProperty64("dur", TimeDuration()); } break; case kInstant: { writer->PrintProperty("ph", "i"); writer->PrintProperty("s", "p"); } break; case kAsyncBegin: { writer->PrintProperty("ph", "b"); writer->PrintfProperty("id", "%" Px64 "", Id()); } break; case kAsyncInstant: { writer->PrintProperty("ph", "n"); writer->PrintfProperty("id", "%" Px64 "", Id()); } break; case kAsyncEnd: { writer->PrintProperty("ph", "e"); writer->PrintfProperty("id", "%" Px64 "", Id()); } break; case kCounter: { writer->PrintProperty("ph", "C"); } break; case kFlowBegin: { writer->PrintProperty("ph", "s"); writer->PrintfProperty("id", "%" Px64 "", Id()); } break; case kFlowStep: { writer->PrintProperty("ph", "t"); writer->PrintfProperty("id", "%" Px64 "", Id()); } break; case kFlowEnd: { writer->PrintProperty("ph", "f"); writer->PrintProperty("bp", "e"); writer->PrintfProperty("id", "%" Px64 "", Id()); } break; case kMetadata: { writer->PrintProperty("ph", "M"); } break; default: UNIMPLEMENTED(); } if (ArgsArePreSerialized()) { ASSERT(arguments_.length() == 1); writer->AppendSerializedObject("args", arguments_[0].value); if (HasIsolateId()) { writer->UncloseObject(); writer->PrintfProperty("isolateId", ISOLATE_SERVICE_ID_FORMAT_STRING, static_cast(isolate_id_)); writer->CloseObject(); } if (HasIsolateGroupId()) { writer->UncloseObject(); writer->PrintfProperty("isolateGroupId", ISOLATE_GROUP_SERVICE_ID_FORMAT_STRING, isolate_group_id_); writer->CloseObject(); } else { ASSERT(isolate_group_id_ == ILLEGAL_PORT); } } else { writer->OpenObject("args"); for (intptr_t i = 0; i < arguments_.length(); i++) { const TimelineEventArgument& arg = arguments_[i]; writer->PrintProperty(arg.name, arg.value); } if (HasIsolateId()) { writer->PrintfProperty("isolateId", ISOLATE_SERVICE_ID_FORMAT_STRING, static_cast(isolate_id_)); } if (HasIsolateGroupId()) { writer->PrintfProperty("isolateGroupId", ISOLATE_GROUP_SERVICE_ID_FORMAT_STRING, isolate_group_id_); } else { ASSERT(isolate_group_id_ == ILLEGAL_PORT); } writer->CloseObject(); } writer->CloseObject(); } #if defined(SUPPORT_PERFETTO) namespace { class TracePacketWriter : public ValueObject { public: using TracePacket = perfetto::protos::pbzero::TracePacket; using TrackEvent = perfetto::protos::pbzero::TrackEvent; using WriteCallback = std::function&)>; TracePacketWriter(protozero::HeapBuffered& packet, WriteCallback&& write_callback, bool intern_strings) : packet_(packet), write_callback_(std::move(write_callback)), intern_strings_(intern_strings) {} // Converting contents of the given |TimelineEvent| into one or more // Perfetto packets and write them out using |write_callback_| which // was specified when this writer was constructed. // // It uses scratch |packet_| which is reset after it is written out. void WriteEvent(const TimelineEvent& event) { if (!CanBeRepresented(event.event_type())) { return; } if (event.IsDuration()) { // Duration events must be converted to pairs of begin and end events to // be serialized in Perfetto's format. PopulateAndWritePacket(TimelineEvent::kBegin, event.TimeOrigin(), event); PopulateAndWritePacket(TimelineEvent::kEnd, event.TimeEnd(), event); } else { PopulateAndWritePacket(event.event_type(), event.TimeOrigin(), event); } } perfetto_utils::InternedDataBuilder& interned_data_builder() { return interned_data_builder_; } private: static TrackEvent::Type ToPerfettoType(TimelineEvent::EventType event_type) { switch (event_type) { case TimelineEvent::kAsyncBegin: case TimelineEvent::kBegin: return TrackEvent::Type::TYPE_SLICE_BEGIN; case TimelineEvent::kAsyncInstant: case TimelineEvent::kInstant: return TrackEvent::Type::TYPE_INSTANT; case TimelineEvent::kAsyncEnd: case TimelineEvent::kEnd: return TrackEvent::Type::TYPE_SLICE_END; default: return TrackEvent::Type::TYPE_UNSPECIFIED; } } static bool IsSync(TimelineEvent::EventType event_type) { switch (event_type) { case TimelineEvent::kBegin: case TimelineEvent::kInstant: case TimelineEvent::kEnd: return true; default: return false; } } static bool CanBeRepresented(TimelineEvent::EventType event_type) { return event_type == TimelineEvent::kDuration || ToPerfettoType(event_type) != TrackEvent::Type::TYPE_UNSPECIFIED; } void PopulateAndWritePacket(TimelineEvent::EventType event_type, int64_t timestamp, const TimelineEvent& event) { PopulatePacket(event_type, timestamp, event); interned_data_builder_.AttachInternedDataTo(packet_.get()); write_callback_(packet_); packet_.Reset(); } void PopulatePacket(TimelineEvent::EventType event_type, int64_t timestamp, const TimelineEvent& event) { ASSERT(event_type == event.event_type() || (event.IsDuration() && (event_type == TimelineEvent::kBegin || event_type == TimelineEvent::kEnd))); perfetto_utils::SetTrustedPacketSequenceId(packet_.get()); perfetto_utils::SetTimestampAndMonotonicClockId(packet_.get(), timestamp); TrackEvent* track_event = packet_->set_track_event(); SetTrackEventCategory(track_event, event.stream()->name()); track_event->set_track_uuid(IsSync(event_type) ? OSThread::ThreadIdToIntPtr(event.thread()) : event.Id()); const auto perfetto_type = ToPerfettoType(event_type); track_event->set_type(perfetto_type); if (perfetto_type != TrackEvent::Type::TYPE_SLICE_END) { SetTrackEventName(track_event, event.label()); for (intptr_t i = 0; i < event.flow_id_count(); ++i) { // TODO(derekx): |TrackEvent|s have a |terminating_flow_ids| field that // we aren't able to populate right now because we aren't keeping track // of terminating flow IDs in |TimelineEvent|. I'm not even sure if // using that field will provide any benefit though. track_event->add_flow_ids(event.FlowIds()[i]); } } AddDebugAnnotations(track_event, event); } void AddDebugAnnotations(TrackEvent* track_event, const TimelineEvent& event) { if (event.GetNumArguments() > 0) { if (event.ArgsArePreSerialized()) { ASSERT(event.GetNumArguments() == 1); perfetto::protos::pbzero::DebugAnnotation& debug_annotation = *track_event->add_debug_annotations(); SetDebugAnnotationName(debug_annotation, event.arguments()[0].name); debug_annotation.set_legacy_json_value(event.arguments()[0].value); } else { for (intptr_t i = 0; i < event.GetNumArguments(); ++i) { perfetto::protos::pbzero::DebugAnnotation& debug_annotation = *track_event->add_debug_annotations(); SetDebugAnnotationName(debug_annotation, event.arguments()[i].name); SetDebugAnnotationStringValue(debug_annotation, event.arguments()[i].value); } } } if (event.HasIsolateId()) { perfetto::protos::pbzero::DebugAnnotation& debug_annotation = *track_event->add_debug_annotations(); SetDebugAnnotationName(debug_annotation, "isolateId", [this](auto name) { return interned_data_builder_.iid_isolateId(); }); SetDebugAnnotationStringValueFromFormattedId( debug_annotation, ISOLATE_SERVICE_ID_FORMAT_STRING, event.isolate_id(), [this](auto id) { return interned_data_builder_.InternFormattedIsolateId(id); }); } if (event.HasIsolateGroupId()) { perfetto::protos::pbzero::DebugAnnotation& debug_annotation = *track_event->add_debug_annotations(); SetDebugAnnotationName( debug_annotation, "isolateGroupId", [this](auto name) { return interned_data_builder_.iid_isolateGroupId(); }); SetDebugAnnotationStringValueFromFormattedId( debug_annotation, ISOLATE_GROUP_SERVICE_ID_FORMAT_STRING, event.isolate_group_id(), [this](auto id) { return interned_data_builder_.InternFormattedIsolateGroupId(id); }); } } // Helpers for setting string valued properties on |TrackEvent| and // |DebugAnnotation|, these can use interning if |intern_strings_| is // |true|. void SetTrackEventCategory(TrackEvent* track_event, const char* value) { if (intern_strings_) { track_event->add_category_iids( interned_data_builder_.event_categories().Intern(value)); } else { track_event->add_categories(value); } } void SetTrackEventName(TrackEvent* track_event, const char* value) { if (intern_strings_) { track_event->set_name_iid( interned_data_builder_.event_names().Intern(value)); } else { track_event->set_name(value); } } template void SetDebugAnnotationName( perfetto::protos::pbzero::DebugAnnotation& debug_annotation, const char* name, F&& intern) { if (intern_strings_) { debug_annotation.set_name_iid(intern(name)); } else { debug_annotation.set_name(name); } } void SetDebugAnnotationName( perfetto::protos::pbzero::DebugAnnotation& debug_annotation, const char* name) { SetDebugAnnotationName(debug_annotation, name, [this](auto name) { return interned_data_builder_.debug_annotation_names().Intern(name); }); } void SetDebugAnnotationStringValue( perfetto::protos::pbzero::DebugAnnotation& debug_annotation, const char* value) { if (intern_strings_) { debug_annotation.set_string_value_iid( interned_data_builder_.debug_annotation_string_values().Intern( value)); } else { debug_annotation.set_string_value(value); } } template void SetDebugAnnotationStringValueFromFormattedId( perfetto::protos::pbzero::DebugAnnotation& debug_annotation, const char (&format)[kFormatLen], uint64_t id, F&& intern_id) { if (intern_strings_) { debug_annotation.set_string_value_iid(intern_id(id)); } else { // 20 characters is enough to format any uint64_t (or int64_t) value. char formatted[kFormatLen + 20]; Utils::SNPrint(formatted, ARRAY_SIZE(formatted), format, id); debug_annotation.set_string_value(formatted); } } protozero::HeapBuffered& packet_; WriteCallback write_callback_; const bool intern_strings_; perfetto_utils::InternedDataBuilder interned_data_builder_; DISALLOW_COPY_AND_ASSIGN(TracePacketWriter); }; } // namespace #endif // defined(SUPPORT_PERFETTO) int64_t TimelineEvent::LowTime() const { return timestamp0_; } int64_t TimelineEvent::HighTime() const { if (event_type() == kDuration) { return timestamp1_or_id_; } else { return timestamp0_; } } int64_t TimelineEvent::TimeDuration() const { ASSERT(event_type() == kDuration); if (timestamp1_or_id_ == 0) { // This duration is still open, use current time as end. return OS::GetCurrentMonotonicMicrosForTimeline() - timestamp0_; } return timestamp1_or_id_ - timestamp0_; } bool TimelineEvent::HasIsolateId() const { return isolate_id_ != ILLEGAL_ISOLATE_ID; } bool TimelineEvent::HasIsolateGroupId() const { return isolate_group_id_ != ILLEGAL_ISOLATE_GROUP_ID; } void TimelineEvent::ClearIsolateGroupId() { isolate_group_id_ = ILLEGAL_ISOLATE_GROUP_ID; } TimelineTrackMetadata::TimelineTrackMetadata(intptr_t pid, intptr_t tid, CStringUniquePtr&& track_name) : pid_(pid), tid_(tid), track_name_(std::move(track_name)) {} void TimelineTrackMetadata::set_track_name(CStringUniquePtr&& track_name) { track_name_ = std::move(track_name); } #if !defined(PRODUCT) void TimelineTrackMetadata::PrintJSON(const JSONArray& jsarr_events) const { JSONObject jsobj(&jsarr_events); jsobj.AddProperty("name", "thread_name"); jsobj.AddProperty("ph", "M"); jsobj.AddProperty("pid", pid()); jsobj.AddProperty("tid", tid()); { JSONObject jsobj_args(&jsobj, "args"); jsobj_args.AddPropertyF("name", "%s (%" Pd ")", track_name(), tid()); jsobj_args.AddProperty("mode", "basic"); } } #endif // !defined(PRODUCT) #if defined(SUPPORT_PERFETTO) void TimelineTrackMetadata::PopulateTracePacket( perfetto::protos::pbzero::TracePacket* track_descriptor_packet) const { perfetto_utils::SetTrustedPacketSequenceId(track_descriptor_packet); perfetto::protos::pbzero::TrackDescriptor& track_descriptor = *track_descriptor_packet->set_track_descriptor(); track_descriptor.set_parent_uuid(pid()); track_descriptor.set_uuid(tid()); perfetto::protos::pbzero::ThreadDescriptor& thread_descriptor = *track_descriptor.set_thread(); thread_descriptor.set_pid(pid()); thread_descriptor.set_tid(tid()); thread_descriptor.set_thread_name(track_name()); } AsyncTimelineTrackMetadata::AsyncTimelineTrackMetadata(intptr_t pid, intptr_t async_id) : pid_(pid), async_id_(async_id) {} void AsyncTimelineTrackMetadata::PopulateTracePacket( perfetto::protos::pbzero::TracePacket* track_descriptor_packet) const { perfetto_utils::SetTrustedPacketSequenceId(track_descriptor_packet); perfetto::protos::pbzero::TrackDescriptor& track_descriptor = *track_descriptor_packet->set_track_descriptor(); track_descriptor.set_parent_uuid(pid()); track_descriptor.set_uuid(async_id()); } #endif // defined(SUPPORT_PERFETTO) TimelineStream::TimelineStream(const char* name, const char* fuchsia_name, bool has_static_labels, bool enabled) : name_(name), fuchsia_name_(fuchsia_name), #if defined(DART_HOST_OS_FUCHSIA) enabled_(static_cast(true)) // For generated code. #else enabled_(static_cast(enabled)) #endif { #if defined(DART_HOST_OS_MACOS) macos_log_ = os_log_create("Dart", name); has_static_labels_ = has_static_labels; #endif } TimelineEvent* TimelineStream::StartEvent() { // Paired with |RecorderSynchronizationLock::ExitLock()| in // |TimelineEvent::Complete()|. // // The lock must be held until the event is completed to avoid having the // memory backing the event being freed in the middle of processing the // event. RecorderSynchronizationLock::EnterLock(); TimelineEventRecorder* recorder = Timeline::recorder(); if (!enabled() || (recorder == nullptr) || !RecorderSynchronizationLock::IsActive()) { RecorderSynchronizationLock::ExitLock(); return nullptr; } ASSERT(name_ != nullptr); TimelineEvent* event = recorder->StartEvent(); if (event == nullptr) { RecorderSynchronizationLock::ExitLock(); return nullptr; } event->StreamInit(this); return event; } TimelineEventScope::TimelineEventScope(TimelineStream* stream, const char* label) : StackResource(static_cast(nullptr)), stream_(stream), label_(label), enabled_(false) { Init(); } TimelineEventScope::TimelineEventScope(Thread* thread, TimelineStream* stream, const char* label) : StackResource(thread), stream_(stream), label_(label), enabled_(false) { Init(); } TimelineEventScope::~TimelineEventScope() {} void TimelineEventScope::Init() { ASSERT(enabled_ == false); ASSERT(label_ != nullptr); ASSERT(stream_ != nullptr); if (!stream_->enabled()) { // Stream is not enabled, do nothing. return; } enabled_ = true; Thread* thread = static_cast(this->thread()); if (thread != nullptr) { id_ = thread->GetNextTaskId(); } else { static RelaxedAtomic next_bootstrap_task_id = {0}; id_ = next_bootstrap_task_id.fetch_add(1); } } void TimelineEventScope::SetNumArguments(intptr_t length) { if (!enabled()) { return; } arguments_.SetNumArguments(length); } // |name| must be a compile time constant. Takes ownership of |argumentp|. void TimelineEventScope::SetArgument(intptr_t i, const char* name, char* argument) { if (!enabled()) { return; } arguments_.SetArgument(i, name, argument); } // |name| must be a compile time constant. Copies |argument|. void TimelineEventScope::CopyArgument(intptr_t i, const char* name, const char* argument) { if (!enabled()) { return; } arguments_.CopyArgument(i, name, argument); } void TimelineEventScope::FormatArgument(intptr_t i, const char* name, const char* fmt, ...) { if (!enabled()) { return; } va_list args; va_start(args, fmt); arguments_.FormatArgument(i, name, fmt, args); va_end(args); } void TimelineEventScope::StealArguments(TimelineEvent* event) { if (event == nullptr) { return; } event->StealArguments(&arguments_); } TimelineBeginEndScope::TimelineBeginEndScope(TimelineStream* stream, const char* label) : TimelineEventScope(stream, label) { EmitBegin(); } TimelineBeginEndScope::TimelineBeginEndScope(Thread* thread, TimelineStream* stream, const char* label) : TimelineEventScope(thread, stream, label) { EmitBegin(); } TimelineBeginEndScope::~TimelineBeginEndScope() { EmitEnd(); } void TimelineBeginEndScope::EmitBegin() { if (!ShouldEmitEvent()) { return; } TimelineEvent* event = stream()->StartEvent(); if (event == nullptr) { // Stream is now disabled. set_enabled(false); return; } ASSERT(event != nullptr); // Emit a begin event. event->Begin(label(), id()); event->Complete(); } void TimelineBeginEndScope::EmitEnd() { if (!ShouldEmitEvent()) { return; } TimelineEvent* event = stream()->StartEvent(); if (event == nullptr) { // Stream is now disabled. set_enabled(false); return; } ASSERT(event != nullptr); // Emit an end event. event->End(label(), id()); StealArguments(event); event->Complete(); } bool TimelineEventBlock::InUseLocked() const { ASSERT(Timeline::recorder()->lock_.IsOwnedByCurrentThread()); return in_use_; } bool TimelineEventBlock::ContainsEventsThatCanBeSerializedLocked() const { ASSERT(Timeline::recorder()->lock_.IsOwnedByCurrentThread()); // Check that the block is not in use and not empty. |!block->in_use()| must // be checked first because we are only holding |lock_|. Holding |lock_| // makes it safe to call |in_use()| on any block, but only makes it safe to // call |IsEmpty()| on blocks that are not in use. return !InUseLocked() && !IsEmpty(); } TimelineEventFilter::TimelineEventFilter(int64_t time_origin_micros, int64_t time_extent_micros) : time_origin_micros_(time_origin_micros), time_extent_micros_(time_extent_micros) { ASSERT(time_origin_micros_ >= -1); ASSERT(time_extent_micros_ >= -1); } TimelineEventFilter::~TimelineEventFilter() {} IsolateTimelineEventFilter::IsolateTimelineEventFilter( Dart_Port isolate_id, int64_t time_origin_micros, int64_t time_extent_micros) : TimelineEventFilter(time_origin_micros, time_extent_micros), isolate_id_(isolate_id) {} TimelineEventRecorder::TimelineEventRecorder() : time_low_micros_(0), time_high_micros_(0), track_uuid_to_track_metadata_lock_(), track_uuid_to_track_metadata_( &SimpleHashMap::SamePointerValue, TimelineEventRecorder::kTrackUuidToTrackMetadataInitialCapacity) {} TimelineEventRecorder::~TimelineEventRecorder() { // We do not need to lock the following section, because at this point // |RecorderSynchronizationLock| must have been put in a state that prevents // the metadata maps from being modified. for (SimpleHashMap::Entry* entry = track_uuid_to_track_metadata_.Start(); entry != nullptr; entry = track_uuid_to_track_metadata_.Next(entry)) { TimelineTrackMetadata* value = static_cast(entry->value); delete value; } } #ifndef PRODUCT void TimelineEventRecorder::PrintJSONMeta(const JSONArray& jsarr_events) { MutexLocker ml(&track_uuid_to_track_metadata_lock_); for (SimpleHashMap::Entry* entry = track_uuid_to_track_metadata_.Start(); entry != nullptr; entry = track_uuid_to_track_metadata_.Next(entry)) { TimelineTrackMetadata* value = static_cast(entry->value); value->PrintJSON(jsarr_events); } } #endif // !defined(PRODUCT) TimelineEvent* TimelineEventRecorder::ThreadBlockStartEvent() { // Grab the current thread. OSThread* thread = OSThread::Current(); ASSERT(thread != nullptr); // Acquire the recorder lock in case we need to call |GetNewBlockLocked|. We // acquire the lock here and not directly before calls to |GetNewBlockLocked| // due to locking order restrictions. Mutex& recorder_lock = lock_; recorder_lock.Lock(); Mutex* thread_block_lock = thread->timeline_block_lock(); ASSERT(thread_block_lock != nullptr); // We are accessing the thread's timeline block- so take the lock here. // This lock will be held until the call to |CompleteEvent| is made. thread_block_lock->Lock(); #if defined(DEBUG) Thread* T = Thread::Current(); if (T != nullptr) { T->IncrementNoSafepointScopeDepth(); } #endif // defined(DEBUG) TimelineEventBlock* thread_block = thread->TimelineBlockLocked(); if ((thread_block != nullptr) && thread_block->IsFull()) { // Thread has a block and it is full: // 1) Mark it as finished. thread->SetTimelineBlockLocked(nullptr); FinishBlock(thread_block); // 2) Allocate a new block. // We release |thread_block_lock| before calling |GetNewBlockLocked| to // avoid TSAN warnings about lock order inversion. thread_block_lock->Unlock(); thread_block = GetNewBlockLocked(); thread_block_lock->Lock(); thread->SetTimelineBlockLocked(thread_block); } else if (thread_block == nullptr) { // Thread has no block. Attempt to allocate one. // We release |thread_block_lock| before calling |GetNewBlockLocked| to // avoid TSAN warnings about lock order inversion. thread_block_lock->Unlock(); thread_block = GetNewBlockLocked(); thread_block_lock->Lock(); thread->SetTimelineBlockLocked(thread_block); } recorder_lock.Unlock(); if (thread_block != nullptr) { // NOTE: We are exiting this function with the thread's block lock held. ASSERT(!thread_block->IsFull()); TimelineEvent* event = thread_block->StartEventLocked(); return event; } // Drop lock here as no event is being handed out. #if defined(DEBUG) if (T != nullptr) { T->DecrementNoSafepointScopeDepth(); } #endif // defined(DEBUG) thread_block_lock->Unlock(); return nullptr; } void TimelineEventRecorder::ResetTimeTracking() { time_high_micros_ = 0; time_low_micros_ = kMaxInt64; } void TimelineEventRecorder::ReportTime(int64_t micros) { if (time_high_micros_ < micros) { time_high_micros_ = micros; } if (time_low_micros_ > micros) { time_low_micros_ = micros; } } int64_t TimelineEventRecorder::TimeOriginMicros() const { if (time_high_micros_ == 0) { return 0; } return time_low_micros_; } int64_t TimelineEventRecorder::TimeExtentMicros() const { if (time_high_micros_ == 0) { return 0; } return time_high_micros_ - time_low_micros_; } void TimelineEventRecorder::ThreadBlockCompleteEvent(TimelineEvent* event) { if (event == nullptr) { return; } #if defined(SUPPORT_PERFETTO) // Async track metadata is only written in Perfetto traces, and Perfetto // traces cannot be written when SUPPORT_PERFETTO is not defined. if (event->event_type() == TimelineEvent::kAsyncBegin || event->event_type() == TimelineEvent::kAsyncInstant) { AddAsyncTrackMetadataBasedOnEvent(*event); } #endif // defined(SUPPORT_PERFETTO) // Grab the current thread. OSThread* thread = OSThread::Current(); ASSERT(thread != nullptr); // Unlock the thread's block lock. Mutex* thread_block_lock = thread->timeline_block_lock(); ASSERT(thread_block_lock != nullptr); #if defined(DEBUG) Thread* T = Thread::Current(); if (T != nullptr) { T->DecrementNoSafepointScopeDepth(); } #endif // defined(DEBUG) thread_block_lock->Unlock(); } #ifndef PRODUCT void TimelineEventRecorder::WriteTo(const char* directory) { Dart_FileOpenCallback file_open = Dart::file_open_callback(); Dart_FileWriteCallback file_write = Dart::file_write_callback(); Dart_FileCloseCallback file_close = Dart::file_close_callback(); if ((file_open == nullptr) || (file_write == nullptr) || (file_close == nullptr)) { OS::PrintErr("warning: Could not access file callbacks."); return; } // Acquire the recorder's lock to prevent the reclaimed blocks from being // handed out again until the trace has been serialized. OSThreadIterator it; MutexLocker ml(&lock_); Timeline::ReclaimCachedBlocksFromThreads(&it); intptr_t pid = OS::ProcessId(); char* filename = OS::SCreate(nullptr, "%s/dart-timeline-%" Pd ".json", directory, pid); void* file = (*file_open)(filename, true); if (file == nullptr) { OS::PrintErr("warning: Failed to write timeline file: %s\n", filename); free(filename); return; } free(filename); JSONStream js; TimelineEventFilter filter; PrintTraceEvent(&js, &filter); // Steal output from JSONStream. char* output = nullptr; intptr_t output_length = 0; js.Steal(&output, &output_length); (*file_write)(output, output_length, file); // Free the stolen output. free(output); (*file_close)(file); return; } #endif void TimelineEventRecorder::FinishBlock(TimelineEventBlock* block) { if (block != nullptr) { block->Finish(); } } void TimelineEventRecorder::AddTrackMetadataBasedOnThread( const intptr_t process_id, const intptr_t trace_id, const char* thread_name) { MutexLocker ml(&track_uuid_to_track_metadata_lock_); void* key = reinterpret_cast(trace_id); const intptr_t hash = Utils::WordHash(trace_id); SimpleHashMap::Entry* entry = track_uuid_to_track_metadata_.Lookup(key, hash, true); if (entry->value == nullptr) { entry->value = new TimelineTrackMetadata( process_id, trace_id, CStringUniquePtr( Utils::StrDup(thread_name == nullptr ? "" : thread_name))); } else { TimelineTrackMetadata* value = static_cast(entry->value); ASSERT(process_id == value->pid()); value->set_track_name(CStringUniquePtr( Utils::StrDup(thread_name == nullptr ? "" : thread_name))); } } void TimelineEventRecorder::AddAsyncTrackMetadataBasedOnEvent( const TimelineEvent& event) {} #if defined(SUPPORT_PERFETTO) template template TimelineEventRecorderWithPerfettoSupport< Base>::TimelineEventRecorderWithPerfettoSupport(Args&&... args) : Base(std::forward(args)...), async_track_uuid_to_track_metadata_lock_(), async_track_uuid_to_track_metadata_( &SimpleHashMap::SamePointerValue, TimelineEventRecorder::kTrackUuidToTrackMetadataInitialCapacity) {} template TimelineEventRecorderWithPerfettoSupport< Base>::~TimelineEventRecorderWithPerfettoSupport() { for (SimpleHashMap::Entry* entry = async_track_uuid_to_track_metadata_.Start(); entry != nullptr; entry = async_track_uuid_to_track_metadata_.Next(entry)) { AsyncTimelineTrackMetadata* value = static_cast(entry->value); delete value; } } template void TimelineEventRecorderWithPerfettoSupport< Base>::AddAsyncTrackMetadataBasedOnEvent(const TimelineEvent& event) { MutexLocker ml(&async_track_uuid_to_track_metadata_lock_); void* key = reinterpret_cast(event.Id()); const intptr_t hash = Utils::WordHash(event.Id()); SimpleHashMap::Entry* entry = async_track_uuid_to_track_metadata_.Lookup(key, hash, true); if (entry->value == nullptr) { entry->value = new AsyncTimelineTrackMetadata(OS::ProcessId(), event.Id()); } } template void TimelineEventRecorderWithPerfettoSupport::PrintPerfettoMeta( JSONBase64String* jsonBase64String) { ASSERT(jsonBase64String != nullptr); perfetto_utils::PopulateClockSnapshotPacket(packet_.get()); perfetto_utils::AppendPacketToJSONBase64String(jsonBase64String, &packet_); packet_.Reset(); perfetto_utils::PopulateProcessDescriptorPacket(packet_.get()); perfetto_utils::AppendPacketToJSONBase64String(jsonBase64String, &packet_); packet_.Reset(); { MutexLocker ml(&async_track_uuid_to_track_metadata_lock_); for (SimpleHashMap::Entry* entry = async_track_uuid_to_track_metadata_.Start(); entry != nullptr; entry = async_track_uuid_to_track_metadata_.Next(entry)) { AsyncTimelineTrackMetadata* value = static_cast(entry->value); value->PopulateTracePacket(packet_.get()); perfetto_utils::AppendPacketToJSONBase64String(jsonBase64String, &packet_); packet_.Reset(); } } { MutexLocker ml(&TimelineEventRecorder::track_uuid_to_track_metadata_lock()); for (SimpleHashMap::Entry* entry = TimelineEventRecorder::track_uuid_to_track_metadata().Start(); entry != nullptr; entry = TimelineEventRecorder::track_uuid_to_track_metadata().Next( entry)) { TimelineTrackMetadata* value = static_cast(entry->value); value->PopulateTracePacket(packet_.get()); perfetto_utils::AppendPacketToJSONBase64String(jsonBase64String, &packet_); packet_.Reset(); } } } #endif // defined(SUPPORT_PERFETTO) TimelineEventFixedBufferRecorder::TimelineEventFixedBufferRecorder( intptr_t capacity) : memory_(nullptr), blocks_(nullptr), capacity_(capacity), num_blocks_(0), block_cursor_(0) { // Capacity must be a multiple of TimelineEventBlock::kBlockSize ASSERT((capacity % TimelineEventBlock::kBlockSize) == 0); // Allocate blocks array. num_blocks_ = capacity / TimelineEventBlock::kBlockSize; intptr_t size = Utils::RoundUp(num_blocks_ * sizeof(TimelineEventBlock), VirtualMemory::PageSize()); const bool executable = false; const bool compressed = false; memory_ = VirtualMemory::Allocate(size, executable, compressed, "dart-timeline"); if (memory_ == nullptr) { OUT_OF_MEMORY(); } blocks_ = reinterpret_cast(memory_->address()); } TimelineEventFixedBufferRecorder::~TimelineEventFixedBufferRecorder() { // We do not need to acquire any locks, because at this point we must have // reclaimed all the blocks, and |RecorderSynchronizationLock| must have been // put in a state that prevents blocks from being given out. delete memory_; } intptr_t TimelineEventFixedBufferRecorder::Size() { return memory_->size(); } #ifndef PRODUCT void TimelineEventFixedBufferRecorder::ForEachNonEmptyBlock( std::function&& handle_block) { // Acquire the recorder's lock to prevent the reclaimed blocks from being // handed out again until the trace has been serialized. OSThreadIterator it; MutexLocker ml(&lock_); Timeline::ReclaimCachedBlocksFromThreads(&it); ResetTimeTracking(); intptr_t block_offset = FindOldestBlockIndexLocked(); if (block_offset == -1) { // All blocks are in use or empty. return; } for (intptr_t block_idx = 0; block_idx < num_blocks_; block_idx++) { TimelineEventBlock* block = &blocks_[(block_idx + block_offset) % num_blocks_]; if (!block->ContainsEventsThatCanBeSerializedLocked()) { continue; } handle_block(*block); } } void TimelineEventBufferedRecorder::PrintEventsCommon( const TimelineEventFilter& filter, std::function&& print_impl) { ForEachNonEmptyBlock( [this, &filter, print_impl = std::move(print_impl)](auto& block) { for (intptr_t event_idx = 0, length = block.length(); event_idx < length; event_idx++) { auto event = block.At(event_idx); if (filter.IncludeEvent(event) && event->Within(filter.time_origin_micros(), filter.time_extent_micros())) { ReportTime(event->LowTime()); ReportTime(event->HighTime()); print_impl(*event); } } }); } void TimelineEventBufferedRecorder::PrintJSONEvents( const JSONArray& events, const TimelineEventFilter& filter) { PrintEventsCommon(filter, [&events](const TimelineEvent& event) { events.AddValue(&event); }); } #if defined(SUPPORT_PERFETTO) void TimelineEventBufferedRecorder::PrintPerfettoEvents( JSONBase64String* jsonBase64String, const TimelineEventFilter& filter) { TracePacketWriter writer( packet(), [&jsonBase64String](auto& packet) { perfetto_utils::AppendPacketToJSONBase64String(jsonBase64String, &packet); }, FLAG_intern_strings_when_writing_perfetto_timeline); PrintEventsCommon(filter, [&writer](const TimelineEvent& event) { writer.WriteEvent(event); }); } #endif // defined(SUPPORT_PERFETTO) void TimelineEventBufferedRecorder::PrintJSON(JSONStream* js, TimelineEventFilter* filter) { JSONObject topLevel(js); topLevel.AddProperty("type", "Timeline"); { JSONArray events(&topLevel, "traceEvents"); PrintJSONMeta(events); PrintJSONEvents(events, *filter); } topLevel.AddPropertyTimeMicros("timeOriginMicros", TimeOriginMicros()); topLevel.AddPropertyTimeMicros("timeExtentMicros", TimeExtentMicros()); } #if defined(SUPPORT_PERFETTO) void TimelineEventBufferedRecorder::PrintPerfettoTimeline( JSONStream* js, const TimelineEventFilter& filter) { JSONObject jsobj_topLevel(js); jsobj_topLevel.AddProperty("type", "PerfettoTimeline"); js->AppendSerializedObject("\"trace\":"); { JSONBase64String jsonBase64String(js); PrintPerfettoMeta(&jsonBase64String); PrintPerfettoEvents(&jsonBase64String, filter); } jsobj_topLevel.AddPropertyTimeMicros("timeOriginMicros", TimeOriginMicros()); jsobj_topLevel.AddPropertyTimeMicros("timeExtentMicros", TimeExtentMicros()); } #endif // defined(SUPPORT_PERFETTO) void TimelineEventBufferedRecorder::PrintTraceEvent( JSONStream* js, TimelineEventFilter* filter) { JSONArray events(js); PrintJSONMeta(events); PrintJSONEvents(events, *filter); } #endif // !defined(PRODUCT) void TimelineEventFixedBufferRecorder::ClearLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); for (intptr_t i = 0; i < num_blocks_; i++) { TimelineEventBlock* block = &blocks_[i]; block->Reset(); } } intptr_t TimelineEventFixedBufferRecorder::FindOldestBlockIndexLocked() const { ASSERT(lock_.IsOwnedByCurrentThread()); int64_t earliest_time = kMaxInt64; intptr_t earliest_index = -1; for (intptr_t block_idx = 0; block_idx < num_blocks_; block_idx++) { TimelineEventBlock* block = &blocks_[block_idx]; if (!block->ContainsEventsThatCanBeSerializedLocked()) { // Skip in use and empty blocks. continue; } if (block->LowerTimeBound() < earliest_time) { earliest_time = block->LowerTimeBound(); earliest_index = block_idx; } } return earliest_index; } TimelineEvent* TimelineEventFixedBufferRecorder::StartEvent() { return ThreadBlockStartEvent(); } void TimelineEventFixedBufferRecorder::CompleteEvent(TimelineEvent* event) { if (event == nullptr) { return; } ThreadBlockCompleteEvent(event); } TimelineEventBlock* TimelineEventRingRecorder::GetNewBlockLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); if (block_cursor_ == num_blocks_) { block_cursor_ = 0; } TimelineEventBlock* block = &blocks_[block_cursor_++]; if (block->current_owner_ != nullptr) { MutexLocker ml(block->current_owner_->timeline_block_lock()); block->current_owner_->SetTimelineBlockLocked(nullptr); block->Reset(); block->Open(); } else { block->Reset(); block->Open(); } return block; } TimelineEventBlock* TimelineEventStartupRecorder::GetNewBlockLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); if (block_cursor_ == num_blocks_) { return nullptr; } TimelineEventBlock* block = &blocks_[block_cursor_++]; block->Reset(); block->Open(); return block; } TimelineEventCallbackRecorder::TimelineEventCallbackRecorder() {} TimelineEventCallbackRecorder::~TimelineEventCallbackRecorder() {} #ifndef PRODUCT void TimelineEventCallbackRecorder::PrintJSON(JSONStream* js, TimelineEventFilter* filter) { UNREACHABLE(); } #if defined(SUPPORT_PERFETTO) void TimelineEventCallbackRecorder::PrintPerfettoTimeline( JSONStream* js, const TimelineEventFilter& filter) { UNREACHABLE(); } #endif // defined(SUPPORT_PERFETTO) void TimelineEventCallbackRecorder::PrintTraceEvent( JSONStream* js, TimelineEventFilter* filter) { JSONArray events(js); } #endif // !defined(PRODUCT) TimelineEvent* TimelineEventCallbackRecorder::StartEvent() { TimelineEvent* event = new TimelineEvent(); return event; } void TimelineEventCallbackRecorder::CompleteEvent(TimelineEvent* event) { OnEvent(event); delete event; } void TimelineEventEmbedderCallbackRecorder::OnEvent(TimelineEvent* event) { Dart_TimelineRecorderCallback callback = Timeline::callback(); if (callback == nullptr) { return; } Dart_TimelineRecorderEvent recorder_event; recorder_event.version = DART_TIMELINE_RECORDER_CURRENT_VERSION; switch (event->event_type()) { case TimelineEvent::kBegin: recorder_event.type = Dart_Timeline_Event_Begin; break; case TimelineEvent::kEnd: recorder_event.type = Dart_Timeline_Event_End; break; case TimelineEvent::kInstant: recorder_event.type = Dart_Timeline_Event_Instant; break; case TimelineEvent::kDuration: recorder_event.type = Dart_Timeline_Event_Duration; break; case TimelineEvent::kAsyncBegin: recorder_event.type = Dart_Timeline_Event_Async_Begin; break; case TimelineEvent::kAsyncEnd: recorder_event.type = Dart_Timeline_Event_Async_End; break; case TimelineEvent::kAsyncInstant: recorder_event.type = Dart_Timeline_Event_Async_Instant; break; case TimelineEvent::kCounter: recorder_event.type = Dart_Timeline_Event_Counter; break; case TimelineEvent::kFlowBegin: recorder_event.type = Dart_Timeline_Event_Flow_Begin; break; case TimelineEvent::kFlowStep: recorder_event.type = Dart_Timeline_Event_Flow_Step; break; case TimelineEvent::kFlowEnd: recorder_event.type = Dart_Timeline_Event_Flow_End; break; default: // Type not expressible as Dart_Timeline_Event_Type: drop event. return; } recorder_event.timestamp0 = event->timestamp0(); recorder_event.timestamp1_or_id = event->timestamp1_or_id(); recorder_event.isolate = event->isolate_id(); recorder_event.isolate_group = event->isolate_group_id(); recorder_event.isolate_data = event->isolate_data(); recorder_event.isolate_group_data = event->isolate_group_data(); recorder_event.label = event->label(); recorder_event.stream = event->stream()->name(); recorder_event.argument_count = event->GetNumArguments(); recorder_event.arguments = reinterpret_cast( event->arguments()); NoActiveIsolateScope no_active_isolate_scope; callback(&recorder_event); } void TimelineEventEmbedderCallbackRecorder::AddTrackMetadataBasedOnThread( const intptr_t process_id, const intptr_t trace_id, const char* thread_name) { // This information can not be retrieved or written out in this format. // Do nothing. } void TimelineEventNopRecorder::OnEvent(TimelineEvent* event) { // Do nothing. } void TimelineEventNopRecorder::AddTrackMetadataBasedOnThread( const intptr_t process_id, const intptr_t trace_id, const char* thread_name) { // This information can not be retrieved or written out in this format. // Do nothing. } TimelineEventPlatformRecorder::TimelineEventPlatformRecorder() {} TimelineEventPlatformRecorder::~TimelineEventPlatformRecorder() {} void TimelineEventPlatformRecorder::AddTrackMetadataBasedOnThread( const intptr_t process_id, const intptr_t trace_id, const char* thread_name) { // This information can not be retrieved or written out in this format. // Do nothing. } #ifndef PRODUCT void TimelineEventPlatformRecorder::PrintJSON(JSONStream* js, TimelineEventFilter* filter) { UNREACHABLE(); } #if defined(SUPPORT_PERFETTO) void TimelineEventPlatformRecorder::PrintPerfettoTimeline( JSONStream* js, const TimelineEventFilter& filter) { UNREACHABLE(); } #endif // defined(SUPPORT_PERFETTO) void TimelineEventPlatformRecorder::PrintTraceEvent( JSONStream* js, TimelineEventFilter* filter) { JSONArray events(js); } #endif // !defined(PRODUCT) TimelineEvent* TimelineEventPlatformRecorder::StartEvent() { TimelineEvent* event = new TimelineEvent(); return event; } void TimelineEventPlatformRecorder::CompleteEvent(TimelineEvent* event) { OnEvent(event); delete event; } static void TimelineEventFileRecorderBaseStart(uword parameter) { reinterpret_cast(parameter)->Drain(); } void* TimelineEventFileRecorderBase::OpenTimelineFileForWriting( const char* path, const char** error) { Dart_FileOpenCallback file_open = Dart::file_open_callback(); Dart_FileWriteCallback file_write = Dart::file_write_callback(); Dart_FileCloseCallback file_close = Dart::file_close_callback(); if ((file_open == nullptr) || (file_write == nullptr) || (file_close == nullptr)) { *error = "Could not access file callbacks."; return nullptr; } void* file = (*file_open)(path, true); if (file == nullptr) { *error = "Failed to open timeline file."; return nullptr; } return file; } TimelineEventFileRecorderBase::TimelineEventFileRecorderBase(void* file) : TimelineEventRecorder() { ASSERT(file != nullptr); file_ = file; } TimelineEventFileRecorderBase::~TimelineEventFileRecorderBase() { // WARNING: |ShutDown()| must be called in the derived class destructor. This // work cannot be performed in this destructor, because then |DrainImpl()| // might run between when the derived class destructor completes, and when // |shutting_down_| is set to true, causing possible use-after-free errors. ASSERT(shutting_down_); ASSERT(thread_id_ != OSThread::kInvalidThreadJoinId); OSThread::Join(thread_id_); thread_id_ = OSThread::kInvalidThreadJoinId; // At this point all blocks created by this recorder should be drained // and placed into |empty_blocks_|. Delete all of them. ASSERT(drained_); ASSERT(completed_blocks_head_ == nullptr); ASSERT(completed_blocks_tail_ == nullptr); while (empty_blocks_ != nullptr) { auto block = empty_blocks_; empty_blocks_ = empty_blocks_->next(); delete block; block_count_--; } ASSERT(block_count_ == 0); FlushBuffer(); Dart_FileCloseCallback file_close = Dart::file_close_callback(); (*file_close)(file_); file_ = nullptr; } void TimelineEventFileRecorderBase::Drain() { MonitorLocker ml(&monitor_); thread_id_ = OSThread::GetCurrentThreadJoinId(OSThread::Current()); ml.Notify(); for (;;) { if (completed_blocks_head_ == nullptr) { ASSERT(completed_blocks_tail_ == nullptr); if (shutting_down_) { break; } ml.Wait(); continue; // Recheck empty. } // Take the whole list of pending blocks and drain all of them. auto blocks = completed_blocks_head_; completed_blocks_tail_ = completed_blocks_head_ = nullptr; { MonitorLeaveScope leave_ml(&ml); DrainBlockChain(blocks); } } drained_ = true; ml.Notify(); } void TimelineEventFileRecorderBase::DrainBlockChain(TimelineEventBlock* block) { while (block != nullptr) { auto next_block = block->next(); block->set_next(nullptr); for (intptr_t i = 0, length = block->length(); i < length; i++) { DrainImpl(*block->At(i)); } block->Reset(); // Place block for reuse. { MonitorLocker ml(&monitor_); block->set_next(empty_blocks_); empty_blocks_ = block; } block = next_block; } } void TimelineEventFileRecorderBase::FlushBuffer() { if (buffer_pos_ != 0) { WriteToFile(buffer_.get(), buffer_pos_); buffer_pos_ = 0; } } void TimelineEventFileRecorderBase::Write(const char* bytes, intptr_t length) { if (length >= kBufferSize / 2) { FlushBuffer(); WriteToFile(bytes, length); return; } do { intptr_t space_left = kBufferSize - buffer_pos_; intptr_t bytes_to_write = Utils::Minimum(length, space_left); memcpy(buffer_.get() + buffer_pos_, bytes, bytes_to_write); // NOLINT buffer_pos_ += bytes_to_write; length -= bytes_to_write; bytes += bytes_to_write; if (buffer_pos_ == kBufferSize) { FlushBuffer(); } } while (length > 0); } void TimelineEventFileRecorderBase::WriteToFile(const char* buffer, intptr_t len) const { Dart_FileWriteCallback file_write = Dart::file_write_callback(); (*file_write)(buffer, len, file_); } TimelineEvent* TimelineEventFileRecorderBase::StartEvent() { return ThreadBlockStartEvent(); } void TimelineEventFileRecorderBase::CompleteEvent(TimelineEvent* event) { if (event == nullptr) { return; } ThreadBlockCompleteEvent(event); } void TimelineEventFileRecorderBase::FinishBlock(TimelineEventBlock* block) { TimelineEventRecorder::FinishBlock(block); if (block != nullptr) { // Append completed block to the end of the list of completed blocks. // We want to keep events from the same thread ordered in sequentially // in the output. MonitorLocker ml(&monitor_); block->set_next(nullptr); if (completed_blocks_tail_ != nullptr) { completed_blocks_tail_->set_next(block); completed_blocks_tail_ = block; } else { completed_blocks_head_ = completed_blocks_tail_ = block; } ml.Notify(); } } void TimelineEventFileRecorderBase::StartUp(const char* name) { OSThread::Start(name, TimelineEventFileRecorderBaseStart, reinterpret_cast(this)); MonitorLocker ml(&monitor_); while (thread_id_ == OSThread::kInvalidThreadJoinId) { ml.Wait(); } } // Must be called in derived class destructors. // See |~TimelineEventFileRecorderBase()| for an explanation. void TimelineEventFileRecorderBase::ShutDown() { MonitorLocker ml(&monitor_); shutting_down_ = true; ml.NotifyAll(); while (!drained_) { ml.Wait(); } } TimelineEventBlock* TimelineEventFileRecorderBase::GetNewBlockLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); TimelineEventBlock* block = nullptr; { MonitorLocker ml(&monitor_); if (empty_blocks_ != nullptr) { block = empty_blocks_; empty_blocks_ = empty_blocks_->next(); } } if (block == nullptr) { block = new TimelineEventBlock(block_count_++); if (FLAG_trace_timeline) { OS::PrintErr("Created new block %p\n", block); } } else if (FLAG_trace_timeline) { OS::PrintErr("Reused empty block %p\n", block); } block->Open(); return block; } void TimelineEventFileRecorderBase::ClearLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); } TimelineEventFileRecorder::TimelineEventFileRecorder(void* file) : TimelineEventFileRecorderBase(file), first_(true) { // Chrome trace format has two forms: // Object form: { "traceEvents": [ event, event, event ] } // Array form: [ event, event, event ] // For this recorder, we use the array form because Catapult will handle a // missing ending bracket in this form in case we don't cleanly end the // trace. Write("[\n"); StartUp("TimelineEventFileRecorder"); } TimelineEventFileRecorder::~TimelineEventFileRecorder() { ShutDown(); Write("]\n"); } void TimelineEventFileRecorder::AddTrackMetadataBasedOnThread( const intptr_t process_id, const intptr_t trace_id, const char* thread_name) { TimelineEvent* event = StartEvent(); event->Metadata("thread_name"); event->SetNumArguments(1); event->CopyArgument(0, "name", thread_name); CompleteEvent(event); } void TimelineEventFileRecorder::DrainImpl(const TimelineEvent& event) { JSONWriter writer; if (first_) { first_ = false; } else { writer.buffer()->AddChar(','); } event.PrintJSON(&writer); char* output = nullptr; intptr_t output_length = 0; writer.Steal(&output, &output_length); Write(output, output_length); free(output); } #if defined(SUPPORT_PERFETTO) class TimelineEventPerfettoFileRecorder : public TimelineEventRecorderWithPerfettoSupport< TimelineEventFileRecorderBase> { public: explicit TimelineEventPerfettoFileRecorder(void* file, bool intern_strings); virtual ~TimelineEventPerfettoFileRecorder(); const char* name() const final { return PERFETTO_FILE_RECORDER_NAME; } #if defined(DART_INCLUDE_PROFILER) void WriteProfile(TimelineProfileType& profile) override; #endif void NotifyAboutIsolateGroupShutdown(IsolateGroup* isolate_group) override; private: void WritePacket( protozero::HeapBuffered* packet); void DrainImpl(const TimelineEvent& event) final; void EmitModuleSymbolsFor(IsolateGroup* isolate_group); Mutex writer_mutex_; TracePacketWriter writer_; }; static TimelineEventRecorder* CreateTimelineEventPerfettoFileRecorder( const char* filename, bool intern_strings, const char** error) { void* file = TimelineEventFileRecorderBase::OpenTimelineFileForWriting( filename, error); if (file == nullptr) { return nullptr; } *error = nullptr; return new TimelineEventPerfettoFileRecorder(file, intern_strings); } #if defined(DART_INCLUDE_PROFILER) void TimelineEventPerfettoFileRecorder::WriteProfile( TimelineProfileType& profile) { // Profile conversion code checks for safepoints so we need to use safepoint // aware mutex locker here to avoid deadlocks when two threads call // |WriteProfile| and the third thread requests a safepoint. // // Note that Drain does not need this because it does not check for // safepoint. SafepointMutexLocker ml(&writer_mutex_); #if defined(DART_PRECOMPILED_RUNTIME) profile.WritePerfetto( streaming_start_micros, streaming_stop_micros, writer_.interned_data_builder(), this, [](auto buffer, auto length, auto stream) { static_cast(stream)->Write( static_cast(buffer), length); }); #else profile.PrintProfilePerfetto( writer_.interned_data_builder(), this, [](auto buffer, auto length, auto stream) { static_cast(stream)->Write( static_cast(buffer), length); }); #endif } #endif TimelineEventPerfettoFileRecorder::TimelineEventPerfettoFileRecorder( void* file, bool intern_strings) : TimelineEventRecorderWithPerfettoSupport(file), writer_( packet(), [this](auto& packet) { this->WritePacket(&packet); }, intern_strings) { protozero::HeapBuffered& packet = this->packet(); perfetto_utils::PopulateClockSnapshotPacket(packet.get()); WritePacket(&packet); packet.Reset(); perfetto_utils::PopulateProcessDescriptorPacket(packet.get()); WritePacket(&packet); packet.Reset(); StartUp("TimelineEventPerfettoFileRecorder"); } void TimelineEventPerfettoFileRecorder::EmitModuleSymbolsFor( IsolateGroup* isolate_group) { ASSERT(IsolateGroup::Current() == nullptr); auto& interned_data_builder = writer_.interned_data_builder(); const auto build_id_iid = interned_data_builder.InternSyntheticBuildIdForIsolateGroup( isolate_group->id()); if (build_id_iid == 0) { return; } const bool kBypassSafepoint = false; Thread::EnterIsolateGroupAsHelper(isolate_group, Thread::kUnknownTask, kBypassSafepoint); { StackZone stack_zone(Thread::Current()); Code& code = Code::Handle(); GrowableArray functions; GrowableArray token_positions; // We assume that in general there is going to be a small number of mappings // (usually just one for each isolate group) and small number of isolate // groups (just one) so iterating them linearly is fine. for (auto interned_mapping : interned_data_builder.mappings()) { const auto mapping_iid = interned_mapping->iid; const auto& mapping = interned_mapping->data; if (mapping.build_id != build_id_iid) { continue; } protozero::HeapBuffered& packet = this->packet(); perfetto::protos::pbzero::ModuleSymbols* module_symbols = nullptr; for (const auto& interned_frame : interned_data_builder.frames()) { const auto& frame = interned_frame->data; if (frame.mapping_iid != mapping_iid) { continue; } const auto pc = mapping.start + frame.rel_pc; // Note: PCs are already adjusted when converting from Sample to // interned Frame, see PerfettoPerfSampleWriter::WriteSample. code = ReversePc::Lookup(isolate_group, pc, /*is_return_address=*/false); if (code.IsNull()) { continue; } if (module_symbols == nullptr) { perfetto_utils::SetTrustedPacketSequenceId(packet.get()); module_symbols = packet->set_module_symbols(); const auto mapping_path = interned_data_builder.mapping_paths().GetByIid( mapping.path_string); module_symbols->set_path(mapping_path); module_symbols->set_build_id( interned_data_builder.build_ids().GetByIid(build_id_iid)); } auto* address_symbols = module_symbols->add_address_symbols(); address_symbols->set_address(frame.rel_pc); if (code.IsFunctionCode()) { const intptr_t offset = pc - code.PayloadStart(); code.GetInlinedFunctionsAtInstruction(offset, &functions, &token_positions); for (intptr_t i = functions.length() - 1; i >= 0; --i) { const char* function_name = functions[i]->QualifiedUserVisibleNameCString(); auto* line = address_symbols->add_lines(); line->set_function_name(function_name); } } else { auto* line = address_symbols->add_lines(); line->set_function_name(code.Name()); } } if (module_symbols != nullptr) { WritePacket(&packet); packet.Reset(); } } } Thread::ExitIsolateGroupAsHelper(kBypassSafepoint); } void TimelineEventPerfettoFileRecorder::NotifyAboutIsolateGroupShutdown( IsolateGroup* isolate_group) { SafepointMutexLocker ml(&writer_mutex_); EmitModuleSymbolsFor(isolate_group); } TimelineEventPerfettoFileRecorder::~TimelineEventPerfettoFileRecorder() { ShutDown(); #if defined(DART_PRECOMPILED_RUNTIME) && defined(DART_INCLUDE_PROFILER) if (!writer_.interned_data_builder().frames().IsEmpty()) { Isolate* caller_isolate = Isolate::Current(); if (caller_isolate != nullptr) { Thread::ExitIsolate(); } IsolateGroup::ForEach([&](auto group) { EmitModuleSymbolsFor(group); }); if (caller_isolate != nullptr) { Thread::EnterIsolate(caller_isolate); } } #endif // We do not need to lock the following section, because at this point // |RecorderSynchronizationLock| must have been put in a state that prevents // the metadata maps from being modified. protozero::HeapBuffered& packet = this->packet(); for (SimpleHashMap::Entry* entry = track_uuid_to_track_metadata().Start(); entry != nullptr; entry = track_uuid_to_track_metadata().Next(entry)) { TimelineTrackMetadata* value = static_cast(entry->value); value->PopulateTracePacket(packet.get()); WritePacket(&packet); packet.Reset(); } for (SimpleHashMap::Entry* entry = async_track_uuid_to_track_metadata().Start(); entry != nullptr; entry = async_track_uuid_to_track_metadata().Next(entry)) { AsyncTimelineTrackMetadata* value = static_cast(entry->value); value->PopulateTracePacket(packet.get()); WritePacket(&packet); packet.Reset(); } } void TimelineEventPerfettoFileRecorder::WritePacket( protozero::HeapBuffered* packet) { const std::tuple, intptr_t>& response = perfetto_utils::GetProtoPreamble(packet); Write(reinterpret_cast(std::get<0>(response).get()), std::get<1>(response)); for (const protozero::ScatteredHeapBuffer::Slice& slice : packet->GetSlices()) { Write(reinterpret_cast(slice.start()), slice.size() - slice.unused_bytes()); } } void TimelineEventPerfettoFileRecorder::DrainImpl(const TimelineEvent& event) { { MutexLocker lock(&writer_mutex_); writer_.WriteEvent(event); } if (event.event_type() == TimelineEvent::kAsyncBegin || event.event_type() == TimelineEvent::kAsyncInstant) { AddAsyncTrackMetadataBasedOnEvent(event); } } #endif // defined(SUPPORT_PERFETTO) TimelineEventEndlessRecorder::TimelineEventEndlessRecorder() : head_(nullptr), tail_(nullptr), block_index_(0) {} TimelineEventEndlessRecorder::~TimelineEventEndlessRecorder() { ASSERT(head_ == nullptr); } #ifndef PRODUCT void TimelineEventEndlessRecorder::ForEachNonEmptyBlock( std::function&& handle_block) { // Acquire the recorder's lock to prevent the reclaimed blocks from being // handed out again until the trace has been serialized. OSThreadIterator it; MutexLocker ml(&lock_); Timeline::ReclaimCachedBlocksFromThreads(&it); ResetTimeTracking(); for (TimelineEventBlock* current = head_; current != nullptr; current = current->next()) { if (!current->ContainsEventsThatCanBeSerializedLocked()) { continue; } handle_block(*current); } } #endif // !defined(PRODUCT) TimelineEvent* TimelineEventEndlessRecorder::StartEvent() { return ThreadBlockStartEvent(); } void TimelineEventEndlessRecorder::CompleteEvent(TimelineEvent* event) { if (event == nullptr) { return; } ThreadBlockCompleteEvent(event); } TimelineEventBlock* TimelineEventEndlessRecorder::GetNewBlockLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); TimelineEventBlock* block = new TimelineEventBlock(block_index_++); block->Open(); if (head_ == nullptr) { head_ = tail_ = block; } else { tail_->set_next(block); tail_ = block; } if (FLAG_trace_timeline) { OS::PrintErr("Created new block %p\n", block); } return block; } void TimelineEventEndlessRecorder::ClearLocked() { ASSERT(lock_.IsOwnedByCurrentThread()); TimelineEventBlock* current = head_; while (current != nullptr) { TimelineEventBlock* next = current->next(); delete current; current = next; } head_ = nullptr; tail_ = nullptr; block_index_ = 0; } bool Timeline::StreamTo(const char* recorder_kind, const char* filename, const char* streams, const char** error) { Timeline::Cleanup(); TimelineEventRecorder* recorder = nullptr; if (strcmp(recorder_kind, "perfettofile") == 0) { #if defined(SUPPORT_PERFETTO) recorder = CreateTimelineEventPerfettoFileRecorder( filename, /*intern_strings=*/true, error); if (recorder == nullptr) { return false; } #else *error = "Support for Perfetto recorder is not included into this build"; return false; #endif // defined(SUPPORT_PERFETTO) } else if (strcmp(recorder_kind, "file") == 0) { void* file = TimelineEventFileRecorderBase::OpenTimelineFileForWriting( filename, error); if (file == nullptr) { return false; } recorder = new TimelineEventFileRecorder(file); } else if (strcmp(recorder_kind, "systrace") == 0) { recorder = CreateSystraceTimelineRecorder(); if (recorder == nullptr) { *error = "Support for systrace recorder is not included into this build"; return false; } } Timeline::InitWithRecorder(recorder, streams); streaming_start_micros.store(OS::GetCurrentMonotonicMicrosForTimeline()); streaming_stop_micros.store(kMaxInt64); is_streaming_timeline.store(true); return true; } #if defined(DART_INCLUDE_PROFILER) void Timeline::DrainCompletedSampleBlocksIntoRecorder( NOT_IN_PRECOMPILED(Isolate* isolate)) { if (!is_streaming_timeline.load()) { return; } #if defined(DART_PRECOMPILED_RUNTIME) auto& profile = *Profiler::sample_block_buffer(); #else auto thread = Thread::Current(); if (Isolate::IsSystemIsolate(isolate)) return; TIMELINE_DURATION(thread, Isolate, "Timeline::WriteProfile") DisableThreadInterruptsScope dtis(thread); StackZone zone(thread); Profile profile; NoAllocationSampleFilter filter(isolate->main_port(), Thread::kMutatorTask, streaming_start_micros, streaming_stop_micros); profile.Build(thread, isolate, &filter, Profiler::sample_block_buffer()); #endif RecorderSynchronizationLockScope ls; if (recorder_ != nullptr && ls.IsActive() && is_streaming_timeline.load()) { recorder_->WriteProfile(profile); } } #endif void Timeline::StopStreaming(bool reinitialize) { if (!is_streaming_timeline.load()) { return; } streaming_stop_micros.store(OS::GetCurrentMonotonicMicrosForTimeline()); is_streaming_timeline.store(false); Timeline::Cleanup(); if (reinitialize) { Timeline::Init(); } } void Timeline::NotifyAboutIsolateGroupShutdown(IsolateGroup* isolate_group) { #if defined(DART_INCLUDE_PROFILER) && defined(SUPPORT_PERFETTO) if (!is_streaming_timeline.load()) { return; } RecorderSynchronizationLockScope ls; if (recorder_ != nullptr && ls.IsActive()) { recorder_->NotifyAboutIsolateGroupShutdown(isolate_group); } #endif } TimelineEventBlock::TimelineEventBlock(intptr_t block_index) : next_(nullptr), length_(0), block_index_(block_index), current_owner_(nullptr), in_use_(false) {} TimelineEventBlock::~TimelineEventBlock() { Reset(); } #ifndef PRODUCT void TimelineEventBlock::PrintJSON(JSONStream* js) const { ASSERT(!InUseLocked()); JSONArray events(js); for (intptr_t i = 0; i < length(); i++) { const TimelineEvent* event = At(i); if (event->IsValid()) { events.AddValue(event); } } } #endif TimelineEvent* TimelineEventBlock::StartEventLocked() { OSThread* os_thread = OSThread::Current(); ASSERT(os_thread != nullptr); ASSERT(os_thread == current_owner_); ASSERT(os_thread->timeline_block_lock()->IsOwnedByCurrentThread()); ASSERT(!IsFull()); if (FLAG_trace_timeline) { intptr_t tid = OSThread::ThreadIdToIntPtr(os_thread->id()); OS::PrintErr("StartEvent in block %p for thread %" Pd "\n", this, tid); } return &events_[length_++]; } int64_t TimelineEventBlock::LowerTimeBound() const { if (length_ == 0) { return kMaxInt64; } ASSERT(length_ > 0); return events_[0].TimeOrigin(); } void TimelineEventBlock::Reset() { for (intptr_t i = 0; i < kBlockSize; i++) { // Clear any extra data. events_[i].Reset(); } length_ = 0; current_owner_ = nullptr; in_use_ = false; } void TimelineEventBlock::Open() { OSThread* os_thread = OSThread::Current(); ASSERT(os_thread != nullptr); current_owner_ = os_thread; in_use_ = true; } void TimelineEventBlock::Finish() { if (FLAG_trace_timeline) { OS::PrintErr("Finish block %p\n", this); } current_owner_ = nullptr; in_use_ = false; #ifndef PRODUCT if (Service::timeline_stream.enabled()) { ServiceEvent service_event(ServiceEvent::kTimelineEvents); service_event.set_timeline_event_block(this); Service::HandleEvent(&service_event, /* enter_safepoint */ false); } #endif } void DartTimelineEventHelpers::ReportTaskEvent( TimelineEvent* event, int64_t id, intptr_t flow_id_count, std::unique_ptr& flow_ids, intptr_t type, char* name, char* args) { const int64_t start = OS::GetCurrentMonotonicMicrosForTimeline(); switch (static_cast(type)) { case TimelineEvent::kAsyncInstant: event->AsyncInstant(name, id, start); break; case TimelineEvent::kAsyncBegin: event->AsyncBegin(name, id, start); break; case TimelineEvent::kAsyncEnd: event->AsyncEnd(name, id, start); break; case TimelineEvent::kBegin: event->Begin(name, id, start); break; case TimelineEvent::kEnd: event->End(name, id, start); break; case TimelineEvent::kFlowBegin: event->FlowBegin(name, id, start); break; case TimelineEvent::kFlowStep: event->FlowStep(name, id, start); break; case TimelineEvent::kFlowEnd: event->FlowEnd(name, id, start); break; case TimelineEvent::kInstant: event->Instant(name, start); break; default: UNREACHABLE(); } if (flow_id_count > 0) { ASSERT(type == TimelineEvent::kBegin || type == TimelineEvent::kInstant || type == TimelineEvent::kAsyncBegin || type == TimelineEvent::kAsyncInstant); event->SetFlowIds(flow_id_count, flow_ids); } event->set_owns_label(true); event->CompleteWithPreSerializedArgs(args); } } // namespace dart #endif // defined(SUPPORT_TIMELINE)