[Concurrency] Replace SWIFT_TASK_PRINTF_DEBUG with a SWIFT_TASK_DEBUG_LOG macro.

This macro takes the string and parameters directly, and is conditionally defined to either call fprintf or ignore its arguments. This makes the call sites a little more pleasant (no #if scattered about) and ensures every log includes the thread ID and a newline automatically.

Author: mikeash

stdlib/public/Concurrency/Actor.cpp

@@ -269,10 +269,7 @@ static ExecutorRef swift_task_getCurrentExecutorImpl() {
   auto currentTracking = ExecutorTrackingInfo::current();
   auto result = (currentTracking ? currentTracking->getActiveExecutor()
                                  : ExecutorRef::generic());
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] getting current executor %p\n",
-          _swift_get_thread_id(), result.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("getting current executor %p", result.getIdentity());
   return result;
 }
 
@@ -1172,10 +1169,7 @@ static Job *preprocessQueue(JobRef first,
 }
 
 void DefaultActorImpl::giveUpThread(RunningJobInfo runner) {
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] giving up thread for actor %p\n",
-          _swift_get_thread_id(), this);
-#endif
+  SWIFT_TASK_DEBUG_LOG("giving up thread for actor %p", this);
   auto oldState = CurrentState.load(std::memory_order_acquire);
   assert(oldState.Flags.isAnyRunningStatus());
 
@@ -1236,14 +1230,10 @@ void DefaultActorImpl::giveUpThread(RunningJobInfo runner) {
       continue;
     }
 
-#if SWIFT_TASK_PRINTF_DEBUG
-#  define LOG_STATE_TRANSITION                                                  \
-    fprintf(stderr, "[%lu] actor %p transitioned from %zx to %zx (%s)\n",       \
-            _swift_get_thread_id(), this, oldState.Flags.getOpaqueValue(),      \
-            newState.Flags.getOpaqueValue(), __FUNCTION__)
-#else
-#  define LOG_STATE_TRANSITION ((void)0)
-#endif
+#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;
 
     // The priority of the remaining work.
@@ -1494,10 +1484,7 @@ static void swift_job_runImpl(Job *job, ExecutorRef executor) {
 SWIFT_CC(swiftasync)
 static void processDefaultActor(DefaultActorImpl *currentActor,
                                 RunningJobInfo runner) {
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] processDefaultActor %p\n",
-          _swift_get_thread_id(), currentActor);
-#endif
+  SWIFT_TASK_DEBUG_LOG("processDefaultActor %p", currentActor);
   DefaultActorImpl *actor = currentActor;
 
   // If we actually have work to do, we'll need to set up tracking info.
@@ -1521,10 +1508,8 @@ static void processDefaultActor(DefaultActorImpl *currentActor,
     auto job = currentActor->claimNextJobOrGiveUp(threadIsRunningActor,
                                                   runner);
 
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%lu] processDefaultActor %p claimed job %p\n",
-            _swift_get_thread_id(), currentActor, job);
-#endif
+    SWIFT_TASK_DEBUG_LOG("processDefaultActor %p claimed job %p", currentActor,
+                         job);
 
     // If we failed to claim a job, we have nothing to do.
     if (!job) {
@@ -1544,10 +1529,8 @@ static void processDefaultActor(DefaultActorImpl *currentActor,
     // If it's become nil, or not a default actor, we have nothing to do.
     auto currentExecutor = trackingInfo.getActiveExecutor();
 
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%lu] processDefaultActor %p current executor now %p\n",
-            _swift_get_thread_id(), currentActor, currentExecutor.getIdentity());
-#endif
+    SWIFT_TASK_DEBUG_LOG("processDefaultActor %p current executor now %p",
+                         currentActor, currentExecutor.getIdentity());
 
     if (!currentExecutor.isDefaultActor()) {
       // The job already gave up the thread for us.
@@ -1851,10 +1834,8 @@ static void runOnAssumedThread(AsyncTask *task, ExecutorRef executor,
   executor = trackingInfo.getActiveExecutor();
   trackingInfo.leave();
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] leaving assumed thread, current executor is %p\n",
-          _swift_get_thread_id(), executor.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("leaving assumed thread, current executor is %p",
+                       executor.getIdentity());
 
   if (executor.isDefaultActor())
     asImpl(executor.getDefaultActor())->giveUpThread(runner);
@@ -1868,11 +1849,9 @@ static void swift_task_switchImpl(SWIFT_ASYNC_CONTEXT AsyncContext *resumeContex
   auto currentExecutor =
     (trackingInfo ? trackingInfo->getActiveExecutor()
                   : ExecutorRef::generic());
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] trying to switch from executor %p to %p\n",
-          _swift_get_thread_id(), currentExecutor.getIdentity(),
-          newExecutor.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("trying to switch from executor %p to %p",
+                       currentExecutor.getIdentity(),
+                       newExecutor.getIdentity());
 
   // If the current executor is compatible with running the new executor,
   // we can just immediately continue running with the resume function
@@ -1898,21 +1877,18 @@ static void swift_task_switchImpl(SWIFT_ASYNC_CONTEXT AsyncContext *resumeContex
   if (canGiveUpThreadForSwitch(trackingInfo, currentExecutor) &&
       !shouldYieldThread() &&
       tryAssumeThreadForSwitch(newExecutor, runner)) {
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%lu] switch succeeded, task %p assumed thread for executor %p\n",
-            _swift_get_thread_id(), task, newExecutor.getIdentity());
-#endif
+    SWIFT_TASK_DEBUG_LOG(
+        "switch succeeded, task %p assumed thread for executor %p", task,
+        newExecutor.getIdentity());
     giveUpThreadForSwitch(currentExecutor, runner);
     // 'return' forces tail call
     return runOnAssumedThread(task, newExecutor, trackingInfo, runner);
   }
 
   // Otherwise, just asynchronously enqueue the task on the given
   // executor.
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] switch failed, task %p enqueued on executor %p\n",
-          _swift_get_thread_id(), task, newExecutor.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("switch failed, task %p enqueued on executor %p", task,
+                       newExecutor.getIdentity());
   task->flagAsSuspended();
   _swift_task_clearCurrent();
   swift_task_enqueue(task, newExecutor);
