Patch from Massimo Dal Zotto <dz@cs.unitn.it>

The following patches add to the backend a new debugging flag -K which prints
a debug trace of all locking operations on user relations (those with oid
greater than 20000). The code is compiled only if LOCK_MGR_DEBUG is defined,
so the patch should be harmless if not explicitly enabled.
I'm using the code to trace deadlock conditions caused by application queries
using the command "$POSTMASTER -D $PGDATA -o '-d 1 -K 1'.
The patches are for version 6.0 dated 970126.

diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index 0091aedcf803bea5fe86211cabfba1d5015eecba..116eb93c25b618a6417cb398fda6f88ae5eb8029 100644 (file)
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -7,7 +7,7 @@
  *
  *
  * IDENTIFICATION
- *    $Header: /cvsroot/pgsql/src/backend/storage/lmgr/lock.c,v 1.6 1996/12/26 17:50:26 momjian Exp $
+ *    $Header: /cvsroot/pgsql/src/backend/storage/lmgr/lock.c,v 1.7 1997/02/12 05:23:49 scrappy Exp $
  *
  * NOTES
  *    Outside modules can create a lock table and acquire/release
@@ -57,41 +57,65 @@
 
 #else /* LOCK_MGR_DEBUG */
 
+int lockDebug = 0;
+
+#ifndef LOCK_DEBUG_OID_MIN
+/*
+ * This is totally arbitrary. It is the minimum relation oid
+ * which will trigger the locking debug when the -K option
+ * is given to the backend. This is done to avoid tracing
+ * locks on system relations.
+ */
+#define LOCK_DEBUG_OID_MIN 20000
+#endif
+
 #define LOCK_PRINT(where,tag,type)\
-  elog(NOTICE, "%s: rel (%d) dbid (%d) tid (%d,%d) type (%d)\n",where, \
-        tag->relId, tag->dbId, \
-        ( (tag->tupleId.ip_blkid.data[0] >= 0) ? \
-               BlockIdGetBlockNumber(&tag->tupleId.ip_blkid) : -1 ), \
-        tag->tupleId.ip_posid, \
-        type);
+    if ((lockDebug >= 1) && (tag->relId >= LOCK_DEBUG_OID_MIN)) \
+        elog(DEBUG, \
+            "%s: pid (%d) rel (%d) dbid (%d) tid (%d,%d) type (%d)",where, \
+            getpid(),\
+            tag->relId, tag->dbId, \
+            ((tag->tupleId.ip_blkid.bi_hi<<16)+\
+             tag->tupleId.ip_blkid.bi_lo),\
+            tag->tupleId.ip_posid, \
+            type);
 
 #define LOCK_DUMP(where,lock,type)\
-  elog(NOTICE, "%s: rel (%d) dbid (%d) tid (%d,%d) nHolding (%d) holders (%d,%d,%d,%d,%d) type (%d)\n",where, \
-       lock->tag.relId, lock->tag.dbId, \
-       ((lock->tag.tupleId.ip_blkid.data[0] >= 0) ? \
-       BlockIdGetBlockNumber(&lock->tag.tupleId.ip_blkid) : -1 ), \
-       lock->tag.tupleId.ip_posid, \
-       lock->nHolding,\
-       lock->holders[1],\
-       lock->holders[2],\
-       lock->holders[3],\
-       lock->holders[4],\
-       lock->holders[5],\
-       type);
+    if ((lockDebug >= 1) && (lock->tag.relId >= LOCK_DEBUG_OID_MIN)) \
+        elog(DEBUG, \
+            "%s: pid (%d) rel (%d) dbid (%d) tid (%d,%d) nHolding (%d) "\
+            "holders (%d,%d,%d,%d,%d) type (%d)",where, \
+            getpid(),\
+            lock->tag.relId, lock->tag.dbId, \
+            ((lock->tag.tupleId.ip_blkid.bi_hi<<16)+\
+             lock->tag.tupleId.ip_blkid.bi_lo),\
+            lock->tag.tupleId.ip_posid, \
+            lock->nHolding,\
+            lock->holders[1],\
+            lock->holders[2],\
+            lock->holders[3],\
+            lock->holders[4],\
+            lock->holders[5],\
+            type);
 
 #define XID_PRINT(where,xidentP)\
