[exclusivity] Introduce an env variable to in asserts builds cause the exclusivity part of the runtime to emit logging information.

The specific environment variable is SWIFT_DEBUG_RUNTIME_EXCLUSIVITY_LOGGING. We only
check the environment the first time we try to lookup the TLSContext, so it
shouldn't impact exclusivity performance.

My intention is to use this to write some FileCheck tests so that we can really
be sure that the runtime is doing what we think it is. As such I also changed
the small amount of logging routines meant for use in the debugger to use stdout.

Author: gottesmm

stdlib/public/runtime/EnvironmentVariables.def

@@ -62,4 +62,11 @@ VARIABLE(SWIFT_DEBUG_ENABLE_SHARED_CACHE_PROTOCOL_CONFORMANCES, bool, true,
 
 #endif
 
+#ifndef NDEBUG
+
+VARIABLE(SWIFT_DEBUG_RUNTIME_EXCLUSIVITY_LOGGING, bool, false,
+         "Enable the an asserts runtime to emit logging as it works.")
+
+#endif
+
 #undef VARIABLE

stdlib/public/runtime/Exclusivity.cpp

@@ -27,10 +27,11 @@
 #include "swift/Basic/Lazy.h"
 #include "swift/Runtime/Config.h"
 #include "swift/Runtime/Debug.h"
+#include "swift/Runtime/EnvironmentVariables.h"
 #include "swift/Runtime/Metadata.h"
 #include "swift/Runtime/ThreadLocalStorage.h"
-#include <memory>
 #include <inttypes.h>
+#include <memory>
 #include <stdio.h>
 
 // Pick a return-address strategy
@@ -56,6 +57,16 @@ static const char *getAccessName(ExclusivityFlags flags) {
   }
 }
 
