Re: Deadlock with pg_dump? - Mailing list pgsql-hackers

I have applied a modified version of this patch, attached.   I trimmed
down the description of log_lock_waits to be more concise, and moved the
idea of using this to tune deadlock_timeout to the deadlock_timeout
section of the manual.

---------------------------------------------------------------------------

Simon Riggs wrote:
> On Mon, 2007-02-19 at 19:38 +0000, Simon Riggs wrote:
> > On Tue, 2007-02-13 at 22:19 -0500, Bruce Momjian wrote:
> > > Simon Riggs wrote:
> > > > On Thu, 2006-10-26 at 18:45 -0400, Tom Lane wrote:
> > > > > Chris Campbell <chris@bignerdranch.com> writes:
> > > > > > Is there additional logging information I can turn on to get more
> > > > > > details? I guess I need to see exactly what locks both processes
> > > > > > hold, and what queries they were running when the deadlock occurred?
> > > > > > Is that easily done, without turning on logging for *all* statements?
> > > > >
> > > > > log_min_error_statement = error would at least get you the statements
> > > > > reporting the deadlocks, though not what they're conflicting against.
> > > >
> > > > Yeh, we need a much better locking logger for performance analysis.
> > > >
> > > > We really need to dump the whole wait-for graph for deadlocks, since
> > > > this might be more complex than just two statements involved. Deadlocks
> > > > ought to be so infrequent that we can afford the log space to do this -
> > > > plus if we did this it would likely lead to fewer deadlocks.
> > > >
> > > > For 8.3 I'd like to have a log_min_duration_lockwait (secs) parameter
> > > > that would allow you to dump the wait-for graph for any data-level locks
> > > > that wait too long, rather than just those that deadlock. Many
> > > > applications experience heavy locking because of lack of holistic
> > > > design. That will also show up the need for other utilities to act
> > > > CONCURRENTLY, if possible.
> > >
> > > Old email, but I don't see how our current output is not good enough?
> > >
> > >     test=> lock a;
> > >     ERROR:  deadlock detected
> > >     DETAIL:  Process 6855 waits for AccessExclusiveLock on relation 16394 of
> > >     database 16384; blocked by process 6795.
> > >     Process 6795 waits for AccessExclusiveLock on relation 16396 of database
> > >     16384; blocked by process 6855.
> >
> > This detects deadlocks, but it doesn't detect lock waits.
> >
> > When I wrote that it was previous experience driving me. Recent client
> > experience has highlighted the clear need for this. We had a lock wait
> > of 50 hours because of an RI check; thats the kind of thing I'd like to
> > show up in the logs somewhere.
> >
> > Lock wait detection can be used to show up synchronisation points that
> > have been inadvertently designed into an application, so its a useful
> > tool in investigating performance issues.
> >
> > I have a patch implementing the logging as agreed with Tom, will post to
> > patches later tonight.
>
> Patch for discussion, includes doc entries at top of patch, so its
> fairly clear how it works.
>
> Output is an INFO message, to allow this to trigger
> log_min_error_statement when it generates a message, to allow us to see
> the SQL statement that is waiting. This allows it to generate a message
> prior to the statement completing, which is important because it may not
> ever complete, in some cases, so simply logging a list of pids won't
> always tell you what the SQL was that was waiting.
>
> Other approaches are possible...
>
> Comments?
>
> --
>   Simon Riggs
>   EnterpriseDB   http://www.enterprisedb.com
>

[ Attachment, skipping... ]

--
  Bruce Momjian  <bruce@momjian.us>          http://momjian.us
  EnterpriseDB                               http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.113
diff -c -c -r1.113 config.sgml
*** doc/src/sgml/config.sgml    2 Mar 2007 23:37:22 -0000    1.113
--- doc/src/sgml/config.sgml    3 Mar 2007 18:41:13 -0000
***************
*** 2946,2951 ****
--- 2946,2966 ----
        </listitem>
       </varlistentry>

+      <varlistentry id="guc-log-lock-waits" xreflabel="log_lock_waits">
+       <term><varname>log_lock_waits</varname> (<type>boolean</type>)</term>
+       <indexterm>
+        <primary><varname>log_lock_waits</> configuration parameter</primary>
+       </indexterm>
+       <listitem>
+        <para>
+         Controls whether a log message is produced when a statement waits
+         longer than <xref linkend="guc-deadlock-timeout"> to acquire a
+         lock.  This is useful in determining if lock waits are causing
+         poor performance.  The default is <literal>off</>.
+        </para>
+       </listitem>
+      </varlistentry>
+
       <varlistentry id="guc-log-temp-files" xreflabel="log_temp_files">
        <term><varname>log_temp_files</varname> (<type>integer</type>)</term>
        <indexterm>
***************
*** 3980,3996 ****
          This is the amount of time, in milliseconds, to wait on a lock
          before checking to see if there is a deadlock condition. The
          check for deadlock is relatively slow, so the server doesn't run
!         it every time it waits for a lock. We (optimistically?) assume
          that deadlocks are not common in production applications and
          just wait on the lock for a while before starting the check for a
          deadlock. Increasing this value reduces the amount of time
          wasted in needless deadlock checks, but slows down reporting of
          real deadlock errors. The default is one second (<literal>1s</>),
          which is probably about the smallest value you would want in
!         practice. On a heavily loaded server you might want to raise it.
          Ideally the setting should exceed your typical transaction time,
!         so as to improve the odds that a lock will be released before
!         the waiter decides to check for deadlock.
         </para>
        </listitem>
       </varlistentry>
--- 3995,4012 ----
          This is the amount of time, in milliseconds, to wait on a lock
          before checking to see if there is a deadlock condition. The
          check for deadlock is relatively slow, so the server doesn't run
!         it every time it waits for a lock. We optimistically assume
          that deadlocks are not common in production applications and
          just wait on the lock for a while before starting the check for a
          deadlock. Increasing this value reduces the amount of time
          wasted in needless deadlock checks, but slows down reporting of
          real deadlock errors. The default is one second (<literal>1s</>),
          which is probably about the smallest value you would want in
!         practice.  Set <xref linkend="guc-log-lock-waits"> to log deadlock
!         checks.  On a heavily loaded server you might want to raise it.
          Ideally the setting should exceed your typical transaction time,
!         so as to improve the odds that a lock will be released before the
!         waiter decides to check for deadlock.
         </para>
        </listitem>
       </varlistentry>
Index: src/backend/storage/lmgr/deadlock.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/storage/lmgr/deadlock.c,v
retrieving revision 1.44
diff -c -c -r1.44 deadlock.c
*** src/backend/storage/lmgr/deadlock.c    5 Jan 2007 22:19:38 -0000    1.44
--- src/backend/storage/lmgr/deadlock.c    3 Mar 2007 18:41:13 -0000
***************
*** 187,199 ****
   * deadlock.  If resolution is impossible, return TRUE --- the caller
   * is then expected to abort the given proc's transaction.
   *
!  * Caller must already have locked all partitions of the lock tables.
   *
   * On failure, deadlock details are recorded in deadlockDetails[] for
   * subsequent printing by DeadLockReport().  That activity is separate
   * because we don't want to do it while holding all those LWLocks.
   */
