Setup error context callback for transaction lock waits
authorAlvaro Herrera <alvherre@alvh.no-ip.org>
Wed, 19 Mar 2014 18:10:36 +0000 (15:10 -0300)
committerAlvaro Herrera <alvherre@alvh.no-ip.org>
Wed, 19 Mar 2014 18:10:36 +0000 (15:10 -0300)
With this in place, a session blocking behind another one because of
tuple locks will get a context line mentioning the relation name, tuple
TID, and operation being done on tuple.  For example:

LOG:  process 11367 still waiting for ShareLock on transaction 717 after 1000.108 ms
DETAIL:  Process holding the lock: 11366. Wait queue: 11367.
CONTEXT:  while updating tuple (0,2) in relation "foo"
STATEMENT:  UPDATE foo SET value = 3;

Most usefully, the new line is displayed by log entries due to
log_lock_waits, although of course it will be printed by any other log
message as well.

Author: Christian Kruse, some tweaks by Álvaro Herrera
Reviewed-by: Amit Kapila, Andres Freund, Tom Lane, Robert Haas
src/backend/access/heap/heapam.c
src/backend/access/nbtree/nbtinsert.c
src/backend/catalog/index.c
src/backend/executor/execMain.c
src/backend/executor/execUtils.c
src/backend/replication/logical/snapbuild.c
src/backend/storage/lmgr/lmgr.c
src/include/storage/lmgr.h
src/nls-global.mk

index e2337acc2abc789fe696ab0bcde6fc77397208bb..180eff4e6b066224cc3d80681696fda0375c3df5 100644 (file)
@@ -105,11 +105,12 @@ static void GetMultiXactIdHintBits(MultiXactId multi, uint16 *new_infomask,
                       uint16 *new_infomask2);
 static TransactionId MultiXactIdGetUpdateXid(TransactionId xmax,
                        uint16 t_infomask);
-static void MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
-               int *remaining, uint16 infomask);
-static bool ConditionalMultiXactIdWait(MultiXactId multi,
-                          MultiXactStatus status, int *remaining,
-                          uint16 infomask);
+static void MultiXactIdWait(MultiXactId multi, MultiXactStatus status, uint16 infomask,
+               Relation rel, ItemPointer ctid, XLTW_Oper oper,
+               int *remaining);
+static bool ConditionalMultiXactIdWait(MultiXactId multi, MultiXactStatus status,
+                          uint16 infomask, Relation rel, ItemPointer ctid,
+                          XLTW_Oper oper, int *remaining);
 static XLogRecPtr log_heap_new_cid(Relation relation, HeapTuple tup);
 static HeapTuple ExtractReplicaIdentity(Relation rel, HeapTuple tup, bool key_modified,
                                        bool *copy);
@@ -2714,8 +2715,9 @@ l1:
        if (infomask & HEAP_XMAX_IS_MULTI)
        {
            /* wait for multixact */
-           MultiXactIdWait((MultiXactId) xwait, MultiXactStatusUpdate,
-                           NULL, infomask);
+           MultiXactIdWait((MultiXactId) xwait, MultiXactStatusUpdate, infomask,
+                           relation, &tp.t_data->t_ctid, XLTW_Delete,
+                           NULL);
            LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
 
            /*
@@ -2741,7 +2743,7 @@ l1:
        else
        {
            /* wait for regular transaction to end */
-           XactLockTableWait(xwait);
+           XactLockTableWait(xwait, relation, &tp.t_data->t_ctid, XLTW_Delete);
            LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
 
            /*
@@ -3266,8 +3268,9 @@ l2:
            int         remain;
 
            /* wait for multixact */
-           MultiXactIdWait((MultiXactId) xwait, mxact_status, &remain,
-                           infomask);
+           MultiXactIdWait((MultiXactId) xwait, mxact_status, infomask,
+                           relation, &oldtup.t_data->t_ctid, XLTW_Update,
+                           &remain);
            LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
 
            /*
@@ -3341,7 +3344,8 @@ l2:
            else
            {
                /* wait for regular transaction to end */
-               XactLockTableWait(xwait);
+               XactLockTableWait(xwait, relation, &oldtup.t_data->t_ctid,
+                                 XLTW_Update);
                LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
 
                /*
@@ -4402,14 +4406,18 @@ l3:
                if (nowait)
                {
                    if (!ConditionalMultiXactIdWait((MultiXactId) xwait,
-                                                   status, NULL, infomask))
+                                                 status, infomask, relation,
+                                                   &tuple->t_data->t_ctid,
+                                                   XLTW_Lock, NULL))
                        ereport(ERROR,
                                (errcode(ERRCODE_LOCK_NOT_AVAILABLE),
                                 errmsg("could not obtain lock on row in relation \"%s\"",
                                        RelationGetRelationName(relation))));
                }
                else
-                   MultiXactIdWait((MultiXactId) xwait, status, NULL, infomask);
+                   MultiXactIdWait((MultiXactId) xwait, status, infomask,
+                                   relation, &tuple->t_data->t_ctid,
+                                   XLTW_Lock, NULL);
 
                /* if there are updates, follow the update chain */
                if (follow_updates &&
@@ -4464,7 +4472,8 @@ l3:
                                        RelationGetRelationName(relation))));
                }
                else
