From f88d4cfc9d417dac2ee41a8f5e593898e56fd2bd Mon Sep 17 00:00:00 2001 From: Alvaro Herrera Date: Wed, 19 Mar 2014 15:10:36 -0300 Subject: [PATCH] Setup error context callback for transaction lock waits MIME-Version: 1.0 Content-Type: text/plain; charset=utf8 Content-Transfer-Encoding: 8bit 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 | 80 ++++++++++----- src/backend/access/nbtree/nbtinsert.c | 2 +- src/backend/catalog/index.c | 8 +- src/backend/executor/execMain.c | 4 +- src/backend/executor/execUtils.c | 3 +- src/backend/replication/logical/snapbuild.c | 2 +- src/backend/storage/lmgr/lmgr.c | 102 +++++++++++++++++++- src/include/storage/lmgr.h | 17 +++- src/nls-global.mk | 5 +- 9 files changed, 189 insertions(+), 34 deletions(-) diff --git a/src/backend/access/heap/heapam.c b/src/backend/access/heap/heapam.c index e2337acc2a..180eff4e6b 100644 --- a/src/backend/access/heap/heapam.c +++ b/src/backend/access/heap/heapam.c @@ -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); } /* diff --git a/src/backend/access/nbtree/nbtinsert.c b/src/backend/access/nbtree/nbtinsert.c index 3cd70ad4cf..3fbeb41d6a 100644 --- a/src/backend/access/nbtree/nbtinsert.c +++ b/src/backend/access/nbtree/nbtinsert.c @@ -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; diff --git a/src/backend/catalog/index.c b/src/backend/catalog/index.c index 432067488b..47f0647cb4 100644 --- a/src/backend/catalog/index.c +++ b/src/backend/catalog/index.c @@ -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; } diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c index 9e3d879ae7..886c75125d 100644 --- a/src/backend/executor/execMain.c +++ b/src/backend/executor/execMain.c @@ -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 */ } diff --git a/src/backend/executor/execUtils.c b/src/backend/executor/execUtils.c index 46895b23b6..fc71d852be 100644 --- a/src/backend/executor/execUtils.c +++ b/src/backend/executor/execUtils.c @@ -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; } diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c index e74053c67d..65d2e2f9de 100644 --- a/src/backend/replication/logical/snapbuild.c +++ b/src/backend/replication/logical/snapbuild.c @@ -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 */ diff --git a/src/backend/storage/lmgr/lmgr.c b/src/backend/storage/lmgr/lmgr.c index 4c61a6f9da..d692aad6cb 100644 --- a/src/backend/storage/lmgr/lmgr.c +++ b/src/backend/storage/lmgr/lmgr.c @@ -25,6 +25,21 @@ #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 diff --git a/src/include/storage/lmgr.h b/src/include/storage/lmgr.h index e74ae21b0f..e9447b7dcc 100644 --- a/src/include/storage/lmgr.h +++ b/src/include/storage/lmgr.h @@ -20,6 +20,20 @@ #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 */ diff --git a/src/nls-global.mk b/src/nls-global.mk index da91c9032e..b90a3f3889 100644 --- a/src/nls-global.mk +++ b/src/nls-global.mk @@ -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 \ -- 2.40.0