Add some lock contention checking
authorBen Gamari <ben@smart-cactus.org>
Sun, 14 Apr 2019 14:46:40 +0000 (10:46 -0400)
committerBen Gamari <ben@smart-cactus.org>
Wed, 19 Jun 2019 01:44:00 +0000 (21:44 -0400)
12 files changed:
includes/rts/OSThreads.h
rts/LongPause.c [new file with mode: 0644]
rts/LongPause.h [new file with mode: 0644]
rts/Schedule.c
rts/StableName.c
rts/StablePtr.c
rts/StaticPtrTable.c
rts/Threads.c
rts/rts.cabal.in
rts/sm/GC.c
rts/sm/NonMoving.c
rts/sm/Storage.h

index 322624e..96f5b65 100644 (file)
@@ -200,8 +200,10 @@ void  freeThreadLocalKey (ThreadLocalKey *key);
 void setThreadAffinity (uint32_t n, uint32_t m);
 void setThreadNode (uint32_t node);
 void releaseThreadNode (void);
+
 #endif // !CMINUSMINUS
 
+
 #if defined(THREADED_RTS)
 
 #define ACQUIRE_LOCK(l) OS_ACQUIRE_LOCK(l)
diff --git a/rts/LongPause.c b/rts/LongPause.c
new file mode 100644 (file)
index 0000000..97f0bd3
--- /dev/null
@@ -0,0 +1,30 @@
+/* ---------------------------------------------------------------------------
+ *
+ * (c) The GHC Team, 2001-2005
+ *
+ * Catching long lock-acquisition pauses.
+ *
+ * --------------------------------------------------------------------------*/
+
+
+#include "PosixSource.h"
+
+#include "Rts.h"
+#include "Trace.h"
+#include "LongPause.h"
+
+#if defined(THREADED_RTS)
+
+void longPauseCb(uint64_t dur_ns STG_UNUSED, const char *desc STG_UNUSED) {
+  trace(TRACE_gc, "LONG PAUSE(%s) %f", desc, 1.0 * dur_ns / 1e9);
+}
+
+void ACQUIRE_LOCK_CHECKED_(Mutex *mutex, int max_msec, const char *desc) {
+  struct long_pause_ctx ctx;
+  LONG_PAUSE_START(&ctx);
+  ACQUIRE_LOCK(mutex);
+  LONG_PAUSE_END(&ctx, max_msec, desc);
+}
+
+#endif
+
diff --git a/rts/LongPause.h b/rts/LongPause.h
new file mode 100644 (file)
index 0000000..bf5bdc0
--- /dev/null
@@ -0,0 +1,67 @@
+/* ---------------------------------------------------------------------------
+ *
+ * (c) The GHC Team, 2001-2005
+ *
+ * Accessing OS threads functionality in a (mostly) OS-independent
+ * manner.
+ *
+ * --------------------------------------------------------------------------*/
+
+#pragma once
+
+#include "rts/OSThreads.h"
+
+#include "BeginPrivate.h"
+
+void longPauseCb (uint64_t dur_ns, const char *desc);
+
+#if !defined(CMINUSMINUS)
+
+#if defined(THREADED_RTS)
+
+#include <time.h>
+
+struct long_pause_ctx {
+  struct timespec start;
+};
+
+INLINE_HEADER void LONG_PAUSE_START(struct long_pause_ctx *ctx) {
+  clock_gettime(CLOCK_MONOTONIC, &ctx->start);
+}
+
+INLINE_HEADER void LONG_PAUSE_END(struct long_pause_ctx *ctx, int max_msec, const char *desc) {
+  struct timespec end;
+  clock_gettime(CLOCK_MONOTONIC, &end);
+  int64_t dt = (end.tv_sec - ctx->start.tv_sec) * 1000*1000*1000 + end.tv_nsec - ctx->start.tv_nsec;
+  if (dt > max_msec * 1000*1000) {
+    longPauseCb(dt, desc);
+  }
+}
+
+/* Acquire the given lock, checking that it takes no more than max_msecs to do
+ * so.
+ */
+void ACQUIRE_LOCK_CHECKED_(Mutex *mutex, int max_msec, const char *desc);
+
+/* Acquire the given lock, checking that it takes a reasonable amount of time
+ * to do so.
+ */
+INLINE_HEADER void ACQUIRE_LOCK_CHECKED(Mutex *mutex, const char *desc) {
+  ACQUIRE_LOCK_CHECKED_(mutex, 100, desc);
+}
+
+#else
+
+struct long_pause_ctx {};
+INLINE_HEADER void LONG_PAUSE_START(struct long_pause_ctx *ctx STG_UNUSED) {}
+INLINE_HEADER void LONG_PAUSE_END(struct long_pause_ctx *ctx STG_UNUSED, int max_msec STG_UNUSED, const char *desc STG_UNUSED) {}
+
+#define ACQUIRE_LOCK_CHECKED(l,desc)
+#define ACQUIRE_LOCK_CHECKED_(l,m,desc)
+
+#endif /* defined(THREADED_RTS) */
+
+#endif /* !CMINUSMINUS */
+
+#include "EndPrivate.h"
+
index 0a5ac94..dbe3377 100644 (file)
@@ -20,6 +20,7 @@
 #include "sm/Sanity.h"
 #include "Stats.h"
 #include "STM.h"