-                   XactLockTableWait(xwait);
+                   XactLockTableWait(xwait, relation, &tuple->t_data->t_ctid,
+                                     XLTW_Lock);
 
                /* if there are updates, follow the update chain */
                if (follow_updates &&
@@ -5151,7 +5160,9 @@ l4:
                    if (needwait)
                    {
                        LockBuffer(buf, BUFFER_LOCK_UNLOCK);
-                       XactLockTableWait(members[i].xid);
+                       XactLockTableWait(members[i].xid, rel,
+                                         &mytup.t_data->t_ctid,
+                                         XLTW_LockUpdated);
                        pfree(members);
                        goto l4;
                    }
@@ -5211,7 +5222,8 @@ l4:
                if (needwait)
                {
                    LockBuffer(buf, BUFFER_LOCK_UNLOCK);
-                   XactLockTableWait(rawxmax);
+                   XactLockTableWait(rawxmax, rel, &mytup.t_data->t_ctid,
+                                     XLTW_LockUpdated);
                    goto l4;
                }
                if (res != HeapTupleMayBeUpdated)
@@ -6076,6 +6088,15 @@ HeapTupleGetUpdateXid(HeapTupleHeader tuple)
  * Do_MultiXactIdWait
  *     Actual implementation for the two functions below.
  *
+ * 'multi', 'status' and 'infomask' indicate what to sleep on (the status is
+ * needed to ensure we only sleep on conflicting members, and the infomask is
+ * used to optimize multixact access in case it's a lock-only multi); 'nowait'
+ * indicates whether to use conditional lock acquisition, to allow callers to
+ * fail if lock is unavailable.  'rel', 'ctid' and 'oper' are used to set up
+ * context information for error messages. 'remaining', if not NULL, receives
+ * the number of members that are still running, including any (non-aborted)
+ * subtransactions of our own transaction.
+ *
  * We do this by sleeping on each member using XactLockTableWait.  Any
  * members that belong to the current backend are *not* waited for, however;
  * this would not merely be useless but would lead to Assert failure inside
@@ -6093,7 +6114,9 @@ HeapTupleGetUpdateXid(HeapTupleHeader tuple)
  */
 static bool
 Do_MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
-                  int *remaining, uint16 infomask, bool nowait)
+                  uint16 infomask, bool nowait,
+                  Relation rel, ItemPointer ctid, XLTW_Oper oper,
+                  int *remaining)
 {
    bool        allow_old;
    bool        result = true;
@@ -6130,6 +6153,12 @@ Do_MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
            /*
             * This member conflicts with our multi, so we have to sleep (or
             * return failure, if asked to avoid waiting.)
+            *
+            * Note that we don't set up an error context callback ourselves,
+            * but instead we pass the info down to XactLockTableWait.  This
+            * might seem a bit wasteful because the context is set up and
+            * tore down for each member of the multixact, but in reality it
+            * should be barely noticeable, and it avoids duplicate code.
             */
            if (nowait)
            {
@@ -6138,7 +6167,7 @@ Do_MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
                    break;
            }
            else
-               XactLockTableWait(memxid);
+               XactLockTableWait(memxid, rel, ctid, oper);
        }
 
        pfree(members);