! bool
  DeadLockCheck(PGPROC *proc)
  {
      int            i,
--- 187,200 ----
   * deadlock.  If resolution is impossible, return TRUE --- the caller
   * is then expected to abort the given proc's transaction.
   *
!  * Caller must already have locked all partitions of the lock tables,
!  * so standard error logging/reporting code is handled by caller.
   *
   * On failure, deadlock details are recorded in deadlockDetails[] for
   * subsequent printing by DeadLockReport().  That activity is separate
   * because we don't want to do it while holding all those LWLocks.
   */
! DeadlockState
  DeadLockCheck(PGPROC *proc)
  {
      int            i,
***************
*** 204,209 ****
--- 205,215 ----
      nPossibleConstraints = 0;
      nWaitOrders = 0;

+ #ifdef LOCK_DEBUG
+     if (Debug_deadlocks)
+         DumpAllLocks();
+ #endif
+
      /* Search for deadlocks and possible fixes */
      if (DeadLockCheckRecurse(proc))
      {
***************
*** 217,223 ****
          if (!FindLockCycle(proc, possibleConstraints, &nSoftEdges))
              elog(FATAL, "deadlock seems to have disappeared");

!         return true;            /* cannot find a non-deadlocked state */
      }

      /* Apply any needed rearrangements of wait queues */
--- 223,229 ----
          if (!FindLockCycle(proc, possibleConstraints, &nSoftEdges))
              elog(FATAL, "deadlock seems to have disappeared");

!         return DS_HARD_DEADLOCK;    /* cannot find a non-deadlocked state */
      }

      /* Apply any needed rearrangements of wait queues */
***************
*** 249,255 ****
          /* See if any waiters for the lock can be woken up now */
          ProcLockWakeup(GetLocksMethodTable(lock), lock);
      }
!     return false;
  }

  /*
--- 255,265 ----
          /* See if any waiters for the lock can be woken up now */
          ProcLockWakeup(GetLocksMethodTable(lock), lock);
      }
!
!     if (nWaitOrders > 0)
!         return DS_SOFT_DEADLOCK;
!     else
!         return DS_DEADLOCK_NOT_FOUND;
  }

  /*
***************
*** 896,902 ****
  }

  /*
!  * Report a detected deadlock, with available details.
   */
  void
  DeadLockReport(void)
--- 906,912 ----
  }

  /*
!  * Report a detected DS_HARD_DEADLOCK, with available details.
   */
  void
  DeadLockReport(void)
Index: src/backend/storage/lmgr/proc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/storage/lmgr/proc.c,v
retrieving revision 1.184
diff -c -c -r1.184 proc.c
*** src/backend/storage/lmgr/proc.c    15 Feb 2007 23:23:23 -0000    1.184
--- src/backend/storage/lmgr/proc.c    3 Mar 2007 18:41:14 -0000
***************
*** 48,53 ****
--- 48,54 ----
  /* GUC variables */
  int            DeadlockTimeout = 1000;
  int            StatementTimeout = 0;
+ bool        log_lock_waits = false;

  /* Pointer to this process's PGPROC struct, if any */
  PGPROC       *MyProc = NULL;
***************
*** 979,984 ****
--- 980,986 ----
  CheckDeadLock(void)
  {
      int            i;
+     DeadlockState deadlock_state = DS_DEADLOCK_NOT_FOUND;

      /*
       * Acquire exclusive lock on the entire shared lock data structures. Must
***************
*** 1004,1063 ****
       * This is quicker than checking our semaphore's state, since no kernel
       * call is needed, and it is safe because we hold the lock partition lock.
       */
!     if (MyProc->links.prev == INVALID_OFFSET ||
!         MyProc->links.next == INVALID_OFFSET)
!         goto check_done;
!
! #ifdef LOCK_DEBUG
!     if (Debug_deadlocks)
!         DumpAllLocks();
! #endif
!
!     if (!DeadLockCheck(MyProc))
      {
!         /* No deadlock, so keep waiting */
!         goto check_done;
!     }
!
!     /*
!      * Oops.  We have a deadlock.
!      *
!      * Get this process out of wait state.    (Note: we could do this more
!      * efficiently by relying on lockAwaited, but use this coding to preserve
!      * the flexibility to kill some other transaction than the one detecting
!      * the deadlock.)
!      *
!      * RemoveFromWaitQueue sets MyProc->waitStatus to STATUS_ERROR, so
!      * ProcSleep will report an error after we return from the signal handler.
!      */
!     Assert(MyProc->waitLock != NULL);
!     RemoveFromWaitQueue(MyProc, LockTagHashCode(&(MyProc->waitLock->tag)));

!     /*
!      * Unlock my semaphore so that the interrupted ProcSleep() call can
!      * finish.
!      */
!     PGSemaphoreUnlock(&MyProc->sem);

!     /*
!      * We're done here.  Transaction abort caused by the error that ProcSleep
!      * will raise will cause any other locks we hold to be released, thus
!      * allowing other processes to wake up; we don't need to do that here.
!      * NOTE: an exception is that releasing locks we hold doesn't consider the
!      * possibility of waiters that were blocked behind us on the lock we just
!      * failed to get, and might now be wakable because we're not in front of
!      * them anymore.  However, RemoveFromWaitQueue took care of waking up any
!      * such processes.
!      */

      /*
       * Release locks acquired at head of routine.  Order is not critical, so
       * do it back-to-front to avoid waking another CheckDeadLock instance
       * before it can get all the locks.
       */
- check_done:
      for (i = NUM_LOCK_PARTITIONS; --i >= 0;)
          LWLockRelease(FirstLockMgrLock + i);
  }


--- 1006,1082 ----
       * This is quicker than checking our semaphore's state, since no kernel
       * call is needed, and it is safe because we hold the lock partition lock.
       */
!     if (MyProc->links.prev != INVALID_OFFSET &&
!         MyProc->links.next != INVALID_OFFSET)
!         deadlock_state = DeadLockCheck(MyProc);
!
!     if (deadlock_state == DS_HARD_DEADLOCK)
      {
!         /*
!          * Oops.  We have a deadlock.
!          *
!          * Get this process out of wait state.    (Note: we could do this more
!          * efficiently by relying on lockAwaited, but use this coding to preserve
!          * the flexibility to kill some other transaction than the one detecting
!          * the deadlock.)
!          *
!          * RemoveFromWaitQueue sets MyProc->waitStatus to STATUS_ERROR, so
!          * ProcSleep will report an error after we return from the signal handler.
!          */
!         Assert(MyProc->waitLock != NULL);
!         RemoveFromWaitQueue(MyProc, LockTagHashCode(&(MyProc->waitLock->tag)));

!         /*
!          * Unlock my semaphore so that the interrupted ProcSleep() call can
!          * finish.
!          */
!         PGSemaphoreUnlock(&MyProc->sem);

!         /*
!          * We're done here.  Transaction abort caused by the error that ProcSleep
!          * will raise will cause any other locks we hold to be released, thus
!          * allowing other processes to wake up; we don't need to do that here.
!          * NOTE: an exception is that releasing locks we hold doesn't consider the
!          * possibility of waiters that were blocked behind us on the lock we just
!          * failed to get, and might now be wakable because we're not in front of
!          * them anymore.  However, RemoveFromWaitQueue took care of waking up any
!          * such processes.
!          */
!     }

      /*
       * Release locks acquired at head of routine.  Order is not critical, so
       * do it back-to-front to avoid waking another CheckDeadLock instance
       * before it can get all the locks.
       */
      for (i = NUM_LOCK_PARTITIONS; --i >= 0;)
          LWLockRelease(FirstLockMgrLock + i);
+
+     /*
+      * Issue any log messages requested.
+      *
+      * Deadlock ERROR messages are issued as part of transaction abort, so
+      * these messages should not raise error states intentionally.
+      */
+     if (log_lock_waits)
+     {
+         switch (deadlock_state)
+         {
+             case DS_SOFT_DEADLOCK:
+                 ereport(LOG,
+                     (errmsg("deadlock avoided by rearranging lock order")));
+                 break;
+             case DS_DEADLOCK_NOT_FOUND:
+                 ereport(LOG,
+                     (errmsg("statement waiting for lock for at least %d ms",
+                                 DeadlockTimeout)));
+                 break;
+             case DS_HARD_DEADLOCK:
+                 break;    /* ERROR message handled during abort */
+             default:
+                 break;
+         }
+     }
  }


Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v
retrieving revision 1.377
diff -c -c -r1.377 guc.c
*** src/backend/utils/misc/guc.c    23 Feb 2007 21:36:18 -0000    1.377
--- src/backend/utils/misc/guc.c    3 Mar 2007 18:41:16 -0000
***************
*** 812,817 ****
--- 812,825 ----
  #endif

      {
+         {"log_lock_waits", PGC_SIGHUP, LOGGING_WHAT,
+             gettext_noop("Logs long lock wait events."),
+             NULL
+         },
+         &log_lock_waits,
+         false, NULL, NULL
+     },
+     {
          {"log_hostname", PGC_SIGHUP, LOGGING_WHAT,
              gettext_noop("Logs the host name in the connection logs."),
              gettext_noop("By default, connection logs only show the IP address "
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.210
diff -c -c -r1.210 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample    2 Mar 2007 23:37:23 -0000    1.210
--- src/backend/utils/misc/postgresql.conf.sample    3 Mar 2007 18:41:16 -0000
***************
*** 340,346 ****
                      # e.g. '<%u%%%d> '
  #log_statement = 'none'            # none, ddl, mod, all
  #log_hostname = off
!
  #log_temp_files = -1            # Log temporary files equal or larger
                      # than the specified number of kilobytes.
                      # -1 disables;  0 logs all temp files
--- 340,346 ----
                      # e.g. '<%u%%%d> '
  #log_statement = 'none'            # none, ddl, mod, all
  #log_hostname = off
! #log_lock_waits = off            # Log lock waits longer than deadlock_timeout
  #log_temp_files = -1            # Log temporary files equal or larger
                      # than the specified number of kilobytes.
                      # -1 disables;  0 logs all temp files
Index: src/include/storage/lock.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/storage/lock.h,v
retrieving revision 1.103
diff -c -c -r1.103 lock.h
*** src/include/storage/lock.h    5 Jan 2007 22:19:58 -0000    1.103
--- src/include/storage/lock.h    3 Mar 2007 18:41:17 -0000
***************
*** 394,399 ****
--- 394,406 ----
      LOCKACQUIRE_ALREADY_HELD    /* incremented count for lock already held */
  } LockAcquireResult;

+ /* Deadlock states identified by DeadlockCheck() */
+ typedef enum
+ {
+     DS_DEADLOCK_NOT_FOUND,        /* no deadlock found within database server */
+     DS_SOFT_DEADLOCK,            /* deadlock, but lock queues rearrangeable */
+     DS_HARD_DEADLOCK            /* deadlock, no way out but ERROR */
+ } DeadlockState;

  /*
   * The lockmgr's shared hash tables are partitioned to reduce contention.
***************
*** 442,448 ****
  extern void lock_twophase_postabort(TransactionId xid, uint16 info,
                          void *recdata, uint32 len);

! extern bool DeadLockCheck(PGPROC *proc);
  extern void DeadLockReport(void);
  extern void RememberSimpleDeadLock(PGPROC *proc1,
                         LOCKMODE lockmode,
--- 449,455 ----
  extern void lock_twophase_postabort(TransactionId xid, uint16 info,
                          void *recdata, uint32 len);

! extern DeadlockState DeadLockCheck(PGPROC *proc);
  extern void DeadLockReport(void);
  extern void RememberSimpleDeadLock(PGPROC *proc1,
                         LOCKMODE lockmode,
Index: src/include/storage/proc.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/storage/proc.h,v
retrieving revision 1.94
diff -c -c -r1.94 proc.h
*** src/include/storage/proc.h    15 Feb 2007 23:23:23 -0000    1.94
--- src/include/storage/proc.h    3 Mar 2007 18:41:17 -0000
***************
*** 127,132 ****
--- 127,133 ----
  /* configurable options */
  extern int    DeadlockTimeout;
  extern int    StatementTimeout;
+ extern bool    log_lock_waits;

  extern volatile bool cancel_from_timeout;