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 <christian@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

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.GB25649@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&gt;) and
the second, new one is located here:

<https://commitfest.postgresql.org/action/patch_view?id=1351&gt;

Regards,

--
Christian Kruse http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

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

On 22 January 2014 04:42, Rajeev rastogi <rajeev.rastogi@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 XXXX 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

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 XXXX 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

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 Herrera 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

Alvaro Herrera <alvherre@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

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 <alvherre@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

Christian Kruse <christian@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

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

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

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

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

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

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

On Tue, Jan 28, 2014 at 6:39 PM, Rajeev rastogi
<rajeev.rastogi@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

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

On Sat, Feb 1, 2014 at 7:41 PM, Christian Kruse
<christian@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

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