pg.ddx.io pgsql-hackers@postgresql.org mailing list archive help / color / mirror / Atom feed From: torikoshia <torikoshia@oss.nttdata.com>
To: Fujii Masao <masao.fujii@oss.nttdata.com>
Cc: Ian Lawrence Barwick <barwick@gmail.com>
Cc: Robert Haas <robertmhaas@gmail.com>
Cc: Justin Pryzby <pryzby@telsasoft.com>
Cc: pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: adding wait_start column to pg_locks
Date: Fri, 22 Jan 2021 14:37:50 +0900
Message-ID: <a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com> (raw )
In-Reply-To: <7b1bb07a-73ec-1fcc-2f65-41101adf0080@oss.nttdata.com >
References: <a96013dc51cdc56b2a2b84fa8a16a993@oss.nttdata.com >
<20210101214930.GH25152@telsasoft.com >
<9e958478d8bcea814e7ce16511a18912@oss.nttdata.com >
<CAB8KJ=hN=sz2+u3cQ+5jhZT9+TP-N7OCBLTp68L4fkVoVTqWjw@mail.gmail.com >
<CA+TgmoYowQhMhT74AsxDib6e3LFPGvXVxVOUdP0-hMNY9c1wgw@mail.gmail.com >
<CAB8KJ=idS0m_+65d2ujjjZj5DSwpYYV3XoHMwr-UZ-OFs3Mb4Q@mail.gmail.com >
<23d39ee9c31643fad8f9ba9c5cf3aaf4@oss.nttdata.com >
<0fd375a53e306566cea7f451cc8cfcde@oss.nttdata.com >
<7b1bb07a-73ec-1fcc-2f65-41101adf0080@oss.nttdata.com >
On 2021-01-21 12:48, Fujii Masao wrote:
> Thanks for updating the patch! I think that this is really useful
> feature!!
Thanks for reviewing!
> I have two minor comments.
>
> + <entry role="catalog_table_entry"><para
> role="column_definition">
> + <structfield>wait_start</structfield> <type>timestamptz</type>
>
> The column name "wait_start" should be "waitstart" for the sake of
> consistency
> with other column names in pg_locks? pg_locks seems to avoid including
> an underscore in column names, so "locktype" is used instead of
> "lock_type",
> "virtualtransaction" is used instead of "virtual_transaction", etc.
>
> + Lock acquisition wait start time. <literal>NULL</literal> if
> + lock acquired.
>
Agreed.
I also changed the variable name "wait_start" in struct PGPROC and
LockInstanceData to "waitStart" for the same reason.
> There seems the case where the wait start time is NULL even when
> "grant"
> is false. It's better to add note about that case into the docs? For
> example,
> I found that the wait start time is NULL while the startup process is
> waiting
> for the lock. Is this only that case?
Thanks, this is because I set 'waitstart' in the following
condition.
---src/backend/storage/lmgr/proc.c
> 1250 if (!InHotStandby)
As far as considering this, I guess startup process would
be the only case.
I also think that in case of startup process, it seems possible
to set 'waitstart' in ResolveRecoveryConflictWithLock(), so I
did it in the attached patch.
Any thoughts?
Regards,
--
Atsushi Torikoshi
Attachments:
[text/x-diff] v5-0001-To-examine-the-duration-of-locks-we-did-join-on-p.patch (10.1K, ../a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com/2-v5-0001-To-examine-the-duration-of-locks-we-did-join-on-p.patch)
download | inline diff:
From 6beb1c61e72c797c915427ae4e36d6bab9e0594c Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikoshia@oss.nttdata.com>
Date: Fri, 22 Jan 2021 13:51:00 +0900
Subject: [PATCH v5] To examine the duration of locks, we did join on pg_locks
and pg_stat_activity and used columns such as query_start or state_change.
However, since they are the moment when queries have started or their state
has changed, we could not get the exact lock duration in this way.
---
contrib/amcheck/expected/check_btree.out | 4 ++--
doc/src/sgml/catalogs.sgml | 10 ++++++++++
src/backend/storage/ipc/standby.c | 8 ++++++--
src/backend/storage/lmgr/lock.c | 8 ++++++++
src/backend/storage/lmgr/proc.c | 4 ++++
src/backend/utils/adt/lockfuncs.c | 9 ++++++++-
src/include/catalog/pg_proc.dat | 6 +++---
src/include/storage/lock.h | 2 ++
src/include/storage/proc.h | 1 +
src/test/regress/expected/rules.out | 5 +++--
10 files changed, 47 insertions(+), 10 deletions(-)
diff --git a/contrib/amcheck/expected/check_btree.out b/contrib/amcheck/expected/check_btree.out
index 13848b7449..5a3f1ef737 100644
--- a/contrib/amcheck/expected/check_btree.out
+++ b/contrib/amcheck/expected/check_btree.out
@@ -97,8 +97,8 @@ SELECT bt_index_parent_check('bttest_b_idx');
SELECT * FROM pg_locks
WHERE relation = ANY(ARRAY['bttest_a', 'bttest_a_idx', 'bttest_b', 'bttest_b_idx']::regclass[])
AND pid = pg_backend_pid();
- locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath
-----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------
+ locktype | database | relation | page | tuple | virtualxid | transactionid | classid | objid | objsubid | virtualtransaction | pid | mode | granted | fastpath | waitstart
+----------+----------+----------+------+-------+------------+---------------+---------+-------+----------+--------------------+-----+------+---------+----------+-----------
(0 rows)
COMMIT;
diff --git a/doc/src/sgml/catalogs.sgml b/doc/src/sgml/catalogs.sgml
index 43d7a1ad90..ba003ce393 100644
--- a/doc/src/sgml/catalogs.sgml
+++ b/doc/src/sgml/catalogs.sgml
@@ -10589,6 +10589,16 @@ SCRAM-SHA-256$<replaceable><iteration count></replaceable>:<replaceable>&l
lock table
</para></entry>
</row>
+
+ <row>
+ <entry role="catalog_table_entry"><para role="column_definition">
+ <structfield>waitstart</structfield> <type>timestamptz</type>
+ </para>
+ <para>
+ Lock acquisition wait start time. <literal>NULL</literal> if
+ lock acquired
+ </para></entry>
+ </row>
</tbody>
</tgroup>
</table>
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.c
index 39a30c00f7..819e00e4ab 100644
--- a/src/backend/storage/ipc/standby.c
+++ b/src/backend/storage/ipc/standby.c
@@ -539,13 +539,17 @@ ResolveRecoveryConflictWithDatabase(Oid dbid)
void
ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool logging_conflict)
{
- TimestampTz ltime;
+ TimestampTz ltime, now;
Assert(InHotStandby);
ltime = GetStandbyLimitTime();
+ now = GetCurrentTimestamp();
- if (GetCurrentTimestamp() >= ltime && ltime != 0)
+ if (MyProc->waitStart == 0)
+ MyProc->waitStart = now;
+
+ if (now >= ltime && ltime != 0)
{
/*
* We're already behind, so clear a path as quickly as possible.
diff --git a/src/backend/storage/lmgr/lock.c b/src/backend/storage/lmgr/lock.c
index 20e50247ea..ffad4e94bc 100644
--- a/src/backend/storage/lmgr/lock.c
+++ b/src/backend/storage/lmgr/lock.c
@@ -3627,6 +3627,12 @@ GetLockStatusData(void)
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ /*
+ * Successfully taking fast path lock means there were no
+ * conflicting locks.
+ */
+ instance->waitStart = 0;
+
el++;
}
@@ -3654,6 +3660,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ instance->waitStart = 0;
el++;
}
@@ -3706,6 +3713,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proclock->groupLeader->pid;
instance->fastpath = false;
+ instance->waitStart = proc->waitStart;
el++;
}
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c
index c87ffc6549..725f1d367a 100644
--- a/src/backend/storage/lmgr/proc.c
+++ b/src/backend/storage/lmgr/proc.c
@@ -402,6 +402,7 @@ InitProcess(void)
MyProc->lwWaitMode = 0;
MyProc->waitLock = NULL;
MyProc->waitProcLock = NULL;
+ MyProc->waitStart = 0;
#ifdef USE_ASSERT_CHECKING
{
int i;
@@ -1262,6 +1263,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
+
+ MyProc->waitStart = get_timeout_start_time(DEADLOCK_TIMEOUT);
}
else if (log_recovery_conflict_waits)
{
@@ -1678,6 +1681,7 @@ ProcWakeup(PGPROC *proc, ProcWaitStatus waitStatus)
proc->waitLock = NULL;
proc->waitProcLock = NULL;
proc->waitStatus = waitStatus;
+ proc->waitStart = 0;
/* And awaken it */
SetLatch(&proc->procLatch);
diff --git a/src/backend/utils/adt/lockfuncs.c b/src/backend/utils/adt/lockfuncs.c
index b1cf5b79a7..97f0265c12 100644
--- a/src/backend/utils/adt/lockfuncs.c
+++ b/src/backend/utils/adt/lockfuncs.c
@@ -63,7 +63,7 @@ typedef struct
} PG_Lock_Status;
/* Number of columns in pg_locks output */
-#define NUM_LOCK_STATUS_COLUMNS 15
+#define NUM_LOCK_STATUS_COLUMNS 16
/*
* VXIDGetDatum - Construct a text representation of a VXID
@@ -142,6 +142,8 @@ pg_lock_status(PG_FUNCTION_ARGS)
BOOLOID, -1, 0);
TupleDescInitEntry(tupdesc, (AttrNumber) 15, "fastpath",
BOOLOID, -1, 0);
+ TupleDescInitEntry(tupdesc, (AttrNumber) 16, "waitstart",
+ TIMESTAMPTZOID, -1, 0);
funcctx->tuple_desc = BlessTupleDesc(tupdesc);
@@ -336,6 +338,10 @@ pg_lock_status(PG_FUNCTION_ARGS)
values[12] = CStringGetTextDatum(GetLockmodeName(instance->locktag.locktag_lockmethodid, mode));
values[13] = BoolGetDatum(granted);
values[14] = BoolGetDatum(instance->fastpath);
+ if (!granted && instance->waitStart != 0)
+ values[15] = TimestampTzGetDatum(instance->waitStart);
+ else
+ nulls[15] = true;
tuple = heap_form_tuple(funcctx->tuple_desc, values, nulls);
result = HeapTupleGetDatum(tuple);
@@ -406,6 +412,7 @@ pg_lock_status(PG_FUNCTION_ARGS)
values[12] = CStringGetTextDatum("SIReadLock");
values[13] = BoolGetDatum(true);
values[14] = BoolGetDatum(false);
+ nulls[15] = true;
tuple = heap_form_tuple(funcctx->tuple_desc, values, nulls);
result = HeapTupleGetDatum(tuple);
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat
index b5f52d4e4a..61310781ca 100644
--- a/src/include/catalog/pg_proc.dat
+++ b/src/include/catalog/pg_proc.dat
@@ -5986,9 +5986,9 @@
{ oid => '1371', descr => 'view system lock information',
proname => 'pg_lock_status', prorows => '1000', proretset => 't',
provolatile => 'v', prorettype => 'record', proargtypes => '',
- proallargtypes => '{text,oid,oid,int4,int2,text,xid,oid,oid,int2,text,int4,text,bool,bool}',
- proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
- proargnames => '{locktype,database,relation,page,tuple,virtualxid,transactionid,classid,objid,objsubid,virtualtransaction,pid,mode,granted,fastpath}',
+ proallargtypes => '{text,oid,oid,int4,int2,text,xid,oid,oid,int2,text,int4,text,bool,bool,timestamptz}',
+ proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o,o,o,o,o}',
+ proargnames => '{locktype,database,relation,page,tuple,virtualxid,transactionid,classid,objid,objsubid,virtualtransaction,pid,mode,granted,fastpath,waitstart}',
prosrc => 'pg_lock_status' },
{ oid => '2561',
descr => 'get array of PIDs of sessions blocking specified backend PID from acquiring a heavyweight lock',
diff --git a/src/include/storage/lock.h b/src/include/storage/lock.h
index 2e6ef174e9..cf312bc55b 100644
--- a/src/include/storage/lock.h
+++ b/src/include/storage/lock.h
@@ -22,6 +22,7 @@
#include "storage/lockdefs.h"
#include "storage/lwlock.h"
#include "storage/shmem.h"
+#include "utils/timestamp.h"
/* struct PGPROC is declared in proc.h, but must forward-reference it */
typedef struct PGPROC PGPROC;
@@ -445,6 +446,7 @@ typedef struct LockInstanceData
LOCKMODE waitLockMode; /* lock awaited by this PGPROC, if any */
BackendId backend; /* backend ID of this PGPROC */
LocalTransactionId lxid; /* local transaction ID of this PGPROC */
+ TimestampTz waitStart; /* time at which this PGPROC started waiting for lock */
int pid; /* pid of this PGPROC */
int leaderPid; /* pid of group leader; = pid if no group */
bool fastpath; /* taken via fastpath? */
diff --git a/src/include/storage/proc.h b/src/include/storage/proc.h
index 683ab64f76..83b5ec3bab 100644
--- a/src/include/storage/proc.h
+++ b/src/include/storage/proc.h
@@ -181,6 +181,7 @@ struct PGPROC
LOCKMODE waitLockMode; /* type of lock we're waiting for */
LOCKMASK heldLocks; /* bitmask for lock types already held on this
* lock object by this backend */
+ TimestampTz waitStart; /* time at which wait for lock acquisition started */
bool delayChkpt; /* true if this proc delays checkpoint start */
diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out
index 6173473de9..5b86c7d5f2 100644
--- a/src/test/regress/expected/rules.out
+++ b/src/test/regress/expected/rules.out
@@ -1394,8 +1394,9 @@ pg_locks| SELECT l.locktype,
l.pid,
l.mode,
l.granted,
- l.fastpath
- FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath);
+ l.fastpath,
+ l.waitstart
+ FROM pg_lock_status() l(locktype, database, relation, page, tuple, virtualxid, transactionid, classid, objid, objsubid, virtualtransaction, pid, mode, granted, fastpath, waitstart);
pg_matviews| SELECT n.nspname AS schemaname,
c.relname AS matviewname,
pg_get_userbyid(c.relowner) AS matviewowner,
--
2.18.1
view thread (27+ messages) latest in thread
Message-ID: <a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com>
Permalink: ../a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com/
Also on: postgresql.org/message-id/a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com
copy link · copy postgr.es · copy git am
reply Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: torikoshia@oss.nttdata.com, masao.fujii@oss.nttdata.com, barwick@gmail.com, robertmhaas@gmail.com, pryzby@telsasoft.com
Subject: Re: adding wait_start column to pg_locks
In-Reply-To: <a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox