Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On Tue, Feb 25, 2014 at 1:03 PM, Rajeev rastogi rajeev.rast...@huawei.com wrote: On 04 February 2014 14:38, Myself wrote: On 4th February 2014, Christian kruse Wrote: On 04/02/14 12:38, Fujii Masao wrote: ISTM that the phrase Request queue is not used much around the lock. Using the phrase wait queue or Simon's suggestion sound better to at least me. Thought? Sounds reasonable to me. Attached patch changes messages to the following: Process holding the lock: A. Wait queue: B. Processes holding the lock: A, B. Wait queue: C. This looks good to me also. I have tested the revised patch and found ready to be committed. I am marking this as Ready for Committer. Committed! Regards, -- Fujii Masao -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi, On 13/03/14 03:27, Fujii Masao wrote: Committed! Thank you very much! Best regards, -- Christian Kruse http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services pgpkDoVMmXIL4.pgp Description: PGP signature
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 04 February 2014 14:38, Myself wrote: On 4th February 2014, Christian kruse Wrote: On 04/02/14 12:38, Fujii Masao wrote: ISTM that the phrase Request queue is not used much around the lock. Using the phrase wait queue or Simon's suggestion sound better to at least me. Thought? Sounds reasonable to me. Attached patch changes messages to the following: Process holding the lock: A. Wait queue: B. Processes holding the lock: A, B. Wait queue: C. This looks good to me also. I have tested the revised patch and found ready to be committed. I am marking this as Ready for Committer. Thanks and Regards, Kumar Rajeev Rastogi -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
On 04/02/14 12:38, Fujii Masao wrote:
ISTM that the phrase Request queue is not used much around the lock.
Using the phrase wait queue or Simon's suggestion sound better to at least
me.
Thought?
Sounds reasonable to me. Attached patch changes messages to the following:
Process holding the lock: A. Wait queue: B.
Processes holding the lock: A, B. Wait queue: C.
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/doc/src/sgml/sources.sgml b/doc/src/sgml/sources.sgml
index 881b0c3..aa20807 100644
--- a/doc/src/sgml/sources.sgml
+++ b/doc/src/sgml/sources.sgml
@@ -251,6 +251,15 @@ ereport(ERROR,
/listitem
listitem
para
+ functionerrdetail_log_plural(const char *fmt_singuar, const char
+ *fmt_plural, unsigned long n, ...)/function is like
+ functionerrdetail_log/, but with support for various plural forms of
+ the message.
+ For more information see xref linkend=nls-guidelines.
+/para
+ /listitem
+ listitem
+para
functionerrhint(const char *msg, ...)/function supplies an optional
quotehint/ message; this is to be used when offering suggestions
about how to fix the problem, as opposed to factual details about
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index fb449a8..9620f6e 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1209,13 +1209,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1225,10 +1235,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ /*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock-procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Wait queue: %s.,
+ Processes holding the lock: %s. Wait queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1240,13 +1307,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Wait queue: %s.,
+ Processes holding the lock: %s. Wait queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg(process %d still waiting for
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 4th February 2014, Christian kruse Wrote: On 04/02/14 12:38, Fujii Masao wrote: ISTM that the phrase Request queue is not used much around the lock. Using the phrase wait queue or Simon's suggestion sound better to at least me. Thought? Sounds reasonable to me. Attached patch changes messages to the following: Process holding the lock: A. Wait queue: B. Processes holding the lock: A, B. Wait queue: C. This looks good to me also. Thanks and Regards, Kumar Rajeev Rastogi -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On Sat, Feb 1, 2014 at 7:41 PM, Christian Kruse christ...@2ndquadrant.com wrote: Hi, On 01/02/14 02:45, Fujii Masao wrote: LOG: process 33662 still waiting for ShareLock on transaction 1011 after 1000.184 ms DETAIL: Process holding the lock: 33660. Request queue: 33662. [... snip ...] LOG: process 33665 still waiting for ExclusiveLock on tuple (0,4) of relation 16384 of database 12310 after 1000.134 ms DETAIL: Process holding the lock: 33662. Request queue: 33665 This log message says that the process 33662 is holding the lock, but it's not true. As the message says: first lock is waiting for the transaction, second one for the tuple. So that are two different locks thus the two different holders and queues. So... Is this the intentional behavior? Yes, I think so. Oh, yes. You're right. I have other minor comments: Since you added errdetail_log_plural(), ISTM that you need to update sources.sgml. While I'm griping, this message isn't even trying to follow the project's message style guidelines. Detail or context messages are supposed to be complete sentence(s), with capitalization and punctuation to match. Hm, I hope I fixed it in this version of the patch. Current message doesn't look like complete sentence yet... We would need to use something like Processes X, Y are holding while Z is waiting for the lock.. I could not come up with good message, though.. Regards, -- Fujii Masao -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
On 03/02/14 17:59, Fujii Masao wrote:
Since you added errdetail_log_plural(), ISTM that you need to update
sources.sgml.
[x] Fixed.
While I'm griping, this message isn't even trying to follow the project's
message style guidelines. Detail or context messages are supposed to be
complete sentence(s), with capitalization and punctuation to match.
Hm, I hope I fixed it in this version of the patch.
Current message doesn't look like complete sentence yet... We would
need to use something like Processes X, Y are holding while Z is waiting
for the lock.. I could not come up with good message, though..
The problem is that we have two potential plural cases in this
message. That leads to the need to formulate the second part
independently from singular/plural. I tried to improve a little bit
and propose this message:
Singular:
The following process is holding the lock: A. The request queue
consists of: B.
Plural:
Following processes are holding the lock: A, B. The request queue
consists of: C.
Attached you will find an updated patch.
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/doc/src/sgml/sources.sgml b/doc/src/sgml/sources.sgml
index 881b0c3..aa20807 100644
--- a/doc/src/sgml/sources.sgml
+++ b/doc/src/sgml/sources.sgml
@@ -251,6 +251,15 @@ ereport(ERROR,
/listitem
listitem
para
+ functionerrdetail_log_plural(const char *fmt_singuar, const char
+ *fmt_plural, unsigned long n, ...)/function is like
+ functionerrdetail_log/, but with support for various plural forms of
+ the message.
+ For more information see xref linkend=nls-guidelines.
+/para
+ /listitem
+ listitem
+para
functionerrhint(const char *msg, ...)/function supplies an optional
quotehint/ message; this is to be used when offering suggestions
about how to fix the problem, as opposed to factual details about
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index fb449a8..da72c82 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1209,13 +1209,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1225,10 +1235,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ /*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock-procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(The following process is holding the lock: %s. The request queue consists of: %s.,
+ Following processes are holding the lock: %s. The request queue consists of: %s.,
+
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 3 February 2014 10:06, Christian Kruse christ...@2ndquadrant.com wrote: Hi, On 03/02/14 17:59, Fujii Masao wrote: Since you added errdetail_log_plural(), ISTM that you need to update sources.sgml. [x] Fixed. While I'm griping, this message isn't even trying to follow the project's message style guidelines. Detail or context messages are supposed to be complete sentence(s), with capitalization and punctuation to match. Hm, I hope I fixed it in this version of the patch. Current message doesn't look like complete sentence yet... We would need to use something like Processes X, Y are holding while Z is waiting for the lock.. I could not come up with good message, though.. The problem is that we have two potential plural cases in this message. That leads to the need to formulate the second part independently from singular/plural. I tried to improve a little bit and propose this message: Singular: The following process is holding the lock: A. The request queue consists of: B. Plural: Following processes are holding the lock: A, B. The request queue consists of: C. Seems too complex. How about this... Lock holder(s): A. Lock waiter(s) B Lock holder(s): A, B. Lock waiter(s) C -- 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
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi Simon, On 03/02/14 10:43, Simon Riggs wrote: Singular: The following process is holding the lock: A. The request queue consists of: B. Plural: Following processes are holding the lock: A, B. The request queue consists of: C. Seems too complex. How about this... Lock holder(s): A. Lock waiter(s) B Lock holder(s): A, B. Lock waiter(s) C This is basically the same as before, it is even shorter. The complaint was that I don't use a whole sentence in this error detail. Won't the change fulfill the same complaint? To be honest, I'd like to stick with your earlier proposal: Singular: Process holding the lock: A. Request queue: B Plural: Processes holding the lock: A, B. Request queue: C, D This seems to be a good trade-off between project guidelines, readability and parsability. Best regards, -- Christian Kruse http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services pgpq4w0aipTXc.pgp Description: PGP signature
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On Mon, Feb 3, 2014 at 8:53 PM, Christian Kruse christ...@2ndquadrant.com wrote: Hi Simon, On 03/02/14 10:43, Simon Riggs wrote: Singular: The following process is holding the lock: A. The request queue consists of: B. Plural: Following processes are holding the lock: A, B. The request queue consists of: C. Seems too complex. How about this... Lock holder(s): A. Lock waiter(s) B Lock holder(s): A, B. Lock waiter(s) C This is basically the same as before, it is even shorter. The complaint was that I don't use a whole sentence in this error detail. Won't the change fulfill the same complaint? To be honest, I'd like to stick with your earlier proposal: Singular: Process holding the lock: A. Request queue: B Plural: Processes holding the lock: A, B. Request queue: C, D This seems to be a good trade-off between project guidelines, readability and parsability. ISTM that the phrase Request queue is not used much around the lock. Using the phrase wait queue or Simon's suggestion sound better to at least me. Thought? Regards, -- Fujii Masao -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi, On 01/02/14 02:45, Fujii Masao wrote: LOG: process 33662 still waiting for ShareLock on transaction 1011 after 1000.184 ms DETAIL: Process holding the lock: 33660. Request queue: 33662. [… snip …] LOG: process 33665 still waiting for ExclusiveLock on tuple (0,4) of relation 16384 of database 12310 after 1000.134 ms DETAIL: Process holding the lock: 33662. Request queue: 33665 This log message says that the process 33662 is holding the lock, but it's not true. As the message says: first lock is waiting for the transaction, second one for the tuple. So that are two different locks thus the two different holders and queues. So… Is this the intentional behavior? Yes, I think so. Best regards, -- Christian Kruse http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services pgpr14uoFS4_6.pgp Description: PGP signature
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On Tue, Jan 28, 2014 at 6:39 PM, Rajeev rastogi rajeev.rast...@huawei.com wrote: On 28/01/14, Christian Kruse wrote: I have checked the revised patch. It looks fine to me except one minor code formatting issue. In elog.c, two tabs are missing in the definition of function errdetail_log_plural. Please run pgindent tool to check the same. I did, but this reformats various other locations in the file, too. Nevertheless I now ran pg_indent against it and removed the other parts. Attached you will find the corrected patch version. Also I would like to highlight one behavior here is that process ID of process trying to acquire lock is also listed in the list of Request queue. E.g. session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; On execution of LOCK in session-2, as part of log it will display as: DETAIL: Process holding the lock: X. Request queue: Y. Where Y is the process ID of same process, which was trying to acquire lock. This is on purpose due to the rewording of the Message. In the first version the PID of the backend was missing. Thanks for the review! Now patch looks fine to me. I am marking this as Ready for Committer. When I tested the patch, I got the strange behavior. 1. I executed the SELECT FOR UPDATE query and kept waiting for a while in the session 1. [session 1] PID=33660 BEGIN; SELECT * FROM t WHERE i = 1 FOR UPDATE; (Wait) 2. I executed the SELECT FOR UPDATE query again in the session 2. [session 2] PID=33662 BEGIN; SELECT * FROM t WHERE i = 1 FOR UPDATE; (Waiting for the lock) 3. I got the following log message. This is OK. LOG: process 33662 still waiting for ShareLock on transaction 1011 after 1000.184 ms DETAIL: Process holding the lock: 33660. Request queue: 33662. 4. I executed the UPDATE query in the session 3. [session 3] PID=33665 UPDATE t SET j = j + 1 WHERE i = 1; (Waiting for the lock) 5. Then, I got the following log message. This looks strange and confusing to me. LOG: process 33665 still waiting for ExclusiveLock on tuple (0,4) of relation 16384 of database 12310 after 1000.134 ms DETAIL: Process holding the lock: 33662. Request queue: 33665 This log message says that the process 33662 is holding the lock, but it's not true. The process holding the lock is 33660. The process 33662 should be in the request queue. Is this the intentional behavior? Regards, -- Fujii Masao -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
On 27/01/14 11:44, Rajeev rastogi wrote:
I have checked the revised patch. It looks fine to me except one minor code
formatting issue.
In elog.c, two tabs are missing in the definition of function
errdetail_log_plural.
Please run pgindent tool to check the same.
I did, but this reformats various other locations in the file,
too. Nevertheless I now ran pg_indent against it and removed the other
parts. Attached you will find the corrected patch version.
Also I would like to highlight one behavior here is that process ID of
process trying to
acquire lock is also listed in the list of Request queue. E.g.
session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE;
session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE;
On execution of LOCK in session-2, as part of log it will display as:
DETAIL: Process holding the lock: X. Request queue: Y.
Where Y is the process ID of same process, which was trying to acquire
lock.
This is on purpose due to the rewording of the Message. In the first
version the PID of the backend was missing.
Thanks for the review!
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index ee6c24c..6c648cf 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1211,10 +1221,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ /*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock-procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Request queue: %s.,
+ Processes holding the lock: %s. Request queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1293,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Request queue: %s.,
+ Processes holding lock: %s. Request queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg(process %d still waiting for %s on %s after
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 28/01/14, Christian Kruse wrote: I have checked the revised patch. It looks fine to me except one minor code formatting issue. In elog.c, two tabs are missing in the definition of function errdetail_log_plural. Please run pgindent tool to check the same. I did, but this reformats various other locations in the file, too. Nevertheless I now ran pg_indent against it and removed the other parts. Attached you will find the corrected patch version. Also I would like to highlight one behavior here is that process ID of process trying to acquire lock is also listed in the list of Request queue. E.g. session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; On execution of LOCK in session-2, as part of log it will display as: DETAIL: Process holding the lock: X. Request queue: Y. Where Y is the process ID of same process, which was trying to acquire lock. This is on purpose due to the rewording of the Message. In the first version the PID of the backend was missing. Thanks for the review! Now patch looks fine to me. I am marking this as Ready for Committer. Thanks and Regards, Kumar Rajeev Rastogi -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 23/01/14, Christian Kruse wrote: Well, is it context or detail? Those fields have reasonably well defined meanings IMO. I find the distinction somewhat blurry and think both would be appropriate. But since I wasn't sure I changed to detail. If we need errcontext_plural, let's add it, not adopt inferior solutions just because that isn't there for lack of previous need. I would've added it if I would've been sure. But having said that, I think this is indeed detail not context. (I kinda wonder whether some of the stuff that's now in the primary message shouldn't be pushed to errdetail as well. It looks like some previous patches in this area have been lazy.) I agree, the primary message is not very well worded. On the other hand finding an appropriate alternative seems hard for me. While I'm griping, this message isn't even trying to follow the project's message style guidelines. Detail or context messages are supposed to be complete sentence(s), with capitalization and punctuation to match. Hm, I hope I fixed it in this version of the patch. Lastly, is this information that we want to be shipping to clients? Perhaps from a security standpoint that's not such a wise idea, and errdetail_log() is what should be used. Fixed. I added an errdetail_log_plural() for this, too. I have checked the revised patch. It looks fine to me except one minor code formatting issue. In elog.c, two tabs are missing in the definition of function errdetail_log_plural. Please run pgindent tool to check the same. Also I would like to highlight one behavior here is that process ID of process trying to acquire lock is also listed in the list of Request queue. E.g. session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; On execution of LOCK in session-2, as part of log it will display as: DETAIL: Process holding the lock: X. Request queue: Y. Where Y is the process ID of same process, which was trying to acquire lock. To me, it seems to be correct behavior as the meaning of message will be list of all processes already holding the lock and processes waiting in queue and position of self process in wait-list. In above example, it will indicate that process Y in on top of wait list. Thanks and Regards, Kumar Rajeev Rastogi -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 23/01/14 14:45, Christian Kruse wrote: Well, is it context or detail? Those fields have reasonably well defined meanings IMO. I find the distinction somewhat blurry and think both would be appropriate. But since I wasn't sure I changed to detail. If we need errcontext_plural, let's add it, not adopt inferior solutions just because that isn't there for lack of previous need. I would've added it if I would've been sure. But having said that, I think this is indeed detail not context. (I kinda wonder whether some of the stuff that's now in the primary message shouldn't be pushed to errdetail as well. It looks like some previous patches in this area have been lazy.) I agree, the primary message is not very well worded. On the other hand finding an appropriate alternative seems hard for me. While I'm griping, this message isn't even trying to follow the project's message style guidelines. Detail or context messages are supposed to be complete sentence(s), with capitalization and punctuation to match. Hm, I hope I fixed it in this version of the patch. Lastly, is this information that we want to be shipping to clients? Perhaps from a security standpoint that's not such a wise idea, and errdetail_log() is what should be used. Fixed. I added an errdetail_log_plural() for this, too. I think you have attached wrong patch. Thanks and Regards, Kumar Rajeev Rastogi -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
I think you have attached wrong patch.
Hurm. You are right, attached v3, not v4. Sorry.
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index ee6c24c..6c648cf 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1211,10 +1221,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ /*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock-procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Request queue: %s.,
+ Processes holding the lock: %s. Request queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1293,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Request queue: %s.,
+ Processes holding lock: %s. Request queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg(process %d still waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Request queue: %s.,
+ Processes holding the lock: %s. Request queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (myWaitStatus == STATUS_OK)
ereport(LOG,
(errmsg(process %d acquired %s on %s after %ld.%03d ms,
@@ -1252,7 +1325,10 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
if (deadlock_state != DS_HARD_DEADLOCK)
ereport(LOG,
(errmsg(process %d failed to acquire %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errdetail_log_plural(Process holding the lock: %s. Request queue: %s.,
+ Processes holding the lock: %s. Request queue: %s.,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
}
/*
@@
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 22 January 2014 04:42, Rajeev rastogi rajeev.rast...@huawei.com wrote: On 31st December 2013, Christian Kruse Wrote: Hi there, I created two patches improving the log messages generated by log_lock_waits. The first patch shows the process IDs holding a lock we try to acquire (show_pids_in_lock_log.patch), sample output (log_lock_waits=on required): session 1: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2: BEGIN; LOCK TABLE foo IN SHARE MODE; session 3: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; Output w/o patch: LOG: process 13777 still waiting for ExclusiveLock on relation 16385 of database 16384 after 1000.030 ms Output with patch: LOG: process 13777 still waiting for ExclusiveLock on relation 16385 of database 16384 after 1000.030 ms CONTEXT: processes owning lock: 13775, 13776 I am reviewing this patch. The idea seems to be reasonable. Following are my first level observation: 1. I find a issue in following scenario: session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; session 3 with process id Z: BEGIN; LOCK TABLE foo IN SHARE MODE; On execution of LOCK in session-3, as part of log it will display as: processes owning lock: X, Y But actually if we see Y has not yet own the lock, it is still waiting with higher priority. It may mislead user. May be we should change message to give all meaning i.e. which process is owning lock and Which process is already in queue. Perhaps this? CONTEXT: lock owner request queue XXX, XXX, XXX, etc 2. Can we give a better name to new variable 'buf1'? 3. Do we need to take performance reading to see if any impact? Don't think so. Diagnosing problems will help performance, not hinder it 4. Do we require documentation? Don't think so. -- 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
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
On 22/01/14 12:40, Simon Riggs wrote:
1. I find a issue in following scenario:
session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE;
session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE
MODE;
session 3 with process id Z: BEGIN; LOCK TABLE foo IN SHARE MODE;
On execution of LOCK in session-3, as part of log it will display
as:
processes owning lock: X, Y
But actually if we see Y has not yet own the lock, it is still
waiting with higher priority.
It may mislead user.
May be we should change message to give all meaning i.e. which
process is owning lock and
Which process is already in queue.
Perhaps this?
CONTEXT: lock owner request queue XXX, XXX, XXX, etc
Fixed.
2. Can we give a better name to new variable 'buf1'?
Fixed.
3. Do we need to take performance reading to see if any impact?
Don't think so. Diagnosing problems will help performance, not hinder it
I agree. And this code path will only get executed when log_lock_waits
= on, which seems to be a debugging method to me.
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index ee6c24c..588c4ef 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1211,10 +1221,58 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum), lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1284,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum), lock_holders_sbuf.data, lock_waiters_sbuf.data;
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg(process %d still waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum),
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Christian Kruse wrote:
I think this could use some more comments -- for instance at the top of
the while loop, explain what's its purpose.
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided
deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename,
buf.data, msecs, usecs)));
+ MyProcPid,
modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process
owning lock: %s request queue: %s,
+processes owning
lock: %s request queue: %s,
+
lockHoldersNum), lock_holders_sbuf.data, lock_waiters_sbuf.data;
This ngettext() call is repeated four times in the new code, which is a
bit annoying because it's not trivial. I think you could assign the
ngettext() to a char * at the bottom of the loop, and then in the
ereport() calls use it:
char *errcxt = NULL;
while ( ... )
{
...
errcxt = ngettext(processes owning lock: ..);
}
ereport(LOG,
(errmsg(blah blah),
errcxt != NULL ? errcontext(errcxt) : 0));
That would avoid the repetition.
--
Álvaro Herrerahttp://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
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Alvaro Herrera alvhe...@2ndquadrant.com writes: This ngettext() call is repeated four times in the new code, which is a bit annoying because it's not trivial. I think you could assign the ngettext() to a char * at the bottom of the loop, and then in the ereport() calls use it: Would that not break the compiler's ability to verify the format codes in the string? Not to mention make it harder for people to compare format to arguments, too? However, the real problem here is that you shouldn't be calling ngettext manually in an ereport context in the first place. There is infrastructure in place for that, and this isn't using it. regards, tom lane -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
attached you will find a new version of the patch containing more
comments.
On 22/01/14 12:00, Tom Lane wrote:
Alvaro Herrera alvhe...@2ndquadrant.com writes:
This ngettext() call is repeated four times in the new code, which is a
bit annoying because it's not trivial. I think you could assign the
ngettext() to a char * at the bottom of the loop, and then in the
ereport() calls use it:
Would that not break the compiler's ability to verify the format codes
in the string? Not to mention make it harder for people to compare
format to arguments, too?
I agree.
However, the real problem here is that you shouldn't be calling ngettext
manually in an ereport context in the first place. There is
infrastructure in place for that, and this isn't using it.
Fixed in attached patch. I changed it from calling
errorcontext(ngettext()) to calling errdetail_plural().
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 122afb2..552c5a4 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1211,10 +1221,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ /*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock-procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+(errdetail_plural(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1293,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+(errdetail_plural(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg(process %d still waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+(errdetail_plural(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum,
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Christian Kruse christ...@2ndquadrant.com writes: However, the real problem here is that you shouldn't be calling ngettext manually in an ereport context in the first place. There is infrastructure in place for that, and this isn't using it. Fixed in attached patch. I changed it from calling errorcontext(ngettext()) to calling errdetail_plural(). Well, is it context or detail? Those fields have reasonably well defined meanings IMO. If we need errcontext_plural, let's add it, not adopt inferior solutions just because that isn't there for lack of previous need. But having said that, I think this is indeed detail not context. (I kinda wonder whether some of the stuff that's now in the primary message shouldn't be pushed to errdetail as well. It looks like some previous patches in this area have been lazy.) While I'm griping, this message isn't even trying to follow the project's message style guidelines. Detail or context messages are supposed to be complete sentence(s), with capitalization and punctuation to match. Lastly, is this information that we want to be shipping to clients? Perhaps from a security standpoint that's not such a wise idea, and errdetail_log() is what should be used. regards, tom lane -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi,
On 22/01/14 14:45, Tom Lane wrote:
Well, is it context or detail? Those fields have reasonably well defined
meanings IMO.
I find the distinction somewhat blurry and think both would be
appropriate. But since I wasn't sure I changed to detail.
If we need errcontext_plural, let's add it, not adopt inferior solutions
just because that isn't there for lack of previous need.
I would've added it if I would've been sure.
But having said that, I think this is indeed detail not context.
(I kinda wonder whether some of the stuff that's now in the primary
message shouldn't be pushed to errdetail as well. It looks like some
previous patches in this area have been lazy.)
I agree, the primary message is not very well worded. On the other
hand finding an appropriate alternative seems hard for me.
While I'm griping, this message isn't even trying to follow the project's
message style guidelines. Detail or context messages are supposed to be
complete sentence(s), with capitalization and punctuation to match.
Hm, I hope I fixed it in this version of the patch.
Lastly, is this information that we want to be shipping to clients?
Perhaps from a security standpoint that's not such a wise idea, and
errdetail_log() is what should be used.
Fixed. I added an errdetail_log_plural() for this, too.
Best regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 122afb2..552c5a4 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ lock_waiters_sbuf,
+ lock_holders_sbuf;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first_holder = true,
+ first_waiter = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(lock_waiters_sbuf);
+ initStringInfo(lock_holders_sbuf);
+
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1211,10 +1221,67 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ /*
+ * we loop over the lock's procLocks to gather a list of all
+ * holders and waiters. Thus we will be able to provide more
+ * detailed information for lock debugging purposes.
+ *
+ * lock-procLocks contains all processes which hold or wait for
+ * this lock.
+ */
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+/*
+ * we are a waiter if myProc-waitProcLock == proclock; we are
+ * a holder if it is NULL or something different
+ */
+if (proclock-tag.myProc-waitProcLock == proclock)
+{
+ if (first_waiter)
+ {
+ appendStringInfo(lock_waiters_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_waiter = false;
+ }
+ else
+ appendStringInfo(lock_waiters_sbuf, , %d,
+ proclock-tag.myProc-pid);
+}
+else
+{
+ if (first_holder)
+ {
+ appendStringInfo(lock_holders_sbuf, %d,
+ proclock-tag.myProc-pid);
+ first_holder = false;
+ }
+ else
+ appendStringInfo(lock_holders_sbuf, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+(errdetail_plural(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1293,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+(errdetail_plural(process owning lock: %s request queue: %s,
+ processes owning lock: %s request queue: %s,
+ lockHoldersNum, lock_holders_sbuf.data,
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 31st December 2013, Christian Kruse Wrote: Hi there, I created two patches improving the log messages generated by log_lock_waits. The first patch shows the process IDs holding a lock we try to acquire (show_pids_in_lock_log.patch), sample output (log_lock_waits=on required): session 1: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2: BEGIN; LOCK TABLE foo IN SHARE MODE; session 3: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; Output w/o patch: LOG: process 13777 still waiting for ExclusiveLock on relation 16385 of database 16384 after 1000.030 ms Output with patch: LOG: process 13777 still waiting for ExclusiveLock on relation 16385 of database 16384 after 1000.030 ms CONTEXT: processes owning lock: 13775, 13776 I am reviewing this patch. The idea seems to be reasonable. Following are my first level observation: 1. I find a issue in following scenario: session 1 with process id X: BEGIN; LOCK TABLE foo IN SHARE MODE; session 2 with process id Y: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE; session 3 with process id Z: BEGIN; LOCK TABLE foo IN SHARE MODE; On execution of LOCK in session-3, as part of log it will display as: processes owning lock: X, Y But actually if we see Y has not yet own the lock, it is still waiting with higher priority. It may mislead user. May be we should change message to give all meaning i.e. which process is owning lock and Which process is already in queue. 2. Can we give a better name to new variable 'buf1'? 3. Do we need to take performance reading to see if any impact? 4. Do we require documentation? Thanks and Regards, Kumar Rajeev Rastogi -- Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-hackers
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
On 30 December 2013 19:52, Christian Kruse christ...@2ndquadrant.com wrote: I created two patches.. Patches are related but separate, so should be tracked on separate threads. Please add them to the CF app also. -- 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
Re: [HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi, On 31/12/13 08:48, Simon Riggs wrote: I created two patches.. Patches are related but separate, so should be tracked on separate threads. [x] Done (in 20131231091244.gb25...@defunct.ch) Please add them to the CF app also. [x] Done. I modified the existing commitfest entry (https://commitfest.postgresql.org/action/patch_view?id=1350) and the second, new one is located here: https://commitfest.postgresql.org/action/patch_view?id=1351 Regards, -- Christian Kruse http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training Services pgpfpe4EtSAQ4.pgp Description: PGP signature
[HACKERS] Patch: Show process IDs of processes holding a lock; show relation and tuple infos of a lock to acquire
Hi there,
I created two patches improving the log messages generated by
log_lock_waits. The first patch shows the process IDs holding a lock
we try to acquire (show_pids_in_lock_log.patch), sample output
(log_lock_waits=on required):
session 1: BEGIN; LOCK TABLE foo IN SHARE MODE;
session 2: BEGIN; LOCK TABLE foo IN SHARE MODE;
session 3: BEGIN; LOCK TABLE foo IN EXCLUSIVE MODE;
Output w/o patch:
LOG: process 13777 still waiting for ExclusiveLock on relation 16385 of
database 16384 after 1000.030 ms
Output with patch:
LOG: process 13777 still waiting for ExclusiveLock on relation 16385 of
database 16384 after 1000.030 ms
CONTEXT: processes owning lock: 13775, 13776
The second patch (show_table_name_and_tuple_in_lock_log.patch)
includes relation info (table name and OID) as well as some tuple
information (if available). Sample output (log_lock_waits=on required):
session 1:
CREATE TABLE foo (val integer);
INSERT INTO foo (val) VALUES (1);
BEGIN;
UPDATE foo SET val = 3;
session 2:
BEGIN;
UPDATE TABLE foo SET val = 2;
Output w/o patch:
LOG: process 24774 acquired ShareLock on transaction 696 after 11688.720 ms
Output with patch:
LOG: process 24774 acquired ShareLock on transaction 696 after 11688.720 ms
CONTEXT: relation name: foo (OID 16385)
tuple (ctid (0,1)): (1)
Regarding this patch I am not really sure where to put the
functions. Currently they are located in backend/storage/lmgr/lmgr.c
because XactLockTableWait() is located there, too. What do you think?
I also created two test specs for easy creation of the log output;
however, I was not able to provide an expected file since the process
IDs vary from test run to test run.
Regards,
--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training Services
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index 122afb2..fdfacdf 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -1195,13 +1195,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (log_lock_waits deadlock_state != DS_NOT_YET_CHECKED)
{
- StringInfoData buf;
+ StringInfoData buf,
+ buf1;
const char *modename;
long secs;
int usecs;
long msecs;
+ SHM_QUEUE *procLocks;
+ PROCLOCK *proclock;
+ bool first = true;
+ int lockHoldersNum = 0;
initStringInfo(buf);
+ initStringInfo(buf1);
DescribeLockTag(buf, locallock-tag.lock);
modename = GetLockmodeName(locallock-tag.lock.locktag_lockmethodid,
lockmode);
@@ -1211,10 +1217,42 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
msecs = secs * 1000 + usecs / 1000;
usecs = usecs % 1000;
+ LWLockAcquire(partitionLock, LW_SHARED);
+
+ procLocks = (lock-procLocks);
+ proclock = (PROCLOCK *) SHMQueueNext(procLocks, procLocks,
+ offsetof(PROCLOCK, lockLink));
+
+ while (proclock)
+ {
+if (MyProc-pid != proclock-tag.myProc-pid)
+{
+ if (first)
+ {
+ appendStringInfo(buf1, %d,
+ proclock-tag.myProc-pid);
+ first = false;
+ }
+ else
+ appendStringInfo(buf1, , %d,
+ proclock-tag.myProc-pid);
+
+ lockHoldersNum++;
+}
+
+proclock = (PROCLOCK *) SHMQueueNext(procLocks, proclock-lockLink,
+ offsetof(PROCLOCK, lockLink));
+ }
+
+ LWLockRelease(partitionLock);
+
if (deadlock_state == DS_SOFT_DEADLOCK)
ereport(LOG,
(errmsg(process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process owning lock: %s,
+ processes owning lock: %s,
+ lockHoldersNum), buf1.data;
else if (deadlock_state == DS_HARD_DEADLOCK)
{
/*
@@ -1226,13 +1264,19 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
ereport(LOG,
(errmsg(process %d detected deadlock while waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process owning lock: %s,
+ processes owning lock: %s,
+ lockHoldersNum), buf1.data;
}
if (myWaitStatus == STATUS_WAITING)
ereport(LOG,
(errmsg(process %d still waiting for %s on %s after %ld.%03d ms,
- MyProcPid, modename, buf.data, msecs, usecs)));
+MyProcPid, modename, buf.data, msecs, usecs),
+ (errcontext(ngettext(process owning lock: %s,
+ processes owning lock: %s,
+ lockHoldersNum), buf1.data;
else if (myWaitStatus == STATUS_OK)
ereport(LOG,
(errmsg(process %d acquired %s on %s after %ld.%03d ms,
@@ -1252,7 +1296,10 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
if (deadlock_state !=