@@ -1932,10 +1908,8 @@ void _swift_task_enqueueOnExecutor(Job *job, HeapObject *executor,
 
 SWIFT_CC(swift)
 static void swift_task_enqueueImpl(Job *job, ExecutorRef executor) {
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] enqueue job %p on executor %p\n",
-          _swift_get_thread_id(), job, executor.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("enqueue job %p on executor %p", job,
+                       executor.getIdentity());
 
   assert(job && "no job provided");
 

stdlib/public/Concurrency/AsyncLet.cpp

@@ -176,13 +176,10 @@ void swift::swift_asyncLet_begin(AsyncLet *alet,
                                  void *closureEntryPoint,
                                  HeapObject *closureContext,
                                  void *resultBuffer) {
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] creating async let buffer of type %s at %p\n",
-          _swift_get_thread_id(),
-          swift_getTypeName(futureResultType, true).data,
-          resultBuffer);
-#endif
-  
+  SWIFT_TASK_DEBUG_LOG("creating async let buffer of type %s at %p",
+                       swift_getTypeName(futureResultType, true).data,
+                       resultBuffer);
+
   auto flags = TaskCreateFlags();
   flags.setEnqueueJob(true);
 
@@ -321,10 +318,7 @@ static void swift_asyncLet_endImpl(AsyncLet *alet) {
   AsyncTask *parent = swift_task_getCurrent();
   assert(parent && "async-let must have a parent task");
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] async let end of task %p, parent: %p\n",
-          _swift_get_thread_id(), task, parent);
-#endif
+  SWIFT_TASK_DEBUG_LOG("async let end of task %p, parent: %p", task, parent);
   _swift_task_dealloc_specific(parent, task);
 }
 
@@ -349,10 +343,8 @@ static void asyncLet_finish_after_task_completion(SWIFT_ASYNC_CONTEXT AsyncConte
   // and finally, release the task and destroy the async-let
   assert(swift_task_getCurrent() && "async-let must have a parent task");
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] async let end of task %p, parent: %p\n",
-          _swift_get_thread_id(), task, swift_task_getCurrent());
-#endif
+  SWIFT_TASK_DEBUG_LOG("async let end of task %p, parent: %p", task,
+                       swift_task_getCurrent());
   // Destruct the task.
   task->~AsyncTask();
   // Deallocate it out of the parent, if it was allocated there.

stdlib/public/Concurrency/Task.cpp