+// In asserts builds if the environment variable
+// SWIFT_DEBUG_RUNTIME_EXCLUSIVITY_LOGGING is set, emit logging information.
+#ifndef NDEBUG
+
+static inline bool isExclusivityLoggingEnabled() {
+  return runtime::environment::SWIFT_DEBUG_RUNTIME_EXCLUSIVITY_LOGGING();
+}
+
+#endif
+
 SWIFT_ALWAYS_INLINE
 static void reportExclusivityConflict(ExclusivityFlags oldAction, void *oldPC,
                                       ExclusivityFlags newFlags, void *newPC,
@@ -179,6 +190,10 @@ class AccessSet {
   constexpr bool isHead(Access *access) const { return Head == access; }
 
   bool insert(Access *access, void *pc, void *pointer, ExclusivityFlags flags) {
+#ifndef NDEBUG
+    if (isExclusivityLoggingEnabled())
+      fprintf(stderr, "Inserting new access: %p\n", access);
+#endif
     auto action = getAccessAction(flags);
 
     for (Access *cur = Head; cur != nullptr; cur = cur->getNext()) {
@@ -198,17 +213,33 @@ class AccessSet {
       // 0 means no backtrace will be printed.
       fatalError(0, "Fatal access conflict detected.\n");
     }
-    if (!isTracking(flags))
+    if (!isTracking(flags)) {
+#ifndef NDEBUG
+      if (isExclusivityLoggingEnabled()) {
+        fprintf(stderr, "  Not tracking!\n");
+      }
+#endif
       return false;
+    }
 
     // Insert to the front of the array so that remove tends to find it faster.
     access->initialize(pc, pointer, Head, action);
     Head = access;
+#ifndef NDEBUG
+    if (isExclusivityLoggingEnabled()) {
+      fprintf(stderr, "  Tracking!\n");
+      swift_dumpTrackedAccesses();
+    }
+#endif
     return true;
   }
 
   void remove(Access *access) {
     assert(Head && "removal from empty AccessSet");
+#ifndef NDEBUG
+    if (isExclusivityLoggingEnabled())
+      fprintf(stderr, "Removing access: %p\n", access);
+#endif
     auto cur = Head;
     // Fast path: stack discipline.
     if (cur == access) {
@@ -419,9 +450,14 @@ char *swift::swift_getOrigOfReplaceable(char **OrigFnPtr) {
 //
 // This is only intended to be used in the debugger.
 void swift::swift_dumpTrackedAccesses() {
-  getTLSContext().accessSet.forEach([](Access *a) {
-      fprintf(stderr, "Access. Pointer: %p. PC: %p. AccessAction: %s\n",
-              a->Pointer, a->PC, getAccessName(a->getAccessAction()));
+  auto &accessSet = getTLSContext().accessSet;
+  if (!accessSet) {
+    fprintf(stderr, "        No Accesses.\n");
+    return;
+  }
+  accessSet.forEach([](Access *a) {
+    fprintf(stderr, "        Access. Pointer: %p. PC: %p. AccessAction: %s\n",
+            a->Pointer, a->PC, getAccessName(a->getAccessAction()));
   });
 }
 
@@ -617,6 +653,15 @@ namespace {
 struct SwiftTaskThreadLocalContext {
   uintptr_t state[2];
 
+#ifndef NDEBUG
+  void dump() {
+    fprintf(stderr,
+            "        SwiftTaskThreadLocalContext: (FirstAccess,LastAccess): "
+            "(%p, %p)\n",
+            (void *)state[0], (void *)state[1]);
+  }
+#endif
+
   bool hasInitialAccessSet() const {
     // If state[0] is nullptr, we have an initial access set.
     return bool(state[0]);
@@ -633,6 +678,25 @@ struct SwiftTaskThreadLocalContext {
   void setTaskAccessSetHead(Access *newHead) { state[0] = uintptr_t(newHead); }
 
   void setTaskAccessSetTail(Access *newTail) { state[1] = uintptr_t(newTail); }
+
+#ifndef NDEBUG
+  const char *getTaskAddress() const {
+    // Constant only used when we have an asserts compiler so that we can output
+    // exactly the header location of the task for FileCheck purposes.
+    //
+    // WARNING: This test will fail if the Task ABI changes. When that happens,
+    // update the offset!
+    //
+    // TODO: This probably will need 32 bit help.
+#if __POINTER_WIDTH__ == 64
+    unsigned taskHeadOffsetFromTaskAccessSet = 128;
+#else
+    unsigned taskHeadOffsetFromTaskAccessSet = 68;
+#endif
+    auto *self = reinterpret_cast<const char *>(this);
+    return self - taskHeadOffsetFromTaskAccessSet;
+  }
+#endif
 };
 
 } // end anonymous namespace
@@ -642,6 +706,29 @@ void swift::swift_task_enterThreadLocalContext(char *state) {
   auto &taskCtx = *reinterpret_cast<SwiftTaskThreadLocalContext *>(state);
   auto &tlsCtxAccessSet = getTLSContext().accessSet;
 
+#ifndef NDEBUG
+  if (isExclusivityLoggingEnabled()) {
+    fprintf(stderr,
+            "Entering Thread Local Context. Before Swizzle. Task: %p\n",
+            taskCtx.getTaskAddress());
+    taskCtx.dump();
+    swift_dumpTrackedAccesses();
+  }
+
+  auto logEndState = [&] {
+    if (isExclusivityLoggingEnabled()) {
+      fprintf(stderr,
+              "Entering Thread Local Context. After Swizzle. Task: %p\n",
+              taskCtx.getTaskAddress());
+      taskCtx.dump();
+      swift_dumpTrackedAccesses();
+    }
+  };
+#else
+  // Just a no-op that should inline away.
+  auto logEndState = [] {};
+#endif
+
   // First handle all of the cases where our task does not start without an
   // initial access set.
   //
@@ -653,6 +740,7 @@ void swift::swift_task_enterThreadLocalContext(char *state) {
     //
     // Handles push cases 1-2.
     if (!tlsCtxAccessSet) {
+      logEndState();
       return;
     }
 
@@ -663,6 +751,7 @@ void swift::swift_task_enterThreadLocalContext(char *state) {
     //
     // Handles push cases 3-4.
     taskCtx.setTaskAccessSetHead(tlsCtxAccessSet.getHead());
+    logEndState();
     return;
   }
 
@@ -679,6 +768,7 @@ void swift::swift_task_enterThreadLocalContext(char *state) {
     tlsCtxAccessSet = taskCtx.getTaskAccessSetHead();
     taskCtx.setTaskAccessSetHead(nullptr);
     taskCtx.setTaskAccessSetTail(nullptr);
+    logEndState();
     return;
   }
 
@@ -694,13 +784,40 @@ void swift::swift_task_enterThreadLocalContext(char *state) {
   tail->setNext(oldHead);
   taskCtx.setTaskAccessSetHead(oldHead);
   taskCtx.setTaskAccessSetTail(nullptr);
+  logEndState();
 }
 
 // See algorithm description on SwiftTaskThreadLocalContext.
 void swift::swift_task_exitThreadLocalContext(char *state) {
   auto &taskCtx = *reinterpret_cast<SwiftTaskThreadLocalContext *>(state);
   auto &tlsCtxAccessSet = getTLSContext().accessSet;
 
+#ifndef NDEBUG
+  if (isExclusivityLoggingEnabled()) {
+    fprintf(stderr,
+            "Exiting Thread Local Context. Before Swizzle. Task: %p\n",
+            taskCtx.getTaskAddress());
+    taskCtx.dump();
+    swift_dumpTrackedAccesses();
+  }
+
+  auto logEndState = [&] {
+    if (isExclusivityLoggingEnabled()) {
+      fprintf(stderr,
+              "Exiting Thread Local Context. After Swizzle. Task: %p\n",
+              taskCtx.getTaskAddress());
+      taskCtx.dump();
+      swift_dumpTrackedAccesses();
+    }
+  };
+#else
+  // If we are not compiling with asserts, just use a simple identity function
+  // that should be inlined away.
+  //
+  // TODO: Can we use defer in the runtime?
+  auto logEndState = [] {};
+#endif
+
   // First check our ctx to see if we were tracking a previous synchronous
   // head. If we don't then we know that our synchronous thread was not
   // initially tracking any accesses.
@@ -719,6 +836,7 @@ void swift::swift_task_exitThreadLocalContext(char *state) {
     if (!tlsCtxAccessSet) {
       assert(taskCtx.getTaskAccessSetTail() == nullptr &&
              "Make sure we set this to nullptr when we pushed");
+      logEndState();
       return;
     }
 
@@ -735,6 +853,7 @@ void swift::swift_task_exitThreadLocalContext(char *state) {
     tlsCtxAccessSet = nullptr;
     taskCtx.setTaskAccessSetHead(newHead);
     taskCtx.setTaskAccessSetTail(newTail);
+    logEndState();
     return;
   }
 
@@ -752,6 +871,7 @@ void swift::swift_task_exitThreadLocalContext(char *state) {
   if (tlsCtxAccessSet.getHead() == oldHead) {
     taskCtx.setTaskAccessSetHead(nullptr);
     taskCtx.setTaskAccessSetTail(nullptr);
+    logEndState();
     return;
   }
 
@@ -770,4 +890,5 @@ void swift::swift_task_exitThreadLocalContext(char *state) {
   newEnd->setNext(nullptr);
   taskCtx.setTaskAccessSetHead(newHead);
   taskCtx.setTaskAccessSetTail(newEnd);
+  logEndState();
 }