@@ -6159,13 +6188,14 @@ Do_MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
  *
  * We return (in *remaining, if not NULL) the number of members that are still
  * running, including any (non-aborted) subtransactions of our own transaction.
- *
  */
 static void
-MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
-               int *remaining, uint16 infomask)
+MultiXactIdWait(MultiXactId multi, MultiXactStatus status, uint16 infomask,
+               Relation rel, ItemPointer ctid, XLTW_Oper oper,
+               int *remaining)
 {
-   Do_MultiXactIdWait(multi, status, remaining, infomask, false);
+   (void) Do_MultiXactIdWait(multi, status, infomask, false,
+                             rel, ctid, oper, remaining);
 }
 
 /*
@@ -6183,9 +6213,11 @@ MultiXactIdWait(MultiXactId multi, MultiXactStatus status,
  */
 static bool
 ConditionalMultiXactIdWait(MultiXactId multi, MultiXactStatus status,
-                          int *remaining, uint16 infomask)
+                          uint16 infomask, Relation rel, ItemPointer ctid,
+                          XLTW_Oper oper, int *remaining)
 {
-   return Do_MultiXactIdWait(multi, status, remaining, infomask, true);
+   return Do_MultiXactIdWait(multi, status, infomask, true,
+                             rel, ctid, oper, remaining);
 }
 
 /*
index 3cd70ad4cfe7799decd6b44bf6d0bae608e06243..3fbeb41d6a89a8f7d269e82e7ab47f0797c4e1d8 100644 (file)
@@ -168,7 +168,7 @@ top:
        {
            /* Have to wait for the other guy ... */
            _bt_relbuf(rel, buf);
-           XactLockTableWait(xwait);
+           XactLockTableWait(xwait, rel, &itup->t_tid, XLTW_InsertIndex);
            /* start over... */
            _bt_freestack(stack);
            goto top;
index 432067488b77285f4d019b287153930694d513d3..47f0647cb4128a4864c585f511b47f9632ceb414 100644 (file)
@@ -2295,7 +2295,9 @@ IndexBuildHeapScan(Relation heapRelation,
                             * Must drop the lock on the buffer before we wait
                             */
                            LockBuffer(scan->rs_cbuf, BUFFER_LOCK_UNLOCK);
-                           XactLockTableWait(xwait);
+                           XactLockTableWait(xwait, heapRelation,
+                                             &heapTuple->t_data->t_ctid,
+                                             XLTW_InsertIndexUnique);
                            goto recheck;
                        }
                    }
@@ -2341,7 +2343,9 @@ IndexBuildHeapScan(Relation heapRelation,
                             * Must drop the lock on the buffer before we wait
                             */
                            LockBuffer(scan->rs_cbuf, BUFFER_LOCK_UNLOCK);
-                           XactLockTableWait(xwait);
+                           XactLockTableWait(xwait, heapRelation,
+                                             &heapTuple->t_data->t_ctid,
+                                             XLTW_InsertIndexUnique);
                            goto recheck;
                        }
 
