Re: 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(dot)rastogi(at)huawei(dot)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