+#include "LongPause.h"
 #include "Prelude.h"
 #include "ThreadLabels.h"
 #include "Updates.h"
@@ -1462,7 +1463,7 @@ static bool requestSync (
             // mark thread). Consequently we must wait until the pending sync is
             // finished before proceeding to ensure we don't loop.
             // TODO: Don't busy-wait
-            ACQUIRE_LOCK(&sync_finished_mutex);
+            ACQUIRE_LOCK_CHECKED(&sync_finished_mutex, "sync_finished_mutex");
             while (pending_sync) {
                 waitCondition(&sync_finished_cond, &sync_finished_mutex);
             }
index 4b26fee..c7bc72e 100644 (file)
@@ -13,6 +13,7 @@
 #include "RtsAPI.h"
 
 #include "Hash.h"
+#include "LongPause.h"
 #include "RtsUtils.h"
 #include "Trace.h"
 #include "StableName.h"
@@ -42,7 +43,7 @@ void
 stableNameLock(void)
 {
     initStableNameTable();
-    ACQUIRE_LOCK(&stable_name_mutex);
+    ACQUIRE_LOCK_CHECKED(&stable_name_mutex, "stable_name_mutex");
 }
 
 void
index 2181b83..7a1a5df 100644 (file)
@@ -13,6 +13,7 @@
 #include "RtsAPI.h"
 
 #include "Hash.h"
+#include "LongPause.h"
 #include "RtsUtils.h"
 #include "Trace.h"
 #include "StablePtr.h"
@@ -125,7 +126,7 @@ void
 stablePtrLock(void)
 {
     initStablePtrTable();
-    ACQUIRE_LOCK(&stable_ptr_mutex);
+    ACQUIRE_LOCK_CHECKED(&stable_ptr_mutex, "stable_ptr_mutex");
 }
 
 void
index f5e6239..e1c49ad 100644 (file)
@@ -12,6 +12,7 @@
 #include "Rts.h"
 #include "RtsUtils.h"
 #include "Hash.h"
+#include "LongPause.h"
 #include "StablePtr.h"
 
 static HashTable * spt = NULL;
@@ -44,7 +45,7 @@ void hs_spt_insert_stableptr(StgWord64 key[2], StgStablePtr *entry) {
 #endif
   }
 
-  ACQUIRE_LOCK(&spt_lock);
+  ACQUIRE_LOCK_CHECKED(&spt_lock, "spt_lock");
   insertHashTable(spt, (StgWord)key, entry);
   RELEASE_LOCK(&spt_lock);
 }