@@ -84,20 +84,16 @@ FutureFragment::Status AsyncTask::waitFuture(AsyncTask *waitingTask,
     switch (queueHead.getStatus()) {
     case Status::Error:
     case Status::Success:
-#if SWIFT_TASK_PRINTF_DEBUG
-      fprintf(stderr, "[%lu] task %p waiting on task %p, completed immediately\n",
-              _swift_get_thread_id(), waitingTask, this);
-#endif
+      SWIFT_TASK_DEBUG_LOG("task %p waiting on task %p, completed immediately",
+                           waitingTask, this);
       _swift_tsan_acquire(static_cast<Job *>(this));
       if (contextIntialized) waitingTask->flagAsRunning();
       // The task is done; we don't need to wait.
       return queueHead.getStatus();
 
     case Status::Executing:
-#if SWIFT_TASK_PRINTF_DEBUG
-      fprintf(stderr, "[%lu] task %p waiting on task %p, going to sleep\n",
-              _swift_get_thread_id(), waitingTask, this);
-#endif
+      SWIFT_TASK_DEBUG_LOG("task %p waiting on task %p, going to sleep",
+                           waitingTask, this);
       _swift_tsan_release(static_cast<Job *>(waitingTask));
       // Task is not complete. We'll need to add ourselves to the queue.
       break;
@@ -183,21 +179,16 @@ void AsyncTask::completeFuture(AsyncContext *context) {
   // Schedule every waiting task on the executor.
   auto waitingTask = queueHead.getTask();
 
-#if SWIFT_TASK_PRINTF_DEBUG
   if (!waitingTask)
-    fprintf(stderr, "[%lu] task %p had no waiting tasks\n",
-            _swift_get_thread_id(), this);
-#endif
+    SWIFT_TASK_DEBUG_LOG("task %p had no waiting tasks", this);
 
   while (waitingTask) {
     // Find the next waiting task before we invalidate it by resuming
     // the task.
     auto nextWaitingTask = waitingTask->getNextWaitingTask();
 
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%lu] waking task %p from future of task %p\n",
-            _swift_get_thread_id(), waitingTask, this);
-#endif
+    SWIFT_TASK_DEBUG_LOG("waking task %p from future of task %p", waitingTask,
+                         this);
 
     // Fill in the return context.
     auto waitingContext =
@@ -247,9 +238,7 @@ static void destroyTask(SWIFT_CONTEXT HeapObject *obj) {
   // the task-local allocator.  There's actually nothing else to clean up
   // here.
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] destroy task %p\n", _swift_get_thread_id(), task);
-#endif
+  SWIFT_TASK_DEBUG_LOG("destroy task %p", task);
   free(task);
 }
 
@@ -322,9 +311,7 @@ static void completeTaskImpl(AsyncTask *task,
 
   task->Private.complete(task);
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] task %p completed\n", _swift_get_thread_id(), task);
-#endif
+  SWIFT_TASK_DEBUG_LOG("task %p completed", task);
 
   // Complete the future.
   // Warning: This deallocates the task in case it's an async let task.
@@ -562,10 +549,8 @@ static AsyncTaskAndContext swift_task_create_commonImpl(
   } else {
     allocation = malloc(amountToAllocate);
   }
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] allocate task %p, parent = %p, slab %u\n",
-          _swift_get_thread_id(), allocation, parent, initialSlabSize);
-#endif
+  SWIFT_TASK_DEBUG_LOG("allocate task %p, parent = %p, slab %u", allocation,
+                       parent, initialSlabSize);
 
   AsyncContext *initialContext =
     reinterpret_cast<AsyncContext*>(
@@ -640,10 +625,7 @@ static AsyncTaskAndContext swift_task_create_commonImpl(
     futureAsyncContextPrefix->indirectResult = futureFragment->getStoragePtr();
   }
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] creating task %p with parent %p\n",
-          _swift_get_thread_id(), task, parent);
-#endif
+  SWIFT_TASK_DEBUG_LOG("creating task %p with parent %p", task, parent);
 
   // Initialize the task-local allocator.
   initialContext->ResumeParent = reinterpret_cast<TaskContinuationFunction *>(

stdlib/public/Concurrency/TaskPrivate.h

@@ -41,8 +41,14 @@
 
 namespace swift {
 
-// Uncomment to enable helpful debug spew to stderr
-//#define SWIFT_TASK_PRINTF_DEBUG 1
+// Set to 1 to enable helpful debug spew to stderr
+#if 0
+#define SWIFT_TASK_DEBUG_LOG(fmt, ...)                                         \
+  fprintf(stderr, "[%lu] " fmt "\n", (unsigned long)_swift_get_thread_id(),    \
+          __VA_ARGS__)
+#else
+#define SWIFT_TASK_DEBUG_LOG(fmt, ...) (void)0
+#endif
 
 #if defined(_WIN32)
 using ThreadID = decltype(GetCurrentThreadId());
@@ -405,10 +411,7 @@ inline void AsyncTask::flagAsSuspended() {
 // that can be used when debugging locally to instrument when a task actually is
 // dealloced.
 inline void AsyncTask::flagAsCompleted() {
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%lu] task completed %p\n",
-          _swift_get_thread_id(), this);
-#endif
+  SWIFT_TASK_DEBUG_LOG("task completed %p", this);
 }
 
 inline void AsyncTask::localValuePush(const HeapObject *key,

stdlib/public/Concurrency/ThreadSanitizer.cpp

@@ -31,18 +31,14 @@ TSanFunc *tsan_acquire, *tsan_release;
 void swift::_swift_tsan_acquire(void *addr) {
   if (tsan_acquire) {
     tsan_acquire(addr);
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%lu] tsan_acquire on %p\n", _swift_get_thread_id(), addr);
-#endif
+    SWIFT_TASK_DEBUG_LOG("tsan_acquire on %p", addr);
   }
 }
 
 void swift::_swift_tsan_release(void *addr) {
   if (tsan_release) {
     tsan_release(addr);
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%lu] tsan_release on %p\n", _swift_get_thread_id(), addr);
-#endif
+    SWIFT_TASK_DEBUG_LOG("tsan_release on %p", addr);
   }
 }