From 0977920217680392178659f17a07ec55135d688e Mon Sep 17 00:00:00 2001 From: Mike Ash Date: Thu, 21 Oct 2021 17:07:59 -0400 Subject: [PATCH] [Concurrency] Add tracing for major operations in the concurrency runtime. Each trace point is declared as a function in the new `Tracing.h` header. These functions are called from the appropriate places in the concurrency runtime. On Darwin, an implementation of these functions is provided which uses the `os/signpost.h` API to emit signpost events/intervals. When the signpost API is not available, no-op stub implementations are provided. Implementations for other OSes can be provided by providing implementations of the trace functions for that OS. rdar://81858487 --- include/swift/ABI/Executor.h | 3 + include/swift/ABI/Task.h | 8 + stdlib/public/Concurrency/Actor.cpp | 51 +++- stdlib/public/Concurrency/CMakeLists.txt | 1 + stdlib/public/Concurrency/GlobalExecutor.cpp | 5 + stdlib/public/Concurrency/Task.cpp | 33 +++ stdlib/public/Concurrency/TaskPrivate.h | 9 + stdlib/public/Concurrency/TaskStatus.cpp | 5 + stdlib/public/Concurrency/Tracing.h | 94 ++++++ stdlib/public/Concurrency/TracingSignpost.cpp | 51 ++++ stdlib/public/Concurrency/TracingSignpost.h | 278 ++++++++++++++++++ stdlib/public/Concurrency/TracingStubs.h | 72 +++++ .../CompatibilityOverrideConcurrency.cpp | 14 +- 13 files changed, 608 insertions(+), 16 deletions(-) create mode 100644 stdlib/public/Concurrency/Tracing.h create mode 100644 stdlib/public/Concurrency/TracingSignpost.cpp create mode 100644 stdlib/public/Concurrency/TracingSignpost.h create mode 100644 stdlib/public/Concurrency/TracingStubs.h diff --git a/include/swift/ABI/Executor.h b/include/swift/ABI/Executor.h index 88c0a39796f8a..47274269211c1 100644 --- a/include/swift/ABI/Executor.h +++ b/include/swift/ABI/Executor.h @@ -124,6 +124,9 @@ class ExecutorRef { /// Is this executor the main executor? bool isMainExecutor() const; + /// Get the raw value of the Implementation field, for tracing. + uintptr_t getRawImplementation() { return Implementation; } + bool operator==(ExecutorRef other) const { return Identity == other.Identity; } diff --git a/include/swift/ABI/Task.h b/include/swift/ABI/Task.h index f5425c73c7a4f..771234af79fc1 100644 --- a/include/swift/ABI/Task.h +++ b/include/swift/ABI/Task.h @@ -272,6 +272,14 @@ class AsyncTask : public Job { /// Set the task's ID field to the next task ID. void setTaskId(); + uint64_t getTaskId(); + + /// Get the task's resume function, for logging purposes only. This will + /// attempt to see through the various adapters that are sometimes used, and + /// failing that will return ResumeTask. The returned function pointer may + /// have a different signature than ResumeTask, and it's only for identifying + /// code associated with the task. + const void *getResumeFunctionForLogging(); /// Given that we've already fully established the job context /// in the current thread, start running this task. To establish diff --git a/stdlib/public/Concurrency/Actor.cpp b/stdlib/public/Concurrency/Actor.cpp index 13c8ac336b8c1..ecff9062c7974 100644 --- a/stdlib/public/Concurrency/Actor.cpp +++ b/stdlib/public/Concurrency/Actor.cpp @@ -525,6 +525,9 @@ class JobRef { return reinterpret_cast(Value); } + /// Get the Job pointer with no preconditions on its type, for tracing. + Job *getRawJob() const { return reinterpret_cast(Value & JobMask); } + bool operator==(JobRef other) const { return Value == other.Value; } @@ -687,6 +690,7 @@ class DefaultActorImpl : public HeapObject { flags.setIsDistributedRemote(isDistributedRemote); new (&CurrentState) swift::atomic(State{JobRef(), flags}); JobStorageHeapObject.metadata = nullptr; + concurrency::trace::actor_create(this); } /// Properly destruct an actor, except for the heap header. @@ -768,8 +772,10 @@ void DefaultActorImpl::destroy() { newState.Flags.setStatus(Status::Zombie_Latching); if (CurrentState.compare_exchange_weak(oldState, newState, std::memory_order_relaxed, - std::memory_order_relaxed)) + std::memory_order_relaxed)) { + concurrency::trace::actor_destroy(this); return; + } } } @@ -795,6 +801,8 @@ void DefaultActorImpl::deallocate() { } void DefaultActorImpl::deallocateUnconditional() { + concurrency::trace::actor_deallocate(this); + if (JobStorageHeapObject.metadata != nullptr) JobStorage.~ProcessInlineJob(); auto metadata = cast(this->metadata); @@ -926,12 +934,19 @@ static Job *preprocessQueue(JobRef first, return firstNewJob; } +static void traceJobQueue(DefaultActorImpl *actor, Job *first) { + concurrency::trace::actor_note_job_queue(actor, first, [](Job *job) { + return getNextJobInQueue(job).getAsPreprocessedJob(); + }); +} + void DefaultActorImpl::giveUpThread(RunningJobInfo runner) { SWIFT_TASK_DEBUG_LOG("giving up thread for actor %p", this); auto oldState = CurrentState.load(std::memory_order_acquire); assert(oldState.Flags.isAnyRunningStatus()); auto firstNewJob = preprocessQueue(oldState.FirstJob, JobRef(), nullptr); + traceJobQueue(this, firstNewJob); _swift_tsan_release(this); while (true) { @@ -978,16 +993,23 @@ void DefaultActorImpl::giveUpThread(RunningJobInfo runner) { firstNewJob = preprocessQueue(oldState.FirstJob, firstPreprocessed, firstNewJob); + traceJobQueue(this, firstNewJob); // Try again. continue; } -#define LOG_STATE_TRANSITION \ - SWIFT_TASK_DEBUG_LOG("actor %p transitioned from %zx to %zx (%s)\n", this, \ - oldState.Flags.getOpaqueValue(), \ - newState.Flags.getOpaqueValue(), __FUNCTION__) - LOG_STATE_TRANSITION; +#define ACTOR_STATE_TRANSITION \ + do { \ + SWIFT_TASK_DEBUG_LOG("actor %p transitioned from %zx to %zx (%s)\n", this, \ + oldState.Flags.getOpaqueValue(), \ + newState.Flags.getOpaqueValue(), __FUNCTION__); \ + concurrency::trace::actor_state_changed( \ + this, newState.FirstJob.getRawJob(), \ + newState.FirstJob.needsPreprocessing(), \ + newState.Flags.getOpaqueValue()); \ + } while (0) + ACTOR_STATE_TRANSITION; // The priority of the remaining work. auto newPriority = newState.Flags.getMaxPriority(); @@ -1040,7 +1062,8 @@ Job *DefaultActorImpl::claimNextJobOrGiveUp(bool actorIsOwned, auto success = CurrentState.compare_exchange_weak(oldState, newState, /*success*/ std::memory_order_relaxed, /*failure*/ std::memory_order_acquire); - if (success) LOG_STATE_TRANSITION; + if (success) + ACTOR_STATE_TRANSITION; return success; }; @@ -1082,7 +1105,7 @@ Job *DefaultActorImpl::claimNextJobOrGiveUp(bool actorIsOwned, /*success*/ std::memory_order_relaxed, /*failure*/ std::memory_order_acquire)) continue; - LOG_STATE_TRANSITION; + ACTOR_STATE_TRANSITION; _swift_tsan_acquire(this); // If that succeeded, we can proceed to the main body. @@ -1100,6 +1123,7 @@ Job *DefaultActorImpl::claimNextJobOrGiveUp(bool actorIsOwned, // Okay, now it's safe to look at queue state. // Preprocess any queue items at the front of the queue. auto newFirstJob = preprocessQueue(oldState.FirstJob, JobRef(), nullptr); + traceJobQueue(this, newFirstJob); _swift_tsan_release(this); while (true) { @@ -1144,11 +1168,12 @@ Job *DefaultActorImpl::claimNextJobOrGiveUp(bool actorIsOwned, newFirstJob = preprocessQueue(oldState.FirstJob, firstPreprocessed, newFirstJob); + traceJobQueue(this, newFirstJob); // Loop to retry updating the state. continue; } - LOG_STATE_TRANSITION; + ACTOR_STATE_TRANSITION; // We successfully updated the state. @@ -1180,10 +1205,12 @@ static void swift_job_runImpl(Job *job, ExecutorRef executor) { if (!executor.isGeneric()) trackingInfo.disallowSwitching(); trackingInfo.enterAndShadow(executor); + auto traceHandle = concurrency::trace::job_run_begin(job, &executor); SWIFT_TASK_DEBUG_LOG("%s(%p)", __func__, job); runJobInEstablishedExecutorContext(job); + concurrency::trace::job_run_end(job, &executor, traceHandle); trackingInfo.leave(); // Give up the current executor if this is a switching context @@ -1237,6 +1264,7 @@ static void processDefaultActor(DefaultActorImpl *currentActor, SWIFT_TASK_DEBUG_LOG("processDefaultActor %p claimed job %p", currentActor, job); + concurrency::trace::actor_dequeue(currentActor, job); // If we failed to claim a job, we have nothing to do. if (!job) { @@ -1351,7 +1379,8 @@ void DefaultActorImpl::enqueue(Job *job) { /*success*/ std::memory_order_release, /*failure*/ std::memory_order_relaxed)) continue; - LOG_STATE_TRANSITION; + ACTOR_STATE_TRANSITION; + concurrency::trace::actor_enqueue(this, job); // Okay, we successfully updated the status. Schedule a job to // process the actor if necessary. @@ -1381,7 +1410,7 @@ bool DefaultActorImpl::tryAssumeThread(RunningJobInfo runner) { if (CurrentState.compare_exchange_weak(oldState, newState, /*success*/ std::memory_order_relaxed, /*failure*/ std::memory_order_acquire)) { - LOG_STATE_TRANSITION; + ACTOR_STATE_TRANSITION; _swift_tsan_acquire(this); return true; } diff --git a/stdlib/public/Concurrency/CMakeLists.txt b/stdlib/public/Concurrency/CMakeLists.txt index 1afbc6f88cc64..5eb23d0768aac 100644 --- a/stdlib/public/Concurrency/CMakeLists.txt +++ b/stdlib/public/Concurrency/CMakeLists.txt @@ -103,6 +103,7 @@ add_swift_target_library(swift_Concurrency ${SWIFT_STDLIB_LIBRARY_BUILD_TYPES} I TaskLocal.swift TaskSleep.swift ThreadSanitizer.cpp + TracingSignpost.cpp Mutex.cpp AsyncStreamBuffer.swift AsyncStream.swift diff --git a/stdlib/public/Concurrency/GlobalExecutor.cpp b/stdlib/public/Concurrency/GlobalExecutor.cpp index ecf81a1f82122..1dd4324f61b25 100644 --- a/stdlib/public/Concurrency/GlobalExecutor.cpp +++ b/stdlib/public/Concurrency/GlobalExecutor.cpp @@ -85,6 +85,8 @@ void (*swift::swift_task_enqueueMainExecutor_hook)( void swift::swift_task_enqueueGlobal(Job *job) { _swift_tsan_release(job); + concurrency::trace::job_enqueue_global(job); + if (swift_task_enqueueGlobal_hook) swift_task_enqueueGlobal_hook(job, swift_task_enqueueGlobalImpl); else @@ -92,6 +94,8 @@ void swift::swift_task_enqueueGlobal(Job *job) { } void swift::swift_task_enqueueGlobalWithDelay(JobDelay delay, Job *job) { + concurrency::trace::job_enqueue_global_with_delay(delay, job); + if (swift_task_enqueueGlobalWithDelay_hook) swift_task_enqueueGlobalWithDelay_hook( delay, job, swift_task_enqueueGlobalWithDelayImpl); @@ -100,6 +104,7 @@ void swift::swift_task_enqueueGlobalWithDelay(JobDelay delay, Job *job) { } void swift::swift_task_enqueueMainExecutor(Job *job) { + concurrency::trace::job_enqueue_main_executor(job); if (swift_task_enqueueMainExecutor_hook) swift_task_enqueueMainExecutor_hook(job, swift_task_enqueueMainExecutorImpl); diff --git a/stdlib/public/Concurrency/Task.cpp b/stdlib/public/Concurrency/Task.cpp index a732732d7f081..569620c07485d 100644 --- a/stdlib/public/Concurrency/Task.cpp +++ b/stdlib/public/Concurrency/Task.cpp @@ -24,6 +24,7 @@ #include "swift/Runtime/HeapObject.h" #include "TaskGroupPrivate.h" #include "TaskPrivate.h" +#include "Tracing.h" #include "Debug.h" #include "Error.h" @@ -102,6 +103,8 @@ FutureFragment::Status AsyncTask::waitFuture(AsyncTask *waitingTask, auto queueHead = fragment->waitQueue.load(std::memory_order_acquire); bool contextIntialized = false; while (true) { + concurrency::trace::task_wait( + waitingTask, this, static_cast(queueHead.getStatus())); switch (queueHead.getStatus()) { case Status::Error: case Status::Success: @@ -245,6 +248,8 @@ AsyncTask::~AsyncTask() { } Private.destroy(); + + concurrency::trace::task_destroy(this); } void AsyncTask::setTaskId() { @@ -260,6 +265,12 @@ void AsyncTask::setTaskId() { _private().Id = (Fetched >> 32) & 0xffffffff; } +uint64_t AsyncTask::getTaskId() { + // Reconstitute a full 64-bit task ID from the 32-bit job ID and the upper + // 32 bits held in _private(). + return (uint64_t)Id << _private().Id; +} + SWIFT_CC(swift) static void destroyTask(SWIFT_CONTEXT HeapObject *obj) { auto task = static_cast(obj); @@ -439,6 +450,26 @@ task_future_wait_resume_adapter(SWIFT_ASYNC_CONTEXT AsyncContext *_context) { return _context->ResumeParent(_context->Parent); } +const void *AsyncTask::getResumeFunctionForLogging() { + if (ResumeTask == non_future_adapter) { + auto asyncContextPrefix = reinterpret_cast( + reinterpret_cast(ResumeContext) - sizeof(AsyncContextPrefix)); + return reinterpret_cast(asyncContextPrefix->asyncEntryPoint); + } else if (ResumeTask == future_adapter) { + auto asyncContextPrefix = reinterpret_cast( + reinterpret_cast(ResumeContext) - + sizeof(FutureAsyncContextPrefix)); + return reinterpret_cast(asyncContextPrefix->asyncEntryPoint); + } else if (ResumeTask == task_wait_throwing_resume_adapter) { + auto context = static_cast(ResumeContext); + return reinterpret_cast(context->ResumeParent); + } else if (ResumeTask == task_future_wait_resume_adapter) { + return reinterpret_cast(ResumeContext->ResumeParent); + } + + return reinterpret_cast(ResumeTask); +} + /// Implementation of task creation. SWIFT_CC(swift) static AsyncTaskAndContext swift_task_create_commonImpl( @@ -702,6 +733,8 @@ static AsyncTaskAndContext swift_task_create_commonImpl( initialContext->Parent = nullptr; initialContext->Flags = AsyncContextKind::Ordinary; + concurrency::trace::task_create(task, parent, group, asyncLet); + // Attach to the group, if needed. if (group) { swift_taskGroup_attachChild(group, task); diff --git a/stdlib/public/Concurrency/TaskPrivate.h b/stdlib/public/Concurrency/TaskPrivate.h index 256ba1d9f20e0..8aea06f588da6 100644 --- a/stdlib/public/Concurrency/TaskPrivate.h +++ b/stdlib/public/Concurrency/TaskPrivate.h @@ -18,6 +18,7 @@ #define SWIFT_CONCURRENCY_TASKPRIVATE_H #include "Error.h" +#include "Tracing.h" #include "swift/ABI/Metadata.h" #include "swift/ABI/Task.h" #include "swift/Runtime/Atomic.h" @@ -266,6 +267,10 @@ class alignas(sizeof(void*) * 2) ActiveTaskStatus { llvm::iterator_range records() const { return record_iterator::rangeBeginning(getInnermostRecord()); } + + void traceStatusChanged(AsyncTask *task) { + concurrency::trace::task_status_changed(task, Flags); + } }; /// The size of an allocator slab. @@ -373,11 +378,13 @@ inline void AsyncTask::flagAsRunning() { if (newStatus.isStoredPriorityEscalated()) { newStatus = newStatus.withoutStoredPriorityEscalation(); Flags.setPriority(oldStatus.getStoredPriority()); + concurrency::trace::task_flags_changed(this, Flags.getOpaqueValue()); } if (_private().Status.compare_exchange_weak(oldStatus, newStatus, std::memory_order_relaxed, std::memory_order_relaxed)) { + newStatus.traceStatusChanged(this); adoptTaskVoucher(this); swift_task_enterThreadLocalContext( (char *)&_private().ExclusivityAccessSet[0]); @@ -403,11 +410,13 @@ inline void AsyncTask::flagAsSuspended() { if (newStatus.isStoredPriorityEscalated()) { newStatus = newStatus.withoutStoredPriorityEscalation(); Flags.setPriority(oldStatus.getStoredPriority()); + concurrency::trace::task_flags_changed(this, Flags.getOpaqueValue()); } if (_private().Status.compare_exchange_weak(oldStatus, newStatus, std::memory_order_relaxed, std::memory_order_relaxed)) { + newStatus.traceStatusChanged(this); swift_task_exitThreadLocalContext( (char *)&_private().ExclusivityAccessSet[0]); restoreTaskVoucher(this); diff --git a/stdlib/public/Concurrency/TaskStatus.cpp b/stdlib/public/Concurrency/TaskStatus.cpp index 571675d4c7633..359e260cba71d 100644 --- a/stdlib/public/Concurrency/TaskStatus.cpp +++ b/stdlib/public/Concurrency/TaskStatus.cpp @@ -184,6 +184,7 @@ static bool withStatusRecordLock(AsyncTask *task, if (task->_private().Status.compare_exchange_weak(status, newStatus, /*success*/ std::memory_order_relaxed, /*failure*/ loadOrdering)) { + newStatus.traceStatusChanged(task); status = newStatus; return false; } @@ -203,6 +204,7 @@ static bool withStatusRecordLock(AsyncTask *task, if (task->_private().Status.compare_exchange_weak(status, newStatus, /*success*/ std::memory_order_release, /*failure*/ loadOrdering)) { + newStatus.traceStatusChanged(task); // Update `status` for the purposes of the callback function. // Note that we don't include the record lock, but do need to @@ -230,6 +232,7 @@ static bool withStatusRecordLock(AsyncTask *task, // atomic objects in the task status records. Because of this, we can // actually unpublish the lock with a relaxed store. assert(!status.isLocked()); + status.traceStatusChanged(task); task->_private().Status.store(status, /*success*/ std::memory_order_relaxed); @@ -606,6 +609,7 @@ void AsyncTask::flagAsRunning_slow() { if (status.isStoredPriorityEscalated()) { status = status.withoutStoredPriorityEscalation(); Flags.setPriority(status.getStoredPriority()); + concurrency::trace::task_flags_changed(this, Flags.getOpaqueValue()); } }); } @@ -619,6 +623,7 @@ void AsyncTask::flagAsSuspended_slow() { if (status.isStoredPriorityEscalated()) { status = status.withoutStoredPriorityEscalation(); Flags.setPriority(status.getStoredPriority()); + concurrency::trace::task_flags_changed(this, Flags.getOpaqueValue()); } }); } diff --git a/stdlib/public/Concurrency/Tracing.h b/stdlib/public/Concurrency/Tracing.h new file mode 100644 index 0000000000000..0edda49feda59 --- /dev/null +++ b/stdlib/public/Concurrency/Tracing.h @@ -0,0 +1,94 @@ +//===--- Tracing.h - Support code for concurrency tracing ----------*- C++ -*-// +// +// This source file is part of the Swift.org open source project +// +// Copyright (c) 2014 - 2021 Apple Inc. and the Swift project authors +// Licensed under Apache License v2.0 with Runtime Library Exception +// +// See https://swift.org/LICENSE.txt for license information +// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors +// +//===----------------------------------------------------------------------===// +// +// Support code for tracing events in the concurrency runtime +// +//===----------------------------------------------------------------------===// + +#ifndef SWIFT_CONCURRENCY_TRACING_H +#define SWIFT_CONCURRENCY_TRACING_H + +#include + +namespace swift { +class AsyncLet; +class AsyncTask; +class ExecutorRef; +struct HeapObject; +class Job; +class TaskGroup; +class TaskStatusRecord; + +namespace concurrency { +namespace trace { + +// Actor trace calls. + +void actor_create(HeapObject *actor); + +void actor_destroy(HeapObject *actor); + +void actor_deallocate(HeapObject *actor); + +void actor_enqueue(HeapObject *actor, Job *job); + +void actor_dequeue(HeapObject *actor, Job *job); + +// The `flags` parameter is the raw values of the actor's +// DefaultActorImpl::State::Flags. +void actor_state_changed(HeapObject *actor, Job *firstJob, + bool needsPreprocessing, uintptr_t flags); + +void actor_note_job_queue(HeapObject *actor, Job *first, + Job *(*getNext)(Job *)); + +// Task trace calls. + +void task_create(AsyncTask *task, AsyncTask *parent, TaskGroup *group, + AsyncLet *asyncLet); + +void task_destroy(AsyncTask *task); + +// The `flags` parameter is the raw value of the ActiveTaskStatus::Flags field +// in the task. +void task_status_changed(AsyncTask *task, uintptr_t flags); + +// The `flags` parameter is the raw value of Job::Flags. +void task_flags_changed(AsyncTask *task, uint32_t flags); + +// The `status` parameter is the value of the corresponding +// FutureFragment::Status. +void task_wait(AsyncTask *task, AsyncTask *waitingOn, uintptr_t status); + +void job_enqueue_global(Job *job); + +void job_enqueue_global_with_delay(unsigned long long delay, Job *job); + +void job_enqueue_main_executor(Job *job); + +// This returns a handle that must be passed to the corresponding call to +// task_run_end. +uint64_t job_run_begin(Job *job, ExecutorRef *executor); + +void job_run_end(Job *job, ExecutorRef *executor, uint64_t beginHandle); + +} // namespace trace +} // namespace concurrency +} // namespace swift + +#if __has_include() +#include "TracingSignpost.h" +#else +#include "TracingStubs.h" +#endif + +#endif diff --git a/stdlib/public/Concurrency/TracingSignpost.cpp b/stdlib/public/Concurrency/TracingSignpost.cpp new file mode 100644 index 0000000000000..b761c7142cb74 --- /dev/null +++ b/stdlib/public/Concurrency/TracingSignpost.cpp @@ -0,0 +1,51 @@ +//===--- TracingSignpost.cpp - Tracing with the signpost API -------*- C++ -*-// +// +// This source file is part of the Swift.org open source project +// +// Copyright (c) 2014 - 2021 Apple Inc. and the Swift project authors +// Licensed under Apache License v2.0 with Runtime Library Exception +// +// See https://swift.org/LICENSE.txt for license information +// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors +// +//===----------------------------------------------------------------------===// +// +// Concurrency tracing implemented with the os_signpost API. +// +//===----------------------------------------------------------------------===// + +#if __has_include() + +#include "TracingSignpost.h" +#include + +// Temporary until we work out what categories we should really use. +#ifndef OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING +#define OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING "DynamicStackTracing" +#endif + +#define SWIFT_LOG_CONCURRENCY_ACTOR_SUBSYSTEM "com.apple.swift.actor" +#define SWIFT_LOG_CONCURRENCY_TASK_SUBSYSTEM "com.apple.swift.task" +#define SWIFT_LOG_ACTOR_CATEGORY OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING +#define SWIFT_LOG_TASK_CATEGORY OS_LOG_CATEGORY_DYNAMIC_STACK_TRACING + +namespace swift { +namespace concurrency { +namespace trace { + +os_log_t ActorLog; +os_log_t TaskLog; +OnceToken_t LogsToken; + +void setupLogs(void *unused) { + ActorLog = os_log_create(SWIFT_LOG_CONCURRENCY_ACTOR_SUBSYSTEM, + SWIFT_LOG_ACTOR_CATEGORY); + TaskLog = os_log_create(SWIFT_LOG_CONCURRENCY_TASK_SUBSYSTEM, + SWIFT_LOG_TASK_CATEGORY); +} + +} // namespace trace +} // namespace concurrency +} // namespace swift + +#endif diff --git a/stdlib/public/Concurrency/TracingSignpost.h b/stdlib/public/Concurrency/TracingSignpost.h new file mode 100644 index 0000000000000..322f75cdbcaed --- /dev/null +++ b/stdlib/public/Concurrency/TracingSignpost.h @@ -0,0 +1,278 @@ +//===--- TracingSignpost.h - Tracing with the signpost API ---------*- C++ -*-// +// +// This source file is part of the Swift.org open source project +// +// Copyright (c) 2014 - 2021 Apple Inc. and the Swift project authors +// Licensed under Apache License v2.0 with Runtime Library Exception +// +// See https://swift.org/LICENSE.txt for license information +// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors +// +//===----------------------------------------------------------------------===// +// +// Concurrency tracing implemented with the os_signpost API. +// +//===----------------------------------------------------------------------===// + +#ifndef SWIFT_CONCURRENCY_TRACINGSIGNPOST_H +#define SWIFT_CONCURRENCY_TRACINGSIGNPOST_H + +#include "TaskPrivate.h" +#include "Tracing.h" +#include "swift/ABI/Task.h" +#include "swift/Basic/Lazy.h" +#include "swift/Runtime/Casting.h" +#include "swift/Runtime/HeapObject.h" +#include +#include +#include + +// Compatibility notes: +// +// These signposts can be read by external software that isn't synced with the +// Swift runtime build. Changes here must be considered carefully to avoid +// breaking users of these signposts. +// +// We may: +// * Add new signpost calls with new names. (Keeping in mind that they won't be +// picked up by software that doesn't know about them.) +// * Remove existing calls if the given event is somehow no longer relevant. +// * Change format strings. +// * Add format string arguments. +// +// We may NOT: +// * Change the order of existing format string arguments. +// * Change event names. +// * Change subsystem names. + +#define SWIFT_LOG_ACTOR_LIFETIME_NAME "actor_lifetime" +#define SWIFT_LOG_ACTOR_DEALLOCATE_NAME "actor_deallocate" +#define SWIFT_LOG_ACTOR_ENQUEUE_NAME "actor_enqueue" +#define SWIFT_LOG_ACTOR_DEQUEUE_NAME "actor_dequeue" +#define SWIFT_LOG_ACTOR_STATE_CHANGED_NAME "actor_state_changed" +#define SWIFT_LOG_ACTOR_JOB_QUEUE_NAME "actor_job_queue" +#define SWIFT_LOG_TASK_LIFETIME_NAME "task_lifetime" +#define SWIFT_LOG_TASK_STATUS_CHANGED_NAME "task_status_changed" +#define SWIFT_LOG_TASK_WAIT_NAME "task_wait" +#define SWIFT_LOG_JOB_ENQUEUE_GLOBAL_NAME "job_enqueue_global" +#define SWIFT_LOG_JOB_ENQUEUE_GLOBAL_WITH_DELAY_NAME \ + "job_enqueue_global_with_delay" +#define SWIFT_LOG_JOB_ENQUEUE_MAIN_EXECUTOR_NAME "job_enqueue_main_executor" +#define SWIFT_LOG_JOB_RUN_NAME "job_run" + +namespace swift { +namespace concurrency { +namespace trace { + +extern os_log_t ActorLog; +extern os_log_t TaskLog; +extern OnceToken_t LogsToken; + +void setupLogs(void *unused); + +// Check a representative os_signpost function for NULL rather than doing a +// standard availability check, for better performance if the check doesn't get +// optimized out. +#define ENSURE_LOGS(...) \ + do { \ + if (!SWIFT_RUNTIME_WEAK_CHECK(os_signpost_enabled)) \ + return __VA_ARGS__; \ + SWIFT_ONCE_F(LogsToken, setupLogs, nullptr); \ + } while (0) + +// Every function does ENSURE_LOGS() before making any os_signpost calls, so +// we can skip availability checking on all the individual calls. +#pragma clang diagnostic push +#pragma clang diagnostic ignored "-Wunguarded-availability" +#pragma clang diagnostic ignored "-Wunguarded-availability-new" + +// Actor trace calls. + +inline void actor_create(HeapObject *actor) { + ENSURE_LOGS(); + + // Do an explicit enabled check here to avoid the cost of swift_getTypeName in + // the common case. + if (!os_signpost_enabled(ActorLog)) + return; + + auto typeName = swift_getTypeName(swift_getObjectType(actor), true); + + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_interval_begin(ActorLog, id, SWIFT_LOG_ACTOR_LIFETIME_NAME, + "actor=%p typeName:%.*s", actor, + (int)typeName.length, typeName.data); +} + +inline void actor_destroy(HeapObject *actor) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_interval_end(ActorLog, id, SWIFT_LOG_ACTOR_LIFETIME_NAME, + "actor=%p", actor); +} + +inline void actor_deallocate(HeapObject *actor) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_event_emit(ActorLog, id, SWIFT_LOG_ACTOR_DEALLOCATE_NAME, + "actor=%p", actor); +} + +inline void actor_enqueue(HeapObject *actor, Job *job) { + if (AsyncTask *task = dyn_cast(job)) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_event_emit(ActorLog, id, SWIFT_LOG_ACTOR_ENQUEUE_NAME, + "actor=%p task=%" PRIx64, actor, task->getTaskId()); + } +} + +inline void actor_dequeue(HeapObject *actor, Job *job) { + if (AsyncTask *task = dyn_cast_or_null(job)) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_event_emit(ActorLog, id, SWIFT_LOG_ACTOR_DEQUEUE_NAME, + "actor=%p task=%" PRIx64, actor, task->getTaskId()); + } +} + +inline void actor_state_changed(HeapObject *actor, Job *firstJob, + bool needsPreprocessing, uintptr_t flags) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_event_emit(ActorLog, id, SWIFT_LOG_ACTOR_STATE_CHANGED_NAME, + "actor=%p needsPreprocessing=%d " + "flags=0x%" PRIxPTR, + actor, needsPreprocessing, flags); +} + +inline void actor_note_job_queue(HeapObject *actor, Job *first, + Job *(*getNext)(Job *)) { + ENSURE_LOGS(); + + // Do an explicit enabled check here, since the loop is potentially expensive. + if (!os_signpost_enabled(ActorLog)) + return; + + // Count the number of pending jobs. We may want to track this separately + // rather than looping to count, but this gets the job done for now. + + unsigned jobCount = 0; + for (Job *job = first; job; job = getNext(job)) + if (isa(job)) + jobCount++; + + auto id = os_signpost_id_make_with_pointer(ActorLog, actor); + os_signpost_event_emit(ActorLog, id, SWIFT_LOG_ACTOR_JOB_QUEUE_NAME, + "actor=%p jobCount=%u", actor, jobCount); +} + +// Task trace calls. + +inline void task_create(AsyncTask *task, AsyncTask *parent, TaskGroup *group, + AsyncLet *asyncLet) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, task); + os_signpost_interval_begin( + TaskLog, id, SWIFT_LOG_TASK_LIFETIME_NAME, + "task=%" PRIx64 " resumefn=%p flags=0x%" PRIx32 + " parent=%p group=%p asyncLet=%p", + task->getTaskId(), task->getResumeFunctionForLogging(), + task->Flags.getOpaqueValue(), parent, group, asyncLet); +} + +inline void task_destroy(AsyncTask *task) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, task); + os_signpost_interval_end(TaskLog, id, SWIFT_LOG_TASK_LIFETIME_NAME, + "task=%" PRIx64 "", task->getTaskId()); +} + +inline void task_status_changed(AsyncTask *task, uintptr_t flags) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, task); + os_signpost_event_emit(TaskLog, id, SWIFT_LOG_TASK_STATUS_CHANGED_NAME, + "task=%" PRIx64 " resumefn=%p flags=0x%" PRIxPTR, + task->getTaskId(), task->getResumeFunctionForLogging(), + flags); +} + +inline void task_flags_changed(AsyncTask *task, uint32_t flags) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, task); + os_signpost_event_emit(TaskLog, id, SWIFT_LOG_TASK_STATUS_CHANGED_NAME, + "task=%" PRIx64 " flags=0x%" PRIx32, task->getTaskId(), + flags); +} + +inline void task_wait(AsyncTask *task, AsyncTask *waitingOn, uintptr_t status) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, task); + os_signpost_event_emit(TaskLog, id, SWIFT_LOG_TASK_WAIT_NAME, + "task=%" PRIx64 " waitingOnTask=%p status=0x%" PRIxPTR, + task->getTaskId(), waitingOn, status); +} + +inline void job_enqueue_global(Job *job) { + if (AsyncTask *task = dyn_cast(job)) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, job); + os_signpost_event_emit(TaskLog, id, SWIFT_LOG_JOB_ENQUEUE_GLOBAL_NAME, + "task=%" PRIx64, task->getTaskId()); + } +} + +inline void job_enqueue_global_with_delay(unsigned long long delay, Job *job) { + if (AsyncTask *task = dyn_cast(job)) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, job); + os_signpost_event_emit( + TaskLog, id, SWIFT_LOG_JOB_ENQUEUE_GLOBAL_WITH_DELAY_NAME, + "task=%" PRIx64 " delay=%llu", task->getTaskId(), delay); + } +} + +inline void job_enqueue_main_executor(Job *job) { + if (AsyncTask *task = dyn_cast(job)) { + ENSURE_LOGS(); + auto id = os_signpost_id_make_with_pointer(TaskLog, job); + os_signpost_event_emit(TaskLog, id, + SWIFT_LOG_JOB_ENQUEUE_MAIN_EXECUTOR_NAME, + "task=%" PRIx64, task->getTaskId()); + } +} + +inline uint64_t job_run_begin(Job *job, ExecutorRef *executor) { + if (AsyncTask *task = dyn_cast(job)) { + ENSURE_LOGS(0); + auto id = os_signpost_id_generate(TaskLog); + os_signpost_interval_begin( + TaskLog, id, SWIFT_LOG_JOB_RUN_NAME, + "task=%" PRIx64 + " executorIdentity=%p executorImplementation=0x%" PRIxPTR, + task->getTaskId(), executor->getIdentity(), + executor->getRawImplementation()); + return id; + } + return 0; +} + +inline void job_run_end(Job *job, ExecutorRef *executor, uint64_t beginHandle) { + if (AsyncTask *task = dyn_cast(job)) { + ENSURE_LOGS(); + os_signpost_interval_end( + TaskLog, beginHandle, SWIFT_LOG_JOB_RUN_NAME, + "task=%" PRIx64 + " executorIdentity=%p executorImplementation=0x%" PRIxPTR, + task->getTaskId(), executor->getIdentity(), + executor->getRawImplementation()); + } +} + +#pragma clang diagnostic pop + +} // namespace trace +} // namespace concurrency +} // namespace swift + +#endif diff --git a/stdlib/public/Concurrency/TracingStubs.h b/stdlib/public/Concurrency/TracingStubs.h new file mode 100644 index 0000000000000..d62c2430b5113 --- /dev/null +++ b/stdlib/public/Concurrency/TracingStubs.h @@ -0,0 +1,72 @@ +//===--- TracingStubs.h - Default stub implementation of tracing. --*- C++ -*-// +// +// This source file is part of the Swift.org open source project +// +// Copyright (c) 2014 - 2021 Apple Inc. and the Swift project authors +// Licensed under Apache License v2.0 with Runtime Library Exception +// +// See https://swift.org/LICENSE.txt for license information +// See https://swift.org/CONTRIBUTORS.txt for the list of Swift project authors +// +//===----------------------------------------------------------------------===// +// +// Concurrency tracing stubs for OSes without tracing support. +// +//===----------------------------------------------------------------------===// + +#ifndef SWIFT_CONCURRENCY_TRACINGSIGNPOST_H +#define SWIFT_CONCURRENCY_TRACINGSIGNPOST_H + +#include "Tracing.h" + +namespace swift { +namespace concurrency { +namespace trace { + +inline void actor_create(HeapObject *actor) {} + +inline void actor_destroy(HeapObject *actor) {} + +inline void actor_deallocate(HeapObject *actor) {} + +inline void actor_enqueue(HeapObject *actor, Job *job) {} + +inline void actor_dequeue(HeapObject *actor, Job *job) {} + +inline void actor_state_changed(HeapObject *actor, Job *firstJob, + bool needsPreprocessing, uintptr_t flags) {} + +inline void actor_note_job_queue(HeapObject *actor, Job *first, + Job *(*getNext)(Job *)) {} + +inline void task_create(AsyncTask *task, AsyncTask *parent, TaskGroup *group, + AsyncLet *asyncLet) {} + +inline void task_destroy(AsyncTask *task) {} + +inline void task_status_changed(AsyncTask *task, TaskStatusRecord *record, + uintptr_t flags) {} + +inline void task_wait(AsyncTask *task, AsyncTask *waitingOn, uintptr_t status) { +} + +inline void task_status_changed(AsyncTask *task, uintptr_t flags) {} + +inline void task_flags_changed(AsyncTask *task, uint32_t flags) {} + +inline void job_enqueue_global(Job *job) {} + +inline void job_enqueue_global_with_delay(unsigned long long delay, Job *job) {} + +inline void job_enqueue_main_executor(Job *job) {} + +inline uint64_t job_run_begin(Job *job, ExecutorRef *executor) { return 0; } + +inline void job_run_end(Job *job, ExecutorRef *executor, uint64_t beginHandle) { +} + +} // namespace trace +} // namespace concurrency +} // namespace swift + +#endif diff --git a/unittests/runtime/CompatibilityOverrideConcurrency.cpp b/unittests/runtime/CompatibilityOverrideConcurrency.cpp index 68277115b19ba..10d20016f5953 100644 --- a/unittests/runtime/CompatibilityOverrideConcurrency.cpp +++ b/unittests/runtime/CompatibilityOverrideConcurrency.cpp @@ -108,12 +108,16 @@ class CompatibilityOverrideConcurrencyTest : public ::testing::Test { } }; +static Job fakeJob{{JobKind::DefaultActorInline}, + static_cast(nullptr), + nullptr}; + TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_enqueue) { - swift_task_enqueue(nullptr, ExecutorRef::generic()); + swift_task_enqueue(&fakeJob, ExecutorRef::generic()); } TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_job_run) { - swift_job_run(nullptr, ExecutorRef::generic()); + swift_job_run(&fakeJob, ExecutorRef::generic()); } TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_getCurrentExecutor) { @@ -125,17 +129,17 @@ TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_switch) { } TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_enqueueGlobal) { - swift_task_enqueueGlobal(nullptr); + swift_task_enqueueGlobal(&fakeJob); } TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_enqueueGlobalWithDelay) { - swift_task_enqueueGlobalWithDelay(0, nullptr); + swift_task_enqueueGlobalWithDelay(0, &fakeJob); } TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_enqueueMainExecutor) { - swift_task_enqueueMainExecutor(nullptr); + swift_task_enqueueMainExecutor(&fakeJob); } TEST_F(CompatibilityOverrideConcurrencyTest, test_swift_task_create_common) {