@@ -67,7 +68,7 @@ static void freeSptEntry(void* entry) {
 
 void hs_spt_remove(StgWord64 key[2]) {
    if (spt) {
-     ACQUIRE_LOCK(&spt_lock);
+     ACQUIRE_LOCK_CHECKED(&spt_lock, "spt_lock");
      StgStablePtr* entry = removeHashTable(spt, (StgWord)key, NULL);
      RELEASE_LOCK(&spt_lock);
 
@@ -78,7 +79,7 @@ void hs_spt_remove(StgWord64 key[2]) {
 
 StgPtr hs_spt_lookup(StgWord64 key1, StgWord64 key2) {
   if (spt) {
-    ACQUIRE_LOCK(&spt_lock);
+    ACQUIRE_LOCK_CHECKED(&spt_lock, "spt_lock");
     StgWord64 key[2] = { key1, key2 };
     const StgStablePtr * entry = lookupHashTable(spt, (StgWord)key);
     const StgPtr ret = entry ? deRefStablePtr(*entry) : NULL;
@@ -90,7 +91,7 @@ StgPtr hs_spt_lookup(StgWord64 key1, StgWord64 key2) {
 
 int hs_spt_keys(StgPtr keys[], int szKeys) {
   if (spt) {
-    ACQUIRE_LOCK(&spt_lock);
+    ACQUIRE_LOCK_CHECKED(&spt_lock, "spt_lock");
     const int ret = keysHashTable(spt, (StgWord*)keys, szKeys);
     RELEASE_LOCK(&spt_lock);
     return ret;
index 03e9380..8b84c71 100644 (file)
@@ -10,6 +10,7 @@
 #include "Rts.h"
 
 #include "Capability.h"
+#include "LongPause.h"
 #include "Updates.h"
 #include "Threads.h"
 #include "STM.h"
@@ -124,7 +125,7 @@ createThread(Capability *cap, W_ size)
 
     /* Link the new thread on the global thread list.
      */
-    ACQUIRE_LOCK(&sched_mutex);
+    ACQUIRE_LOCK_CHECKED(&sched_mutex, "sched_mutex");
     tso->id = next_thread_id++;  // while we have the mutex
     tso->global_link = g0->threads;
     g0->threads = tso;
index a3f74be..63cca92 100644 (file)
@@ -137,6 +137,7 @@ library
                       rts/Libdw.h
                       rts/LibdwPool.h
                       rts/Linker.h
+                      rts/LongPause.h
                       rts/Main.h
                       rts/Messages.h
                       rts/OSThreads.h
@@ -392,6 +393,7 @@ library
                Libdw.c
                LibdwPool.c
                Linker.c
+               LongPause.c
                Messages.c
                OldARMAtomic.c
                PathUtils.c
index 0e80ec4..ed4a6d3 100644 (file)
@@ -37,6 +37,7 @@
 #include "Schedule.h"
 #include "Sanity.h"
 #include "BlockAlloc.h"
+#include "LongPause.h"
 #include "ProfHeap.h"
 #include "Weak.h"
 #include "Prelude.h"
@@ -284,6 +285,9 @@ GarbageCollect (uint32_t collect_gen,
   }
 #endif
 
+  struct long_pause_ctx gc_pause;
+  LONG_PAUSE_START(&gc_pause);
+
   /* N.B. The nonmoving collector works a bit differently. See
    * Note [Static objects under the nonmoving collector].
    */
@@ -386,6 +390,9 @@ GarbageCollect (uint32_t collect_gen,
   // of markSomeCapabilities() because markSomeCapabilities() can only
   // call back into the GC via mark_root() (due to the gct register
   // variable).
+  trace(TRACE_gc, "scavenging mut_lists");
+  struct long_pause_ctx pause;
+  LONG_PAUSE_START(&pause);
   if (n_gc_threads == 1) {
       for (n = 0; n < n_capabilities; n++) {
 #if defined(THREADED_RTS)
@@ -404,8 +411,11 @@ GarbageCollect (uint32_t collect_gen,
           }
       }
   }
+  LONG_PAUSE_END(&pause, 20, "scav mut_lists");
+  trace(TRACE_gc, "done scavenging mut_lists");
 
   // follow roots from the CAF list (used by GHCi)
+  LONG_PAUSE_START(&pause);
   gct->evac_gen_no = 0;
   markCAFs(mark_root, gct);
 
@@ -419,7 +429,9 @@ GarbageCollect (uint32_t collect_gen,
   } else {
       markCapability(mark_root, gct, cap, true/*don't mark sparks*/);
   }
+  LONG_PAUSE_END(&pause, 50, "mark caps&sched");
 
+  LONG_PAUSE_START(&pause);
   markScheduler(mark_root, gct);
 
   // Mark the weak pointer list, and prepare to detect dead weak pointers.
@@ -431,6 +443,7 @@ GarbageCollect (uint32_t collect_gen,
 
   // Remember old stable name addresses.
   rememberOldStableNameAddresses ();
+  LONG_PAUSE_END(&pause, 50, "mark stables&weaks");
 
   /* -------------------------------------------------------------------------
    * Repeatedly scavenge all the areas we know about until there's no
@@ -440,6 +453,7 @@ GarbageCollect (uint32_t collect_gen,
   StgWeak *dead_weak_ptr_list = NULL;
   StgTSO *resurrected_threads = END_TSO_QUEUE;
 
+  LONG_PAUSE_START(&pause);
   for (;;)
   {
       scavenge_until_all_done();
@@ -459,6 +473,7 @@ GarbageCollect (uint32_t collect_gen,
   }
 
   shutdown_gc_threads(gct->thread_index, idle_cap);
+  LONG_PAUSE_END(&pause, 50, "scavenge loop");
 
   // Now see which stable names are still alive.
   gcStableNameTable();
@@ -760,12 +775,14 @@ GarbageCollect (uint32_t collect_gen,
       // so we need to mark those too.
       // Note that in sequential case these lists will be appended with more
       // weaks and threads found to be dead in mark.
+      LONG_PAUSE_START(&pause);
 #if !defined(THREADED_RTS)
       // In the non-threaded runtime this is the only time we push to the
       // upd_rem_set
       nonmovingAddUpdRemSetBlocks(&gct->cap->upd_rem_set.queue);
 #endif
       nonmovingCollect(&dead_weak_ptr_list, &resurrected_threads);
+      LONG_PAUSE_END(&pause, 50, "nonmovingCollect");
       ACQUIRE_SM_LOCK;
   }
 
@@ -931,6 +948,8 @@ GarbageCollect (uint32_t collect_gen,
              gc_spin_spin, gc_spin_yield, mut_spin_spin, mut_spin_yield,
              any_work, no_work, scav_find_work);
 
+  LONG_PAUSE_END(&gc_pause, major_gc ? 10000 : 100, "overall gc");
+
 #if defined(RTS_USER_SIGNALS)
   if (RtsFlags.MiscFlags.install_signal_handlers) {
     // unblock signals again
index 871a869..3520690 100644 (file)
@@ -18,6 +18,7 @@
 #include "GCTDecl.h"
 #include "Schedule.h"
 #include "Stats.h"
+#include "LongPause.h"
 
 #include "NonMoving.h"
 #include "NonMovingMark.h"
@@ -677,6 +678,8 @@ static void nonmovingPrepareMark(void)
     ASSERT(nonmovingHeap.sweep_list == NULL);
 
     nonmovingBumpEpoch();
+    struct long_pause_ctx pause;
+    LONG_PAUSE_START(&pause);
     for (int alloca_idx = 0; alloca_idx < NONMOVING_ALLOCA_CNT; ++alloca_idx) {
         struct NonmovingAllocator *alloca = nonmovingHeap.allocators[alloca_idx];
 
@@ -714,7 +717,9 @@ static void nonmovingPrepareMark(void)
         // they were set after they were swept and haven't seen any allocation
         // since.
     }
+    LONG_PAUSE_END(&pause, 20, "take-snapshot");
 
+    LONG_PAUSE_START(&pause);
     ASSERT(oldest_gen->scavenged_large_objects == NULL);
     bdescr *next;
     for (bdescr *bd = oldest_gen->large_objects; bd; bd = next) {
@@ -722,6 +727,7 @@ static void nonmovingPrepareMark(void)
         bd->flags |= BF_NONMOVING_SWEEPING;
         dbl_link_onto(bd, &nonmoving_large_objects);
     }
+    LONG_PAUSE_END(&pause, 20, "large-objects");
     n_nonmoving_large_blocks += oldest_gen->n_large_blocks;
     oldest_gen->large_objects = NULL;
     oldest_gen->n_large_words = 0;
@@ -799,7 +805,10 @@ void nonmovingCollect(StgWeak **dead_weaks, StgTSO **resurrected_threads)
 
     resizeGenerations();
 
+    struct long_pause_ctx pause;
+    LONG_PAUSE_START(&pause);
     nonmovingPrepareMark();
+    LONG_PAUSE_END(&pause, 20, "prepare-mark");
 
     // N.B. These should have been cleared at the end of the last sweep.
     ASSERT(nonmoving_marked_large_objects == NULL);
@@ -807,6 +816,7 @@ void nonmovingCollect(StgWeak **dead_weaks, StgTSO **resurrected_threads)
     ASSERT(nonmoving_marked_compact_objects == NULL);
     ASSERT(n_nonmoving_marked_compact_blocks == 0);
 
+    LONG_PAUSE_START(&pause);
     MarkQueue *mark_queue = stgMallocBytes(sizeof(MarkQueue), "mark queue");
     initMarkQueue(mark_queue);
     current_mark_queue = mark_queue;
@@ -825,6 +835,7 @@ void nonmovingCollect(StgWeak **dead_weaks, StgTSO **resurrected_threads)
     for (StgTSO *tso = *resurrected_threads; tso != END_TSO_QUEUE; tso = tso->global_link) {
         markQueuePushClosure_(mark_queue, (StgClosure*)tso);
     }
+    LONG_PAUSE_END(&pause, 20, "root-marking");
 
     // Roots marked, mark threads and weak pointers
 
index cdb9720..5bb7806 100644 (file)
@@ -9,6 +9,7 @@
 #pragma once
 
 #include "Capability.h"
+#include "LongPause.h"
 
 #include "BeginPrivate.h"
 
@@ -34,7 +35,7 @@ extern Mutex sm_mutex;
 #endif
 
 #if defined(THREADED_RTS)
-#define ACQUIRE_SM_LOCK   ACQUIRE_LOCK(&sm_mutex);
+#define ACQUIRE_SM_LOCK   ACQUIRE_LOCK_CHECKED(&sm_mutex, "sm_lock");
 #define RELEASE_SM_LOCK   RELEASE_LOCK(&sm_mutex);
 #define ASSERT_SM_LOCK()  ASSERT_LOCK_HELD(&sm_mutex);
 #else