On 31 December 2013 17:06, Simon Riggs <simon@2ndquadrant.com> wrote:
> On 31 December 2013 16:36, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> Simon Riggs <simon@2ndQuadrant.com> writes:
>>> On 31 December 2013 09:12, Christian Kruse <christian@2ndquadrant.com> wrote:
>>>> 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)
>>
>>> That is useful info.
>>
>>> I think the message should be changed to say this only, without a context line
>>
>>> LOG: process 24774 acquired ShareLock on relation "foo" (OID 16385)
>>> tuple (0,1) after 11688.720 ms
>>
>>> My reason is that pid 24774 was waiting for a *tuple lock* and it was
>>> eventually granted, so thats what it should say.
>>
>> No, that wasn't what it was waiting for, and lying to the user like that
>> isn't going to make things better.
>
> "Like that" is ambiguous and I don't understand you or what you are
> objecting to.
>
> When we run SELECT ... FOR SHARE we are attempting to lock rows. Why
> is the transaction we are waiting for important when we wait to lock
> rows, but when we wait to lock relations it isn't?
My thought is that this message refers to a lock wait for a
transaction to end, which is made as part of a request to lock a row.
But it is not 100% of the lock request and a race condition exists
that means that we might need to wait multiple times in rare
circumstances.
So reporting that tuple lock has been *acquired* would be inaccurate,
since at that point it isn't true. So we need to describe the
situation better, e.g. "as part of waiting for a tuple lock we waited
on a transaction". Not very snappy.
Anyway, the important thing is that we can work out the tie being
waited for. Maybe logging the PK value would be useful as well, but
not the whole row.
-- Simon Riggs http://www.2ndQuadrant.com/PostgreSQL Development, 24x7 Support, Training & Services