[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.

(cherry picked from commit d5c0469)

Author: mikeash

stdlib/public/Concurrency/Actor.cpp

@@ -260,9 +260,7 @@ static ExecutorRef swift_task_getCurrentExecutorImpl() {
   auto currentTracking = ExecutorTrackingInfo::current();
   auto result = (currentTracking ? currentTracking->getActiveExecutor()
                                  : ExecutorRef::generic());
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%p] getting current executor %p\n", pthread_self(), result.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("getting current executor %p", result.getIdentity());
   return result;
 }
 
@@ -1158,9 +1156,7 @@ static Job *preprocessQueue(JobRef first,
 }
 
 void DefaultActorImpl::giveUpThread(RunningJobInfo runner) {
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%p] giving up thread for actor %p\n", pthread_self(), 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());
 
@@ -1220,13 +1216,11 @@ void DefaultActorImpl::giveUpThread(RunningJobInfo runner) {
       // Try again.
       continue;
     }
-    
-#if SWIFT_TASK_PRINTF_DEBUG
-#  define LOG_STATE_TRANSITION fprintf(stderr, "[%p] actor %p transitioned from %zx to %zx (%s)\n", \
-  pthread_self(), 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.
@@ -1478,9 +1472,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, "[%p] processDefaultActor %p\n", pthread_self(), 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.
@@ -1504,9 +1496,8 @@ static void processDefaultActor(DefaultActorImpl *currentActor,
     auto job = currentActor->claimNextJobOrGiveUp(threadIsRunningActor,
                                                   runner);
 
-#if SWIFT_TASK_PRINTF_DEBUG
-    fprintf(stderr, "[%p] processDefaultActor %p claimed job %p\n", pthread_self(), 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) {
@@ -1526,9 +1517,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, "[%p] processDefaultActor %p current executor now %p\n", pthread_self(), 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.
@@ -1827,9 +1817,8 @@ static void runOnAssumedThread(AsyncTask *task, ExecutorRef executor,
   executor = trackingInfo.getActiveExecutor();
   trackingInfo.leave();
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%p] leaving assumed thread, current executor is %p\n", pthread_self(), executor.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("leaving assumed thread, current executor is %p",
+                       executor.getIdentity());
 
   if (executor.isDefaultActor())
     asImpl(executor.getDefaultActor())->giveUpThread(runner);
@@ -1843,9 +1832,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, "[%p] trying to switch from executor %p to %p\n", pthread_self(), 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
@@ -1871,19 +1860,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, "[%p] switch succeeded, task %p assumed thread for executor %p\n", pthread_self(), 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, "[%p] switch failed, task %p enqueued on executor %p\n", pthread_self(), task, newExecutor.getIdentity());
-#endif
+  SWIFT_TASK_DEBUG_LOG("switch failed, task %p enqueued on executor %p", task,
+                       newExecutor.getIdentity());
   task->flagAsSuspended();
   swift_task_enqueue(task, newExecutor);
 }
@@ -1902,9 +1890,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, "[%p] enqueue job %p on executor %p\n", pthread_self(), 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

@@ -178,13 +178,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);
 
@@ -323,9 +320,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, "[%p] async let end of task %p, parent: %p\n", pthread_self(), task, parent);
-#endif
+  SWIFT_TASK_DEBUG_LOG("async let end of task %p, parent: %p", task, parent);
   _swift_task_dealloc_specific(parent, task);
 }
 
@@ -350,10 +345,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

@@ -83,18 +83,16 @@ FutureFragment::Status AsyncTask::waitFuture(AsyncTask *waitingTask,
     switch (queueHead.getStatus()) {
     case Status::Error:
     case Status::Success:
-#if SWIFT_TASK_PRINTF_DEBUG
-      fprintf(stderr, "[%p] task %p waiting on task %p, completed immediately\n", pthread_self(), 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, "[%p] task %p waiting on task %p, going to sleep\n", pthread_self(), 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;
@@ -179,19 +177,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, "[%p] task %p had no waiting tasks\n", pthread_self(), 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, "[%p] waking task %p from future of task %p\n", pthread_self(), waitingTask, this);
-#endif
+    SWIFT_TASK_DEBUG_LOG("waking task %p from future of task %p", waitingTask,
+                         this);
 
     // Fill in the return context.
     auto waitingContext =
@@ -241,9 +236,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, "[%p] destroy task %p\n", pthread_self(), task);
-#endif
+  SWIFT_TASK_DEBUG_LOG("destroy task %p", task);
   free(task);
 }
 
@@ -316,9 +309,7 @@ static void completeTaskImpl(AsyncTask *task,
 
   task->Private.complete(task);
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%p] task %p completed\n", pthread_self(), 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.
@@ -556,10 +547,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",
-          pthread_self(), allocation, parent, initialSlabSize);
-#endif
+  SWIFT_TASK_DEBUG_LOG("allocate task %p, parent = %p, slab %u", allocation,
+                       parent, initialSlabSize);
 
   AsyncContext *initialContext =
     reinterpret_cast<AsyncContext*>(
@@ -638,9 +627,7 @@ static AsyncTaskAndContext swift_task_create_commonImpl(
     futureAsyncContextPrefix->indirectResult = futureFragment->getStoragePtr();
   }
 
-#if SWIFT_TASK_PRINTF_DEBUG
-  fprintf(stderr, "[%p] creating task %p with parent %p\n", pthread_self(), 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

@@ -29,8 +29,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
 
 class AsyncTask;
 class TaskGroup;
@@ -393,10 +399,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);
   }
 }