log_lock_waits to identify transaction's relation
When there is contention between concurrent transactions it shows up
as with log_lock_waits as
LOG: process %d acquired %s on %s transaction %u after %ld.%03d ms
Which is mostly useless for identifying and eliminating the contention
in the application since you can't tell which table is causing
problems. This only occurs for lock waits on transactions, not on
other lock types, such as tuples which are much more informative, for
example
LOG: process %d acquired %s on tuple(x,y) of relation %u of
database %u after %ld.%03d ms
Attached patch passes through further information about the lock wait,
so we can display the following message instead
LOG: process %d acquired %s on transaction %u on relation %u of
database %u after %ld.%03d ms
This should help identify benefit/loss from the FKlocks feature, since
MultiXactIdWait() shows up in the log as contention of this type.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
Attachments:
identify_xact_waits.v1.patchapplication/octet-stream; name=identify_xact_waits.v1.patchDownload
diff --git a/src/backend/access/heap/heapam.c b/src/backend/access/heap/heapam.c
index b19d1cf..261c5be 100644
--- a/src/backend/access/heap/heapam.c
+++ b/src/backend/access/heap/heapam.c
@@ -2494,7 +2494,7 @@ l1:
if (infomask & HEAP_XMAX_IS_MULTI)
{
/* wait for multixact */
- MultiXactIdWait((MultiXactId) xwait);
+ MultiXactIdWait((MultiXactId) xwait, relation->rd_id);
LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
/*
@@ -2520,7 +2520,7 @@ l1:
else
{
/* wait for regular transaction to end */
- XactLockTableWait(xwait);
+ XactLockTableWait(xwait, relation->rd_id);
LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
/*
@@ -2871,7 +2871,7 @@ l2:
if (infomask & HEAP_XMAX_IS_MULTI)
{
/* wait for multixact */
- MultiXactIdWait((MultiXactId) xwait);
+ MultiXactIdWait((MultiXactId) xwait, relation->rd_id);
LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
/*
@@ -2897,7 +2897,7 @@ l2:
else
{
/* wait for regular transaction to end */
- XactLockTableWait(xwait);
+ XactLockTableWait(xwait, relation->rd_id);
LockBuffer(buffer, BUFFER_LOCK_EXCLUSIVE);
/*
@@ -3612,14 +3612,14 @@ l3:
/* wait for multixact to end */
if (nowait)
{
- if (!ConditionalMultiXactIdWait((MultiXactId) xwait))
+ if (!ConditionalMultiXactIdWait((MultiXactId) xwait, relation->rd_id))
ereport(ERROR,
(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
errmsg("could not obtain lock on row in relation \"%s\"",
RelationGetRelationName(relation))));
}
else
- MultiXactIdWait((MultiXactId) xwait);
+ MultiXactIdWait((MultiXactId) xwait, relation->rd_id);
LockBuffer(*buffer, BUFFER_LOCK_EXCLUSIVE);
@@ -3647,14 +3647,14 @@ l3:
/* wait for regular transaction to end */
if (nowait)
{
- if (!ConditionalXactLockTableWait(xwait))
+ if (!ConditionalXactLockTableWait(xwait, relation->rd_id))
ereport(ERROR,
(errcode(ERRCODE_LOCK_NOT_AVAILABLE),
errmsg("could not obtain lock on row in relation \"%s\"",
RelationGetRelationName(relation))));
}
else
- XactLockTableWait(xwait);
+ XactLockTableWait(xwait, relation->rd_id);
LockBuffer(*buffer, BUFFER_LOCK_EXCLUSIVE);
diff --git a/src/backend/access/nbtree/nbtinsert.c b/src/backend/access/nbtree/nbtinsert.c
index 4432bb1..d48ffb2 100644
--- a/src/backend/access/nbtree/nbtinsert.c
+++ b/src/backend/access/nbtree/nbtinsert.c
@@ -165,7 +165,7 @@ top:
{
/* Have to wait for the other guy ... */
_bt_relbuf(rel, buf);
- XactLockTableWait(xwait);
+ XactLockTableWait(xwait, heapRel->rd_id);
/* start over... */
_bt_freestack(stack);
goto top;
diff --git a/src/backend/access/transam/multixact.c b/src/backend/access/transam/multixact.c
index 1ae6717..cd6db82 100644
--- a/src/backend/access/transam/multixact.c
+++ b/src/backend/access/transam/multixact.c
@@ -583,7 +583,7 @@ MultiXactIdSetOldestVisible(void)
* of the containing tuple, so the caller needs to iterate on us somehow.
*/
void
-MultiXactIdWait(MultiXactId multi)
+MultiXactIdWait(MultiXactId multi, Oid relid)
{
TransactionId *members;
int nmembers;
@@ -601,7 +601,7 @@ MultiXactIdWait(MultiXactId multi)
debug_elog4(DEBUG2, "MultiXactIdWait: waiting for %d (%u)",
i, member);
if (!TransactionIdIsCurrentTransactionId(member))
- XactLockTableWait(member);
+ XactLockTableWait(member, relid);
}
pfree(members);
@@ -613,7 +613,7 @@ MultiXactIdWait(MultiXactId multi)
* As above, but only lock if we can get the lock without blocking.
*/
bool
-ConditionalMultiXactIdWait(MultiXactId multi)
+ConditionalMultiXactIdWait(MultiXactId multi, Oid relid)
{
bool result = true;
TransactionId *members;
@@ -633,7 +633,7 @@ ConditionalMultiXactIdWait(MultiXactId multi)
i, member);
if (!TransactionIdIsCurrentTransactionId(member))
{
- result = ConditionalXactLockTableWait(member);
+ result = ConditionalXactLockTableWait(member, relid);
if (!result)
break;
}
diff --git a/src/backend/catalog/index.c b/src/backend/catalog/index.c
index 5892e44..73e2dfa 100644
--- a/src/backend/catalog/index.c
+++ b/src/backend/catalog/index.c
@@ -2335,7 +2335,7 @@ 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->rd_id);
goto recheck;
}
}
@@ -2382,7 +2382,7 @@ 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->rd_id);
goto recheck;
}
diff --git a/src/backend/executor/execMain.c b/src/backend/executor/execMain.c
index 9d5d829..88bb8f0 100644
--- a/src/backend/executor/execMain.c
+++ b/src/backend/executor/execMain.c
@@ -1836,7 +1836,7 @@ EvalPlanQualFetch(EState *estate, Relation relation, int lockmode,
if (TransactionIdIsValid(SnapshotDirty.xmax))
{
ReleaseBuffer(buffer);
- XactLockTableWait(SnapshotDirty.xmax);
+ XactLockTableWait(SnapshotDirty.xmax, relation->rd_id);
continue; /* loop back to repeat heap_fetch */
}
diff --git a/src/backend/executor/execUtils.c b/src/backend/executor/execUtils.c
index 9206195..f48a24c 100644
--- a/src/backend/executor/execUtils.c
+++ b/src/backend/executor/execUtils.c
@@ -1291,7 +1291,7 @@ retry:
if (TransactionIdIsValid(xwait))
{
index_endscan(index_scan);
- XactLockTableWait(xwait);
+ XactLockTableWait(xwait, heap->rd_id);
goto retry;
}
diff --git a/src/backend/storage/lmgr/deadlock.c b/src/backend/storage/lmgr/deadlock.c
index a0f7d34..67fb75e 100644
--- a/src/backend/storage/lmgr/deadlock.c
+++ b/src/backend/storage/lmgr/deadlock.c
@@ -916,7 +916,7 @@ DeadLockReport(void)
/* reset locktagbuf to hold next object description */
resetStringInfo(&locktagbuf);
- DescribeLockTag(&locktagbuf, &info->locktag);
+ DescribeLockTag(&locktagbuf, &info->locktag, false);
if (i > 0)
appendStringInfoChar(&clientbuf, '\n');
diff --git a/src/backend/storage/lmgr/lmgr.c b/src/backend/storage/lmgr/lmgr.c
index 2b7a1db..20e935b 100644
--- a/src/backend/storage/lmgr/lmgr.c
+++ b/src/backend/storage/lmgr/lmgr.c
@@ -24,6 +24,7 @@
#include "storage/procarray.h"
#include "utils/inval.h"
+static Oid XactLockTableRelid = InvalidOid; /* Relid of table we are waiting for */
/*
* RelationInitLockInfo
@@ -481,10 +482,12 @@ XactLockTableDelete(TransactionId xid)
* and if so wait for its parent.
*/
void
-XactLockTableWait(TransactionId xid)
+XactLockTableWait(TransactionId xid, Oid WaitRelid)
{
LOCKTAG tag;
+ XactLockTableRelid = WaitRelid;
+
for (;;)
{
Assert(TransactionIdIsValid(xid));
@@ -500,6 +503,8 @@ XactLockTableWait(TransactionId xid)
break;
xid = SubTransGetParent(xid);
}
+
+ XactLockTableRelid = InvalidOid;
}
/*
@@ -509,10 +514,11 @@ XactLockTableWait(TransactionId xid)
* Returns TRUE if the lock was acquired.
*/
bool
-ConditionalXactLockTableWait(TransactionId xid)
+ConditionalXactLockTableWait(TransactionId xid, Oid WaitRelid)
{
LOCKTAG tag;
+ XactLockTableRelid = WaitRelid;
for (;;)
{
Assert(TransactionIdIsValid(xid));
@@ -521,7 +527,10 @@ ConditionalXactLockTableWait(TransactionId xid)
SET_LOCKTAG_TRANSACTION(tag, xid);
if (LockAcquire(&tag, ShareLock, false, true) == LOCKACQUIRE_NOT_AVAIL)
+ {
+ XactLockTableRelid = InvalidOid;
return false;
+ }
LockRelease(&tag, ShareLock, false);
@@ -530,10 +539,21 @@ ConditionalXactLockTableWait(TransactionId xid)
xid = SubTransGetParent(xid);
}
+ XactLockTableRelid = InvalidOid;
return true;
}
/*
+ * Return the relid of the table we are currently waiting on, to
+ * allow full reporting of lock waits.
+ */
+Oid
+GetXactLockTableRelid(void)
+{
+ return XactLockTableRelid;
+}
+
+/*
* LockDatabaseObject
*
* Obtain a lock on a general object of the current database. Don't use
@@ -664,9 +684,13 @@ UnlockSharedObjectForSession(Oid classid, Oid objid, uint16 objsubid,
* Ideally we would print names for the numeric values, but that requires
* getting locks on system tables, which might cause problems since this is
* typically used to report deadlock situations.
+ *
+ * describeXact can be used by a backend that is describing a lock of type
+ * LOCKTAG_TRANSACTION that the backend is requesting. This information
+ * isn't available for locks requested or held by other backends.
*/
void
-DescribeLockTag(StringInfo buf, const LOCKTAG *tag)
+DescribeLockTag(StringInfo buf, const LOCKTAG *tag, bool describeXact)
{
switch ((LockTagType) tag->locktag_type)
{
@@ -698,7 +722,14 @@ DescribeLockTag(StringInfo buf, const LOCKTAG *tag)
tag->locktag_field1);
break;
case LOCKTAG_TRANSACTION:
- appendStringInfo(buf,
+ if (describeXact && OidIsValid(GetXactLockTableRelid()))
+ appendStringInfo(buf,
+ _("transaction %u on relation %u of database %u"),
+ tag->locktag_field1,
+ GetXactLockTableRelid(),
+ MyDatabaseId);
+ else
+ appendStringInfo(buf,
_("transaction %u"),
tag->locktag_field1);
break;
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 2e012fa..5ec0eed 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1128,7 +1128,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
initStringInfo(&locktagbuf);
initStringInfo(&logbuf);
- DescribeLockTag(&locktagbuf, &lock->tag);
+ DescribeLockTag(&locktagbuf, &lock->tag, false);
appendStringInfo(&logbuf,
_("Process %d waits for %s on %s."),
MyProcPid,
@@ -1176,7 +1176,7 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
long msecs;
initStringInfo(&buf);
- DescribeLockTag(&buf, &locallock->tag.lock);
+ DescribeLockTag(&buf, &locallock->tag.lock, true);
modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid,
lockmode);
TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT),
diff --git a/src/include/access/multixact.h b/src/include/access/multixact.h
index b5486be..6cca9fa 100644
--- a/src/include/access/multixact.h
+++ b/src/include/access/multixact.h
@@ -46,8 +46,8 @@ extern MultiXactId MultiXactIdCreate(TransactionId xid1, TransactionId xid2);
extern MultiXactId MultiXactIdExpand(MultiXactId multi, TransactionId xid);
extern bool MultiXactIdIsRunning(MultiXactId multi);
extern bool MultiXactIdIsCurrent(MultiXactId multi);
-extern void MultiXactIdWait(MultiXactId multi);
-extern bool ConditionalMultiXactIdWait(MultiXactId multi);
+extern void MultiXactIdWait(MultiXactId multi, Oid relid);
+extern bool ConditionalMultiXactIdWait(MultiXactId multi, Oid relid);
extern void MultiXactIdSetOldestMember(void);
extern int GetMultiXactIdMembers(MultiXactId multi, TransactionId **xids);
diff --git a/src/include/storage/lmgr.h b/src/include/storage/lmgr.h
index 9b1fb93..5aee9f5 100644
--- a/src/include/storage/lmgr.h
+++ b/src/include/storage/lmgr.h
@@ -54,8 +54,9 @@ 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 bool ConditionalXactLockTableWait(TransactionId xid);
+extern void XactLockTableWait(TransactionId xid, Oid WaitRelid);
+extern bool ConditionalXactLockTableWait(TransactionId xid, Oid WaitRelid);
+extern Oid GetXactLockTableRelid(void);
/* Lock a general object (other than a relation) of the current database */
extern void LockDatabaseObject(Oid classid, Oid objid, uint16 objsubid,
@@ -75,6 +76,6 @@ extern void UnlockSharedObjectForSession(Oid classid, Oid objid, uint16 objsubid
LOCKMODE lockmode);
/* Describe a locktag for error messages */
-extern void DescribeLockTag(StringInfo buf, const LOCKTAG *tag);
+extern void DescribeLockTag(StringInfo buf, const LOCKTAG *tag, bool describeXact);
#endif /* LMGR_H */
Simon,
* Simon Riggs (simon@2ndQuadrant.com) wrote:
Attached patch passes through further information about the lock wait,
so we can display the following message instead
LOG: process %d acquired %s on transaction %u on relation %u of
database %u after %ld.%03d ms
I love this idea. Please take these comments as an initial/quick review
because I'd really like to see this get in.
A couple quick notes regarding the patch- what does
GetXactLockTableRelid really provide..? This patch does use it outside
of lmgr.c, where XactLockTableRelid is defined. Second, do we really
need to describeXact bool to DescribeLockTag..? Strikes me as
unnecessary- if the information is available, include it.
Lastly, I really don't like the changes made to XactLockTableWait() and
friends. They had a very clearly defined and simple goal previously and
the additional parameter seems to muddy things a bit, particularly
without any comments about what it's all about or why it's there. I
understand that you're trying to pass the necessary information down to
where the log is generated, but it doesn't feel quite right. Also, what
about VirtualXactLockTableWait()..? Should that have a similar
treatment?
Thanks!
Stephen
On 16 January 2013 03:47, Stephen Frost <sfrost@snowman.net> wrote:
Simon,
* Simon Riggs (simon@2ndQuadrant.com) wrote:
Attached patch passes through further information about the lock wait,
so we can display the following message instead
LOG: process %d acquired %s on transaction %u on relation %u of
database %u after %ld.%03d msI love this idea. Please take these comments as an initial/quick review
because I'd really like to see this get in.
It's there as a way to prove FKlocks works, or not, and to help that
get committed.
It's possible we reject this in this CF, since I see it as low priority anyway.
A couple quick notes regarding the patch- what does
GetXactLockTableRelid really provide..?
The ability to access a static variable in a different module. It
doesn't provide anything other than that,
This patch does use it outside
of lmgr.c, where XactLockTableRelid is defined. Second, do we really
need to describeXact bool to DescribeLockTag..? Strikes me as
unnecessary- if the information is available, include it.
The information isn't available, which is why I didn't include it.
Comments explain that the additional information is only available
within the backend that was waiting. That's sufficient for stats, but
not enough for an extended multi-backend deadlock report.
Lastly, I really don't like the changes made to XactLockTableWait() and
friends. They had a very clearly defined and simple goal previously and
the additional parameter seems to muddy things a bit, particularly
without any comments about what it's all about or why it's there. I
understand that you're trying to pass the necessary information down to
where the log is generated, but it doesn't feel quite right.
There is an API change to XactLockTableWait() to pass the relid. That
part is essential to any solution.
There are 2 possible designs for this...
(1) Simple - we remember the relid we are waiting on in a backend-only
variable so it can be used later when generating stats.
(2) Complex - record the additional information within the unused
fields of the locktag of a TRANSACTION lock, so they will be stored
and accessible by all, within the shared lock table itself. This would
require changing the hash function for transaction lock tags so that
only the key and not the additional payload items get hashed. That
seemed a much more contentious change.
Also, what
about VirtualXactLockTableWait()..? Should that have a similar
treatment?
That isn't needed, IMHO. We wait on Xids whenever we see them on heap
tuples. Vxids aren't recorded anywhere, so they don't offer the same
blockage, which is basically for visibility checks on index creation.
That is more obvious. One might argue its needed as well, but I would
see it as a separate patch.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
* Simon Riggs (simon@2ndquadrant.com) wrote:
A couple quick notes regarding the patch- what does
GetXactLockTableRelid really provide..?The ability to access a static variable in a different module. It
doesn't provide anything other than that,
It isn't actually necessary for that currently though, is it? All calls
to it appeared to be inside the same module. Do you anticipate that
needing to change in the future?
The information isn't available, which is why I didn't include it.
Comments explain that the additional information is only available
within the backend that was waiting. That's sufficient for stats, but
not enough for an extended multi-backend deadlock report.
Right, sorry, to be clear, it seemed that we could simply detect if the
information is available and print it out if it is- and not print it if
it isn't. The additional boolean variable looked to be unnecessary, or
is there a point where OidIsValid(GetXactLockTableRelid()) will be true
but the additional information shouldn't be printed or isn't actually
available?
There is an API change to XactLockTableWait() to pass the relid. That
part is essential to any solution.
I'm wondering if we could pass in something both more generic and with
more information- perhaps a simple string which is constructed when we
have more information and is then included in the log message which is
generated? Perhaps something which includes both the relname and the
OID? Could that be used across more than just these kinds of locks? Of
course, on the flip side, I understand that we don't want to spend a lot
of time building strings and whatnot during all of these code paths;
would be nice if we could defer that until we're about to log.
Regardless, I do think it'd be good to update the comments to indicate
that the relid is being passed in solely for the purpose of being
available to be included in the log, if necessary.
(2) Complex - record the additional information within the unused
fields of the locktag of a TRANSACTION lock, so they will be stored
and accessible by all, within the shared lock table itself. This would
require changing the hash function for transaction lock tags so that
only the key and not the additional payload items get hashed. That
seemed a much more contentious change.
As the lock table is itself contended for greatly, I agree that we
probably don't want to go changing it. It would be nice if we had a way
to associate additional meta-data with why a lock is being attempted
though and for logging it.
That isn't needed, IMHO. We wait on Xids whenever we see them on heap
tuples. Vxids aren't recorded anywhere, so they don't offer the same
blockage, which is basically for visibility checks on index creation.
That is more obvious. One might argue its needed as well, but I would
see it as a separate patch.
Alright.
Thanks,
Stephen
On 16 January 2013 16:12, Stephen Frost <sfrost@snowman.net> wrote:
* Simon Riggs (simon@2ndquadrant.com) wrote:
A couple quick notes regarding the patch- what does
GetXactLockTableRelid really provide..?The ability to access a static variable in a different module. It
doesn't provide anything other than that,It isn't actually necessary for that currently though, is it? All calls
to it appeared to be inside the same module. Do you anticipate that
needing to change in the future?
OK, will change.
The information isn't available, which is why I didn't include it.
Comments explain that the additional information is only available
within the backend that was waiting. That's sufficient for stats, but
not enough for an extended multi-backend deadlock report.Right, sorry, to be clear, it seemed that we could simply detect if the
information is available and print it out if it is- and not print it if
it isn't. The additional boolean variable looked to be unnecessary, or
is there a point where OidIsValid(GetXactLockTableRelid()) will be true
but the additional information shouldn't be printed or isn't actually
available?
You might be reporting a deadlock in another backend when you are
waiting on a transaction yourself. If we don't address that we'll end
up reporting the wrong info in a way that makes it look real and
probably never even notice.
There is an API change to XactLockTableWait() to pass the relid. That
part is essential to any solution.I'm wondering if we could pass in something both more generic and with
more information- perhaps a simple string which is constructed when we
have more information and is then included in the log message which is
generated? Perhaps something which includes both the relname and the
OID? Could that be used across more than just these kinds of locks? Of
course, on the flip side, I understand that we don't want to spend a lot
of time building strings and whatnot during all of these code paths;
would be nice if we could defer that until we're about to log.
Keeping it as an Oid is better, since we don't always need the string.
Regardless, I do think it'd be good to update the comments to indicate
that the relid is being passed in solely for the purpose of being
available to be included in the log, if necessary.
OK, will add.
--
Simon Riggs http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers