Horton

Thread

  1. Patch: Show queries of processes holding a lock

    Alexey Orlov <aporlov@gmail.com> — 2024-09-30T20:15:38Z

    Hi, there!

I created patch improving the log messages generated by
log_lock_waits.

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 3133043 still waiting for ShareLock on transaction 758
after 1000.239 ms
DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
CONTEXT: while updating tuple (0,7) in relation "foo"
STATEMENT: update foo SET val = 2;

Output with path

LOG: process 3133043 still waiting for ShareLock on transaction 758
after 1000.239 ms
DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
Process 3132855: update foo SET val = 3;
CONTEXT: while updating tuple (0,7) in relation "foo"
STATEMENT: update foo SET val = 2;

As you can see information about query that holds the lock goes into log.

If this approach proves unacceptable, we can make the log_lock_waits
parameter as an enum
and display the query if the log_lock_waits=verbose (for example).

What do you think?

Regards,

--
Orlov Alexey

  2. Re: Patch: Show queries of processes holding a lock

    wenhui qiu <qiuwenhuifx@gmail.com> — 2024-10-01T08:44:57Z

    Hi Alexey Orlov
     Thank you for your work on this path,The lock information is recorded
in detail,Easy to trace the lock competition at that time there is a
detailed lock competition log，But I have a concern,Frequent calls to this
function (pgstat_get_backend_current_activity) in heavy lock contention or
high concurrency environments may cause performance degradation, especially
when processes frequently enter and exit lock waits. Can you add a guc
parameter to turn this feature on or off?After all communities for this
parameter( log_lock_waits )default values set to on many people concern (
https://commitfest.postgresql.org/49/4718/)



Thanks

Alexey Orlov <aporlov@gmail.com> 于2024年10月1日周二 16:04写道：

> Hi, there!
>
> I created patch improving the log messages generated by
> log_lock_waits.
>
> 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 3133043 still waiting for ShareLock on transaction 758
> after 1000.239 ms
> DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
> CONTEXT: while updating tuple (0,7) in relation "foo"
> STATEMENT: update foo SET val = 2;
>
> Output with path
>
> LOG: process 3133043 still waiting for ShareLock on transaction 758
> after 1000.239 ms
> DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
> Process 3132855: update foo SET val = 3;
> CONTEXT: while updating tuple (0,7) in relation "foo"
> STATEMENT: update foo SET val = 2;
>
> As you can see information about query that holds the lock goes into log.
>
> If this approach proves unacceptable, we can make the log_lock_waits
> parameter as an enum
> and display the query if the log_lock_waits=verbose (for example).
>
> What do you think?
>
> Regards,
>
> --
> Orlov Alexey
>

  3. Re: Patch: Show queries of processes holding a lock

    Alexey Orlov <aporlov@gmail.com> — 2024-10-02T09:43:03Z

    On Tue, Oct 1, 2024 at 11:45 AM wenhui qiu <qiuwenhuifx@gmail.com> wrote:
>
> Hi Alexey Orlov
>      Thank you for your work on this path,The lock information is recorded in detail,Easy to trace the lock competition at that time there is a detailed lock competition log，But I have a concern,Frequent calls to this function (pgstat_get_backend_current_activity) in heavy lock contention or high concurrency environments may cause performance degradation, especially when processes frequently enter and exit lock waits. Can you add a guc parameter to turn this feature on or off?After all communities for this parameter( log_lock_waits )default values set to on many people concern (https://commitfest.postgresql.org/49/4718/)
>
>
>
> Thanks
>
Yeah, agree, thank you. I just think changing the parameter type would
be nice too.

 typedef enum
{
 LOG_LOCK_WAIT_NONE = 0,
 LOG_LOCK_WAIT_TERSE,
 LOG_LOCK_WAIT_VERBOSE,
} LogLockWaitVerbosity;

LOG_LOCK_WAIT_NONE is "off", LOG_LOCK_WAIT_TERSE is "on",
LOG_LOCK_WAIT_VERBOSE enables  writing the query to to the log.

I've attached a slightly modified patch to use the new log_lock_wait values.

--
Regards,
 Alexey Orlov!

  4. Re: Patch: Show queries of processes holding a lock

    David Rowley <dgrowleyml@gmail.com> — 2024-10-03T00:58:12Z

    On Tue, 1 Oct 2024 at 21:04, Alexey Orlov <aporlov@gmail.com> wrote:
> 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;
>
> LOG: process 3133043 still waiting for ShareLock on transaction 758
> after 1000.239 ms
> DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
> Process 3132855: update foo SET val = 3;
> CONTEXT: while updating tuple (0,7) in relation "foo"
> STATEMENT: update foo SET val = 2;

> What do you think?

Can you explain why the last query executed by the blocking process is
relevant output to show?  Are you just hoping that the last statement
to execute is the one that obtained the lock? Wouldn't it be confusing
if the last query to execute wasn't the query which obtained the lock?

David

  5. Re: Patch: Show queries of processes holding a lock

    Alexey Orlov <aporlov@gmail.com> — 2024-10-03T09:32:59Z

    On Thu, Oct 3, 2024 at 3:58 AM David Rowley <dgrowleyml@gmail.com> wrote:
>
> On Tue, 1 Oct 2024 at 21:04, Alexey Orlov <aporlov@gmail.com> wrote:
> > 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;
> >
> > LOG: process 3133043 still waiting for ShareLock on transaction 758
> > after 1000.239 ms
> > DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
> > Process 3132855: update foo SET val = 3;
> > CONTEXT: while updating tuple (0,7) in relation "foo"
> > STATEMENT: update foo SET val = 2;
>
> > What do you think?
>
> Can you explain why the last query executed by the blocking process is
> relevant output to show?  Are you just hoping that the last statement
> to execute is the one that obtained the lock? Wouldn't it be confusing
> if the last query to execute wasn't the query which obtained the lock?
>
> David
Thanks for the review! I completely agree with you,  relying on chance is wrong.
What if I do a small check? I’ll check whether the command string has
changed during the DeadLockTimeout.
And if so we will see in the log:

Process holding the lock: 1057195. Wait queue: 1057550.
Process 1057195: <command string has been changed>

I have shared updated patch[3]

-- 
Regards,
Alexey Orlov!

  6. Re: Patch: Show queries of processes holding a lock

    Viktor Holmberg <v@viktorh.net> — 2025-12-23T13:58:46Z

    I know this was a long time ago, do you still have interest in pursuing this patch Alexey?
Having this capability would be a big help when debugging locking issues after the fact.
Re. The fact that the last query isn’t necessarily the one holding the lock - yes that’s annoying but even so, knowing which was the last query executed by the blocking process would help as it allows one to narrow down what job/process is causing the locking.
On 3 Oct 2024 at 11:33 +0200, Alexey Orlov <aporlov@gmail.com>, wrote:
> On Thu, Oct 3, 2024 at 3:58 AM David Rowley <dgrowleyml@gmail.com> wrote:
> >
> > On Tue, 1 Oct 2024 at 21:04, Alexey Orlov <aporlov@gmail.com> wrote:
> > > 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;
> > >
> > > LOG: process 3133043 still waiting for ShareLock on transaction 758
> > > after 1000.239 ms
> > > DETAIL: Process holding the lock: 3132855. Wait queue: 3133043.
> > > Process 3132855: update foo SET val = 3;
> > > CONTEXT: while updating tuple (0,7) in relation "foo"
> > > STATEMENT: update foo SET val = 2;
> >
> > > What do you think?
> >
> > Can you explain why the last query executed by the blocking process is
> > relevant output to show? Are you just hoping that the last statement
> > to execute is the one that obtained the lock? Wouldn't it be confusing
> > if the last query to execute wasn't the query which obtained the lock?
> >
> > David
> Thanks for the review! I completely agree with you, relying on chance is wrong.
> What if I do a small check? I’ll check whether the command string has
> changed during the DeadLockTimeout.
> And if so we will see in the log:
>
> Process holding the lock: 1057195. Wait queue: 1057550.
> Process 1057195: <command string has been changed>
>
> I have shared updated patch[3]
>
> --
> Regards,
> Alexey Orlov!