-  elog(NOTICE,\
-       "%s:xid (%d) pid (%d) lock (%x) nHolding (%d) holders (%d,%d,%d,%d,%d)",\
-       where,\
-       xidentP->tag.xid,\
-       xidentP->tag.pid,\
-       xidentP->tag.lock,\
-       xidentP->nHolding,\
-       xidentP->holders[1],\
-       xidentP->holders[2],\
-       xidentP->holders[3],\
-       xidentP->holders[4],\
-       xidentP->holders[5]);
+    if ((lockDebug >= 2) && \
+       (((LOCK *)MAKE_PTR(xidentP->tag.lock))->tag.relId \
+        >= LOCK_DEBUG_OID_MIN)) \
+       elog(DEBUG,\
+            "%s: pid (%d) xid (%d) pid (%d) lock (%x) nHolding (%d) "\
+            "holders (%d,%d,%d,%d,%d)",\
+            where,\
+            getpid(),\
+            xidentP->tag.xid,\
+            xidentP->tag.pid,\
+            xidentP->tag.lock,\
+            xidentP->nHolding,\
+            xidentP->holders[1],\
+            xidentP->holders[2],\
+            xidentP->holders[3],\
+            xidentP->holders[4],\
+            xidentP->holders[5]);
 
 #endif /* LOCK_MGR_DEBUG */
 
