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, 05 Feb 2021 00:03:51 +0900
Message-ID: <b8425207811a6b99d0ecd76844906a8e@oss.nttdata.com> (raw)
In-Reply-To: <3db333a9-31f7-a225-8038-eeb835ba8f37@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>
<a5bfd1c2f2fb21eb7ea5ddec2e094430@oss.nttdata.com>
<8002219d-b999-12fa-2327-49afe40e5fbb@oss.nttdata.com>
<88c451c7-2729-4329-fbae-6ed7664adea1@oss.nttdata.com>
<f9153182845e5584b954ab6f03514d13@oss.nttdata.com>
<ef0dd522-9096-a60f-a0fa-5f0a0fdbafbd@oss.nttdata.com>
<3db333a9-31f7-a225-8038-eeb835ba8f37@oss.nttdata.com>
On 2021-02-03 11:23, Fujii Masao wrote:
>> 64-bit fetches are not atomic on some platforms. So spinlock is
>> necessary when updating "waitStart" without holding the partition
>> lock? Also GetLockStatusData() needs spinlock when reading
>> "waitStart"?
>
> Also it might be worth thinking to use 64-bit atomic operations like
> pg_atomic_read_u64(), for that.
Thanks for your suggestion and advice!
In the attached patch I used pg_atomic_read_u64() and
pg_atomic_write_u64().
waitStart is TimestampTz i.e., int64, but it seems pg_atomic_read_xxx
and pg_atomic_write_xxx only supports unsigned int, so I cast the type.
I may be using these functions not correctly, so if something is wrong,
I would appreciate any comments.
About the documentation, since your suggestion seems better than v6, I
used it as is.
Regards,
--
Atsushi Torikoshi
Attachments:
[text/x-diff] v7-0001-To-examine-the-duration-of-locks-we-did-join-on-p.patch (11.8K, ../b8425207811a6b99d0ecd76844906a8e@oss.nttdata.com/2-v7-0001-To-examine-the-duration-of-locks-we-did-join-on-p.patch)
download | inline diff:
From 38a3d8996c4b1690cf18cdb1015e270201d34330 Mon Sep 17 00:00:00 2001
From: Atsushi Torikoshi <torikoshia@oss.nttdata.com>
Date: Thu, 4 Feb 2021 23:23:36 +0900
Subject: [PATCH v7] 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 lock duration in this way. This patch adds
a new field "waitstart" preserving lock acquisition wait start time.
Note that updating this field and lock acquisition are not performed
synchronously for performance reasons. Therefore, depending on the
timing, it can happen that waitstart is NULL even though granted is
false.
Author: Atsushi Torikoshi
Reviewed-by: Ian Lawrence Barwick, Robert Haas, Fujii Masao
Discussion: https://postgr.es/m/a96013dc51cdc56b2a2b84fa8a16a993@oss.nttdata.com
modifies
---
contrib/amcheck/expected/check_btree.out | 4 ++--
doc/src/sgml/catalogs.sgml | 13 +++++++++++++
src/backend/storage/ipc/standby.c | 17 +++++++++++++++--
src/backend/storage/lmgr/lock.c | 8 ++++++++
src/backend/storage/lmgr/proc.c | 14 ++++++++++++++
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, 69 insertions(+), 10 deletions(-)
diff --git a/contrib/amcheck/expected/check_btree.out b/contrib/amcheck/expected/check_btree.outindex 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.sgmlindex 865e826fb0..7df4c30a65 100644--- a/doc/src/sgml/catalogs.sgml+++ b/doc/src/sgml/catalogs.sgml@@ -10592,6 +10592,19 @@ 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>+ Time when the server process started waiting for this lock,+ or null if the lock is held.+ Note that this can be null for a very short period of time after+ the wait started even though <structfield>granted</structfield>+ is <literal>false</literal>.+ </para></entry>+ </row>
</tbody>
</tgroup>
</table>
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.cindex 39a30c00f7..1c8135ba74 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -539,13 +539,26 @@ 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)+ /*+ * Record waitStart using the current time obtained for comparison+ * with ltime.+ *+ * It would be ideal this can be synchronously done with updating+ * lock information. Howerver, since it gives performance impacts+ * to hold partitionLock longer time, we do it here asynchronously.+ */+ if (pg_atomic_read_u64(&MyProc->waitStart) == 0)+ pg_atomic_write_u64(&MyProc->waitStart,+ pg_atomic_read_u64((pg_atomic_uint64 *) &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.cindex 79c1cf9b8b..108b4d9023 100644--- a/src/backend/storage/lmgr/lock.c+++ b/src/backend/storage/lmgr/lock.c@@ -3619,6 +3619,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++;
}
@@ -3646,6 +3652,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proc->pid;
instance->fastpath = true;
+ instance->waitStart = 0;
el++;
}
@@ -3698,6 +3705,7 @@ GetLockStatusData(void)
instance->pid = proc->pid;
instance->leaderPid = proclock->groupLeader->pid;
instance->fastpath = false;
+ instance->waitStart = (TimestampTz) pg_atomic_read_u64(&proc->waitStart);
el++;
}
diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.cindex c87ffc6549..dc9212cf89 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;
+ pg_atomic_init_u64(&MyProc->waitStart, 0);
#ifdef USE_ASSERT_CHECKING
{
int i;
@@ -1248,6 +1249,8 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
*/
if (!InHotStandby)
{
+ TimestampTz deadlockStart;+
if (LockTimeout > 0)
{
EnableTimeoutParams timeouts[2];
@@ -1262,6 +1265,16 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
+ /*+ * Record waitStart reusing the deadlock timeout timer.+ *+ * It would be ideal this can be synchronously done with updating+ * lock information. Howerver, since it gives performance impacts+ * to hold partitionLock longer time, we do it here asynchronously.+ */+ deadlockStart = get_timeout_start_time(DEADLOCK_TIMEOUT);+ pg_atomic_write_u64(&MyProc->waitStart,+ pg_atomic_read_u64((pg_atomic_uint64 *) &deadlockStart));
}
else if (log_recovery_conflict_waits)
{
@@ -1678,6 +1691,7 @@ ProcWakeup(PGPROC *proc, ProcWaitStatus waitStatus)
proc->waitLock = NULL;
proc->waitProcLock = NULL;
proc->waitStatus = waitStatus;
+ pg_atomic_init_u64(&MyProc->waitStart, 0);
/* And awaken it */
SetLatch(&proc->procLatch);
diff --git a/src/backend/utils/adt/lockfuncs.c b/src/backend/utils/adt/lockfuncs.cindex 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.datindex f8174061ef..a1a99c9ef4 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.hindex 68a3487d49..846487f94b 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;
@@ -446,6 +447,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.hindex 683ab64f76..21aa5afb14 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 */
+ pg_atomic_uint64 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.outindex 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
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: <b8425207811a6b99d0ecd76844906a8e@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