index 9e3d879ae778837d41754063663617346ffac24c..886c75125d2096c1f1fd6329cfcdd10f54531a50 100644 (file)
@@ -1982,7 +1982,9 @@ EvalPlanQualFetch(EState *estate, Relation relation, int lockmode,
            if (TransactionIdIsValid(SnapshotDirty.xmax))
            {
                ReleaseBuffer(buffer);
-               XactLockTableWait(SnapshotDirty.xmax);
+               XactLockTableWait(SnapshotDirty.xmax,
+                                 relation, &tuple.t_data->t_ctid,
+                                 XLTW_FetchUpdated);
                continue;       /* loop back to repeat heap_fetch */
            }
 
index 46895b23b6c34f29fb713a07b4c716291c7df7c0..fc71d852bedfe45bf27579e40acd97967b9f5ae7 100644 (file)
@@ -1307,7 +1307,8 @@ retry:
        if (TransactionIdIsValid(xwait))
        {
            index_endscan(index_scan);
-           XactLockTableWait(xwait);
+           XactLockTableWait(xwait, heap, &tup->t_data->t_ctid,
+                             XLTW_RecheckExclusionConstr);
            goto retry;
        }
 
index e74053c67dae85a1af3df808fc387ed5ceaf58cb..65d2e2f9decfa7562b199a8703e338b0af6d471a 100644 (file)
@@ -1343,7 +1343,7 @@ SnapBuildFindSnapshot(SnapBuild *builder, XLogRecPtr lsn, xl_running_xacts *runn
            if (TransactionIdIsCurrentTransactionId(xid))
                elog(ERROR, "waiting for ourselves");
 
-           XactLockTableWait(xid);
+           XactLockTableWait(xid, NULL, NULL, XLTW_None);
        }
 
        /* nothing could have built up so far, so don't perform cleanup */
index 4c61a6f9da0f135a671d724daf3af44d210b98cf..d692aad6cbf8a1ba02fadea17b6669eeb1efc0c6 100644 (file)
 #include "utils/inval.h"
 
 
+/*
+ * Struct to hold context info for transaction lock waits.
+ *
+ * 'oper' is the operation that needs to wait for the other transaction; 'rel'
+ * and 'ctid' specify the address of the tuple being waited for.
+ */
+typedef struct XactLockTableWaitInfo
+{
+   XLTW_Oper   oper;
+   Relation    rel;
+   ItemPointer ctid;
+} XactLockTableWaitInfo;
+
+static void XactLockTableWaitErrorCb(void *arg);
+
 /*
  * RelationInitLockInfo
  *     Initializes the lock information in a relation descriptor.
@@ -471,7 +486,9 @@ XactLockTableDelete(TransactionId xid)
 /*
  *     XactLockTableWait
  *
- * Wait for the specified transaction to commit or abort.
+ * Wait for the specified transaction to commit or abort.  If an operation
+ * is specified, an error context callback is set up.  If 'oper' is passed as
+ * None, no error context callback is set up.
  *
  * Note that this does the right thing for subtransactions: if we wait on a
  * subtransaction, we will exit as soon as it aborts or its top parent commits.
@@ -481,9 +498,31 @@ XactLockTableDelete(TransactionId xid)
  * and if so wait for its parent.
  */
 void
-XactLockTableWait(TransactionId xid)
+XactLockTableWait(TransactionId xid, Relation rel, ItemPointer ctid,
+                 XLTW_Oper oper)
 {
    LOCKTAG     tag;
+   XactLockTableWaitInfo info;
+   ErrorContextCallback callback;
+
+   /*
+    * If an operation is specified, set up our verbose error context
+    * callback.
+    */
+   if (oper != XLTW_None)
+   {
+       Assert(RelationIsValid(rel));
+       Assert(ItemPointerIsValid(ctid));
+
+       info.rel = rel;
+       info.ctid = ctid;
+       info.oper = oper;
+
+       callback.callback = XactLockTableWaitErrorCb;
+       callback.arg = &info;
+       callback.previous = error_context_stack;
+       error_context_stack = &callback;
+   }
 
    for (;;)
    {
@@ -500,6 +539,9 @@ XactLockTableWait(TransactionId xid)
            break;
        xid = SubTransGetParent(xid);
    }
+
+   if (oper != XLTW_None)
+       error_context_stack = callback.previous;
 }
 
 /*
@@ -533,6 +575,62 @@ ConditionalXactLockTableWait(TransactionId xid)
    return true;
 }
 
+/*
+ * XactLockTableWaitErrorContextCb
+ *     Error context callback for transaction lock waits.
+ */
+static void
+XactLockTableWaitErrorCb(void *arg)
+{
+   XactLockTableWaitInfo *info = (XactLockTableWaitInfo *) arg;
+
+   /*
+    * We would like to print schema name too, but that would require a
+    * syscache lookup.
+    */
+   if (info->oper != XLTW_None &&
+       ItemPointerIsValid(info->ctid) && RelationIsValid(info->rel))
+   {
+       const char *cxt;
+
+       switch (info->oper)
+       {
+           case XLTW_Update:
+               cxt = gettext_noop("while updating tuple (%u,%u) in relation \"%s\"");
+               break;
+           case XLTW_Delete:
+               cxt = gettext_noop("while deleting tuple (%u,%u) in relation \"%s\"");
+               break;
+           case XLTW_Lock:
+               cxt = gettext_noop("while locking tuple (%u,%u) in relation \"%s\"");
+               break;
+           case XLTW_LockUpdated:
+               cxt = gettext_noop("while locking updated version (%u,%u) of tuple in relation \"%s\"");
+               break;
+           case XLTW_InsertIndex:
+               cxt = gettext_noop("while inserting index tuple (%u,%u) in relation \"%s\"");
+               break;
+           case XLTW_InsertIndexUnique:
+               cxt = gettext_noop("while checking uniqueness of tuple (%u,%u) in relation \"%s\"");
+               break;
+           case XLTW_FetchUpdated:
+               cxt = gettext_noop("while rechecking updated tuple (%u,%u) in relation \"%s\"");
+               break;
+           case XLTW_RecheckExclusionConstr:
+               cxt = gettext_noop("while checking exclusion constraint on tuple (%u,%u) in relation \"%s\"");
+               break;
+
+           default:
+               return;
+       }
+
+       errcontext(cxt,
+                  ItemPointerGetBlockNumber(info->ctid),
+                  ItemPointerGetOffsetNumber(info->ctid),
+                  RelationGetRelationName(info->rel));
+   }
+}
+
 /*
  * WaitForLockersMultiple
  *     Wait until no transaction holds locks that conflict with the given
index e74ae21b0f9cda474692c8e404db48b83ad88e08..e9447b7dccffa14eb50322bd7bc52e7ce5709ed2 100644 (file)
 #include "utils/rel.h"
 
 
+/* XactLockTableWait operations */
+typedef enum XLTW_Oper
+{
+   XLTW_None,
+   XLTW_Update,
+   XLTW_Delete,
+   XLTW_Lock,
+   XLTW_LockUpdated,
+   XLTW_InsertIndex,
+   XLTW_InsertIndexUnique,
+   XLTW_FetchUpdated,
+   XLTW_RecheckExclusionConstr
+} XLTW_Oper;
+
 extern void RelationInitLockInfo(Relation relation);
 
 /* Lock a relation */
@@ -54,7 +68,8 @@ extern void UnlockTuple(Relation relation, ItemPointer tid, LOCKMODE lockmode);
 /* Lock an XID (used to wait for a transaction to finish) */
 extern void XactLockTableInsert(TransactionId xid);
 extern void XactLockTableDelete(TransactionId xid);
-extern void XactLockTableWait(TransactionId xid);
+extern void XactLockTableWait(TransactionId xid, Relation rel,
+                 ItemPointer ctid, XLTW_Oper oper);
 extern bool ConditionalXactLockTableWait(TransactionId xid);
 
 /* Lock VXIDs, specified by conflicting locktags */
index da91c9032e5f02f4e897b2d8b593b27c874bd86b..b90a3f3889a9ceb2015b8c8da2fa8e742fdcd8d0 100644 (file)
@@ -57,7 +57,10 @@ BACKEND_COMMON_GETTEXT_TRIGGERS = \
     errmsg errmsg_plural:1,2 \
     errdetail errdetail_log errdetail_plural:1,2 \
     errhint \
-    errcontext
+    errcontext \
+    XactLockTableWait:4 \
+    MultiXactIdWait:6 \
+    ConditionalMultiXactIdWait:6
 BACKEND_COMMON_GETTEXT_FLAGS = \
     errmsg:1:c-format errmsg_plural:1:c-format errmsg_plural:2:c-format \
     errdetail:1:c-format errdetail_log:1:c-format errdetail_plural:1:c-format errdetail_plural:2:c-format \