@@ -528,7 +552,7 @@ LockAcquire(LockTableId tableId, LOCKTAG *lockName, LOCKT lockt)
        }
     if (!found)
        {
-           XID_PRINT("queueing XidEnt LockAcquire:", result);
+           XID_PRINT("LockAcquire: queueing XidEnt", result);
            ProcAddLock(&result->queue);
            result->nHolding = 0;
            memset((char *)result->holders, 0, sizeof(int)*MAX_LOCKTYPES);
@@ -1102,7 +1126,7 @@ LockReleaseAll(LockTableId tableId, SHM_QUEUE *lockQueue)
 #endif
     SHMQueueFirst(lockQueue,(Pointer*)&xidLook,&xidLook->queue);
     
-    XID_PRINT("LockReleaseAll:", xidLook);
+    XID_PRINT("LockReleaseAll", xidLook);
     
 #ifndef USER_LOCKS
     SpinAcquire(masterLock);
@@ -1322,3 +1346,75 @@ LockingDisabled()
 {
     return LockingIsDisabled;
 }
+
+#ifdef DEADLOCK_DEBUG
+/*
+ * Dump all locks. Must have already acquired the masterLock.
+ */
+void
+DumpLocks()
+{
+    SHMEM_OFFSET       location;
+    PROC               *proc;
+    SHM_QUEUE          *lockQueue;
+    int                        done;
+    XIDLookupEnt       *xidLook = NULL;
+    XIDLookupEnt       *tmp = NULL;
+    SHMEM_OFFSET       end;
+    SPINLOCK           masterLock;
+    int                        nLockTypes;
+    LOCK               *lock;
+    int                pid, count;
+    int                        tableId = 1;
+    LOCKTAB            *ltable;
+
+    pid = getpid();
+    ShmemPIDLookup(pid,&location);
+    if (location == INVALID_OFFSET)
+      return;
+    proc = (PROC *) MAKE_PTR(location);
+    if (proc != MyProc)
+      return;
+    lockQueue = &proc->lockQueue;
+
+    Assert (tableId < NumTables);
+    ltable = AllTables[tableId];
+    if (!ltable)
+       return;
+    
+    nLockTypes = ltable->ctl->nLockTypes;
+    masterLock = ltable->ctl->masterLock;
+    
+    if (SHMQueueEmpty(lockQueue))
+       return;
+
+    SHMQueueFirst(lockQueue,(Pointer*)&xidLook,&xidLook->queue);
+    end = MAKE_OFFSET(lockQueue);
+    
+    LOCK_DUMP("DumpLocks", MyProc->waitLock, 0);
+    XID_PRINT("DumpLocks", xidLook);
+    
+    for (count=0;;) {
+       /* ---------------------------
+        * XXX Here we assume the shared memory queue is circular and
+        * that we know its internal structure.  Should have some sort of
+        * macros to allow one to walk it.  mer 20 July 1991
+        * ---------------------------
+        */
+       done = (xidLook->queue.next == end);
+       lock = (LOCK *) MAKE_PTR(xidLook->tag.lock);
+       
+       LOCK_DUMP("DumpLocks",lock,0);
+       
+       if (count++ > 2000) {
+           elog(NOTICE,"DumpLocks: xid loop detected, giving up");
+           break;
+       }
+       
+       if (done)
+         break;
+       SHMQueueFirst(&xidLook->queue,(Pointer*)&tmp,&tmp->queue);
+       xidLook = tmp;
+    }
+}
+#endif

diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index a9b578b3535126ee8f79121b67aef79d93b79582..bfbeffb45c7da25876242b6a51982b300fd42cc5 100644 (file)
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -7,7 +7,7 @@
  *
  *
  * IDENTIFICATION
- *    $Header: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v 1.14 1997/02/11 23:05:38 momjian Exp $
+ *    $Header: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v 1.15 1997/02/12 05:23:54 scrappy Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -46,7 +46,7 @@
  *      This is so that we can support more backends. (system-wide semaphore
  *      sets run out pretty fast.)                -ay 4/95
  *
- * $Header: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v 1.14 1997/02/11 23:05:38 momjian Exp $
+ * $Header: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v 1.15 1997/02/12 05:23:54 scrappy Exp $
  */
 #include <sys/time.h>
 #ifndef WIN32
@@ -685,6 +685,10 @@ HandleDeadLock(int sig)
     lock = MyProc->waitLock;
     size = lock->waitProcs.size; /* so we can look at this in the core */
     
+#ifdef DEADLOCK_DEBUG
+    DumpLocks();
+#endif
+
     /* ------------------------
      * Get this process off the lock's wait queue
      * ------------------------

diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 9819c6d565cc6b93092cff21bc82e50d2bcb55fa..a0b51ef327029308a77954692a95de17ec4c51d8 100644 (file)
--- a/src/backend/tcop/postgres.c
+++ b/src/backend/tcop/postgres.c
@@ -7,7 +7,7 @@
  *
  *
  * IDENTIFICATION
- *    $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.29 1997/02/03 04:43:31 scrappy Exp $
+ *    $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.30 1997/02/12 05:24:22 scrappy Exp $
  *
  * NOTES
  *    this is the "main" module of the postgres backend and
@@ -91,6 +91,9 @@ static bool     DebugPrintRewrittenParsetree = false;
 /*static bool   EnableRewrite = true; , never changes why have it*/
 CommandDest whereToSendOutput;
 
+#ifdef LOCK_MGR_DEBUG
+extern int      lockDebug;
+#endif
 extern int      lockingOff;
 extern int      NBuffers;
 
@@ -757,6 +760,9 @@ static void usage(char* progname)
     fprintf(stderr, "    F: turn off fsync\n");
     fprintf(stderr, "    f: forbid plantype generation\n");
     fprintf(stderr, "    i: don't execute the query, just show the plan tree\n");
+#ifdef LOCK_MGR_DEBUG
+    fprintf(stderr, "    K: set locking debug level [0|1|2]\n");
+#endif
     fprintf(stderr, "    L: turn off locking\n");
     fprintf(stderr, "    m: set up a listening backend at portno to support multiple front-ends\n");
     fprintf(stderr, "    M: start as postmaster\n");
@@ -846,7 +852,10 @@ PostgresMain(int argc, char *argv[])
      */
     flagC = flagQ = flagS = flagE = flagEu = ShowStats = 0;
     ShowParserStats = ShowPlannerStats = ShowExecutorStats = 0;
-    
+#ifdef LOCK_MGR_DEBUG
+    lockDebug = 0;
+#endif
+
     /* get hostname is either the environment variable PGHOST
        or 'localhost' */
     if (!(hostName = getenv("PGHOST"))) {
@@ -858,7 +867,7 @@ PostgresMain(int argc, char *argv[])
     DataDir = getenv("PGDATA");   /* default */
     multiplexedBackend = false;   /* default */
 
-    while ((flag = getopt(argc, argv, "B:bCD:d:Eef:iLm:MNo:P:pQSst:x:F")) 
+    while ((flag = getopt(argc, argv, "B:bCD:d:Eef:iK:Lm:MNo:P:pQSst:x:F")) 
            != EOF)
         switch (flag) {
             
@@ -955,6 +964,14 @@ PostgresMain(int argc, char *argv[])
             dontExecute = 1;
             break;
             
+        case 'K':
+#ifdef LOCK_MGR_DEBUG
+            lockDebug = atoi(optarg);
+#else
+           fprintf(stderr, "Lock debug not compiled in\n");
+#endif
+            break;
+            
         case 'L':
             /* --------------------
              *  turn off locking
@@ -1283,7 +1300,7 @@ PostgresMain(int argc, char *argv[])
      */
     if (IsUnderPostmaster == false) {
         puts("\nPOSTGRES backend interactive interface");
-        puts("$Revision: 1.29 $ $Date: 1997/02/03 04:43:31 $");
+        puts("$Revision: 1.30 $ $Date: 1997/02/12 05:24:22 $");
     }
     
     /* ----------------

diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index e8c46ce739b502f914a06cfb89603855f74e788f..49e8915dc7365c372c535a59863513d88314dde9 100644 (file)
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -6,7 +6,7 @@
  *
  * Copyright (c) 1994, Regents of the University of California
  *
- * $Id: lock.h,v 1.3 1996/11/05 06:11:00 scrappy Exp $
+ * $Id: lock.h,v 1.4 1997/02/12 05:25:13 scrappy Exp $
  *
  *-------------------------------------------------------------------------
  */
@@ -211,4 +211,8 @@ extern bool LockReleaseAll(LockTableId tableId, SHM_QUEUE *lockQueue);
 extern int LockShmemSize(void);
 extern bool LockingDisabled(void);
 
+#ifdef DEADLOCK_DEBUG
+extern void DumpLocks(void);
+#endif
+
 #endif /* LOCK_H */