add extra lock tracing to threads::shared
authorTony Cook <tony@develop-help.com>
Wed, 27 Feb 2019 01:01:12 +0000 (12:01 +1100)
committerTony Cook <tony@develop-help.com>
Thu, 7 Mar 2019 23:36:13 +0000 (10:36 +1100)
This was useful in tracing the cause for the deadlock in #124203.

This can be enabled during a build of perl by adding:

  -Accflags=-DSHARED_TRACE_LOCKS -DDEBUGGING

to the Configure command-line.

To see the trace at run-time add -DU or -DUv to the perl command-line.

The original DEBUG_LOCKS tracing using warn caused extra calls
confusing back traces when trying to debug this problem.

dist/threads-shared/shared.xs

index d0f7d1e..6cdf094 100644 (file)
  * without the prefix (e.g., sv, tmp or obj).
  */
 
+/* this is lower overhead than warn() and less likely to interfere
+   with other parts of perl (like with the debugger.)
+*/
+#ifdef SHARED_TRACE_LOCKS
+#  define TRACE_LOCK(x) DEBUG_U(x)
+#  define TRACE_LOCKv(x) DEBUG_Uv(x)
+#else
+#  define TRACE_LOCK(x)
+#  define TRACE_LOCKv(x)
+#endif
+
 #define PERL_NO_GET_CONTEXT
 #include "EXTERN.h"
 #include "perl.h"
@@ -211,8 +222,24 @@ recursive_lock_release(pTHX_ recursive_lock_t *lock)
         if (--lock->locks == 0) {
             lock->owner = NULL;
             COND_SIGNAL(&lock->cond);
+            TRACE_LOCK(
+                    PerlIO_printf(Perl_debug_log, "shared lock released %p for %p at %s:%d\n",
+                                  lock, aTHX, CopFILE(PL_curcop), CopLINE(PL_curcop))
+                    );
+        }
+        else {
+            TRACE_LOCKv(
+                    PerlIO_printf(Perl_debug_log, "shared lock unbump %p for %p at %s:%d\n",
+                                  lock, aTHX, CopFILE(PL_curcop), CopLINE(PL_curcop))
+                    );
         }
     }
+    else {
+        TRACE_LOCK(
+                PerlIO_printf(Perl_debug_log, "bad shared lock release %p for %p (owned by %p) at %s:%d\n",
+                               lock, aTHX, lock->owner, CopFILE(PL_curcop), CopLINE(PL_curcop))
+                 );
+    }
     MUTEX_UNLOCK(&lock->mutex);
 }
 
@@ -224,8 +251,16 @@ recursive_lock_acquire(pTHX_ recursive_lock_t *lock, const char *file, int line)
     assert(aTHX);
     MUTEX_LOCK(&lock->mutex);
     if (lock->owner == aTHX) {
+        TRACE_LOCKv(
+                 PerlIO_printf(Perl_debug_log, "shared lock bump %p (%p) at %s:%d\n",
+                               lock, lock->owner, CopFILE(PL_curcop), CopLINE(PL_curcop))
+                 );
         lock->locks++;
     } else {
+        TRACE_LOCK(
+                 PerlIO_printf(Perl_debug_log, "shared lock try %p for %p (owned by %p) at %s:%d\n",
+                               lock, aTHX, lock->owner, CopFILE(PL_curcop), CopLINE(PL_curcop))
+                 );
         while (lock->owner) {
 #ifdef DEBUG_LOCKS
             Perl_warn(aTHX_ " %p waiting - owned by %p %s:%d\n",
@@ -233,6 +268,10 @@ recursive_lock_acquire(pTHX_ recursive_lock_t *lock, const char *file, int line)
 #endif
             COND_WAIT(&lock->cond,&lock->mutex);
         }
+        TRACE_LOCK(
+                 PerlIO_printf(Perl_debug_log, "shared lock got %p at %s:%d\n",
+                               lock, CopFILE(PL_curcop), CopLINE(PL_curcop))
+                 );
         lock->locks = 1;
         lock->owner = aTHX;
 #ifdef DEBUG_LOCKS