From: Fujii Masao <masao.fujii@oss.nttdata.com>
To: torikoshia <torikoshia@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: Wed, 10 Feb 2021 10:43:35 +0900
Message-ID: <337d5311-6113-15e0-bd85-90b47b55f5ae@oss.nttdata.com> (raw)
In-Reply-To: <067d5597e5de82fe47e5716991ab65c4@oss.nttdata.com>
References: <a96013dc51cdc56b2a2b84fa8a16a993@oss.nttdata.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>
<b8425207811a6b99d0ecd76844906a8e@oss.nttdata.com>
<f77120a3-4762-bf71-57d5-f0be081715f7@oss.nttdata.com>
<d45e44d655f2ba06d9e722d3dbcfdd79@oss.nttdata.com>
<990e5d4b-075f-101f-aec5-bb44f9b30550@oss.nttdata.com>
<40dfaa75-1058-e811-1f7c-4cf7203a3068@oss.nttdata.com>
<64102638-7fc3-1941-12f1-e139e3463c03@oss.nttdata.com>
<067d5597e5de82fe47e5716991ab65c4@oss.nttdata.com>
On 2021/02/09 23:31, torikoshia wrote:
> On 2021-02-09 22:54, Fujii Masao wrote:
>> On 2021/02/09 19:11, Fujii Masao wrote:
>>>
>>>
>>> On 2021/02/09 18:13, Fujii Masao wrote:
>>>>
>>>>
>>>> On 2021/02/09 17:48, torikoshia wrote:
>>>>> On 2021-02-05 18:49, Fujii Masao wrote:
>>>>>> On 2021/02/05 0:03, torikoshia wrote:
>>>>>>> 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.
>>>>>>
>>>>>> Thanks for updating the patch!
>>>>>>
>>>>>> + if (pg_atomic_read_u64(&MyProc->waitStart) == 0)
>>>>>> + pg_atomic_write_u64(&MyProc->waitStart,
>>>>>> + pg_atomic_read_u64((pg_atomic_uint64 *) &now));
>>>>>>
>>>>>> pg_atomic_read_u64() is really necessary? I think that
>>>>>> "pg_atomic_write_u64(&MyProc->waitStart, now)" is enough.
>>>>>>
>>>>>> + deadlockStart = get_timeout_start_time(DEADLOCK_TIMEOUT);
>>>>>> + pg_atomic_write_u64(&MyProc->waitStart,
>>>>>> + pg_atomic_read_u64((pg_atomic_uint64 *) &deadlockStart));
>>>>>>
>>>>>> Same as above.
>>>>>>
>>>>>> + /*
>>>>>> + * 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.
>>>>>> + */
>>>>>>
>>>>>> IMO it's better to comment why we reuse the deadlock timeout timer.
>>>>>>
>>>>>> proc->waitStatus = waitStatus;
>>>>>> + pg_atomic_init_u64(&MyProc->waitStart, 0);
>>>>>>
>>>>>> pg_atomic_write_u64() should be used instead? Because waitStart can be
>>>>>> accessed concurrently there.
>>>>>>
>>>>>> I updated the patch and addressed the above review comments. Patch attached.
>>>>>> Barring any objection, I will commit this version.
>>>>>
>>>>> Thanks for modifying the patch!
>>>>> I agree with your comments.
>>>>>
>>>>> BTW, I ran pgbench several times before and after applying
>>>>> this patch.
>>>>>
>>>>> The environment is virtual machine(CentOS 8), so this is
>>>>> just for reference, but there were no significant difference
>>>>> in latency or tps(both are below 1%).
>>>>
>>>> Thanks for the test! I pushed the patch.
>>>
>>> But I reverted the patch because buildfarm members rorqual and
>>> prion don't like the patch. I'm trying to investigate the cause
>>> of this failures.
>>>
>>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=rorqual&dt=2021-02-09%2009%3A20%3A10
>>
>> - relation | locktype | mode
>> ------------------+----------+---------------------
>> - test_prepared_1 | relation | RowExclusiveLock
>> - test_prepared_1 | relation | AccessExclusiveLock
>> -(2 rows)
>> -
>> +ERROR: invalid spinlock number: 0
>>
>> "rorqual" reported that the above error happened in the server built with
>> --disable-atomics --disable-spinlocks when reading pg_locks after
>> the transaction was prepared. The cause of this issue is that "waitStart"
>> atomic variable in the dummy proc created at the end of prepare transaction
>> was not initialized. I updated the patch so that pg_atomic_init_u64() is
>> called for the "waitStart" in the dummy proc for prepared transaction.
>> Patch attached. I confirmed that the patched server built with
>> --disable-atomics --disable-spinlocks passed all the regression tests.
>
> Thanks for fixing the bug, I also tested v9.patch configured with
> --disable-atomics --disable-spinlocks on my environment and confirmed
> that all tests have passed.
Thanks for the test!
I found another bug in the patch. InitProcess() initializes "waitStart",
but previously InitAuxiliaryProcess() did not. This could cause "invalid
spinlock number" error when reading pg_locks in the standby server.
I fixed that. Attached is the updated version of the patch.
Regards,
--
Fujii Masao
Advanced Computing Technology Center
Research and Development Headquarters
NTT DATA CORPORATION
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 ea222c0464..9085d2e64c 100644--- a/doc/src/sgml/catalogs.sgml+++ b/doc/src/sgml/catalogs.sgml@@ -10604,6 +10604,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/access/transam/twophase.c b/src/backend/access/transam/twophase.cindex fc18b77832..70d22577ce 100644--- a/src/backend/access/transam/twophase.c+++ b/src/backend/access/transam/twophase.c@@ -873,8 +873,15 @@ PGPROC *
TwoPhaseGetDummyProc(TransactionId xid, bool lock_held)
{
GlobalTransaction gxact = TwoPhaseGetGXact(xid, lock_held);
+ PGPROC *dummy = &ProcGlobal->allProcs[gxact->pgprocno];- return &ProcGlobal->allProcs[gxact->pgprocno];+ /*+ * Initialize atomic variable in dummy proc so that GetLockStatusData()+ * can read it later.+ */+ pg_atomic_init_u64(&dummy->waitStart, 0);++ return dummy;
}
/************************************************************************/
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.cindex 39a30c00f7..5877a60715 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -540,12 +540,34 @@ void
ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool logging_conflict)
{
TimestampTz ltime;
+ TimestampTz now;
Assert(InHotStandby);
ltime = GetStandbyLimitTime();
+ now = GetCurrentTimestamp();- if (GetCurrentTimestamp() >= ltime && ltime != 0)+ /*+ * Update waitStart if first time through after the startup process+ * started waiting for the lock. It should not be updated every time+ * ResolveRecoveryConflictWithLock() is called during the wait.+ *+ * Use the current time obtained for comparison with ltime as waitStart+ * (i.e., the time when this process started waiting for the lock). Since+ * getting the current time newly can cause overhead, we reuse the+ * already-obtained time to avoid that overhead.+ *+ * Note that waitStart is updated without holding the lock table's+ * partition lock, to avoid the overhead by additional lock acquisition.+ * This can cause "waitstart" in pg_locks to become NULL for a very short+ * period of time after the wait started even though "granted" is false.+ * This is OK in practice because we can assume that users are likely to+ * look at "waitstart" when waiting for the lock for a long time.+ */+ if (pg_atomic_read_u64(&MyProc->waitStart) == 0)+ pg_atomic_write_u64(&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.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..0884909a22 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;
@@ -580,6 +581,7 @@ InitAuxiliaryProcess(void)
MyProc->lwWaitMode = 0;
MyProc->waitLock = NULL;
MyProc->waitProcLock = NULL;
+ pg_atomic_init_u64(&MyProc->waitStart, 0);
#ifdef USE_ASSERT_CHECKING
{
int i;
@@ -1262,6 +1264,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
++ /*+ * Use the current time obtained for the deadlock timeout timer as+ * waitStart (i.e., the time when this process started waiting for the+ * lock). Since getting the current time newly can cause overhead, we+ * reuse the already-obtained time to avoid that overhead.+ *+ * Note that waitStart is updated without holding the lock table's+ * partition lock, to avoid the overhead by additional lock+ * acquisition. This can cause "waitstart" in pg_locks to become NULL+ * for a very short period of time after the wait started even though+ * "granted" is false. This is OK in practice because we can assume+ * that users are likely to look at "waitstart" when waiting for the+ * lock for a long time.+ */+ pg_atomic_write_u64(&MyProc->waitStart,+ get_timeout_start_time(DEADLOCK_TIMEOUT));
}
else if (log_recovery_conflict_waits)
{
@@ -1678,6 +1697,7 @@ ProcWakeup(PGPROC *proc, ProcWaitStatus waitStatus)
proc->waitLock = NULL;
proc->waitProcLock = NULL;
proc->waitStatus = waitStatus;
+ pg_atomic_write_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/catversion.h b/src/include/catalog/catversion.hindex 638830aaac..c1a5dd4ee7 100644--- a/src/include/catalog/catversion.h+++ b/src/include/catalog/catversion.h@@ -53,6 +53,6 @@
*/
/* yyyymmddN */
-#define CATALOG_VERSION_NO 202102021+#define CATALOG_VERSION_NO 202102091
#endif
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.datindex 4e0c9be58c..1487710d59 100644--- a/src/include/catalog/pg_proc.dat+++ b/src/include/catalog/pg_proc.dat@@ -5994,9 +5994,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..9b2a421c32 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,8 @@ 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..a777cb64a1 100644--- a/src/include/storage/proc.h+++ b/src/include/storage/proc.h@@ -181,6 +181,8 @@ 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 b632d9f2ea..10a1f34ebc 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,
Attachments:
[text/plain] v10.patch (12.3K, ../337d5311-6113-15e0-bd85-90b47b55f5ae@oss.nttdata.com/2-v10.patch)
download | inline diff: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 ea222c0464..9085d2e64c 100644--- a/doc/src/sgml/catalogs.sgml+++ b/doc/src/sgml/catalogs.sgml@@ -10604,6 +10604,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/access/transam/twophase.c b/src/backend/access/transam/twophase.cindex fc18b77832..70d22577ce 100644--- a/src/backend/access/transam/twophase.c+++ b/src/backend/access/transam/twophase.c@@ -873,8 +873,15 @@ PGPROC *
TwoPhaseGetDummyProc(TransactionId xid, bool lock_held)
{
GlobalTransaction gxact = TwoPhaseGetGXact(xid, lock_held);
+ PGPROC *dummy = &ProcGlobal->allProcs[gxact->pgprocno];- return &ProcGlobal->allProcs[gxact->pgprocno];+ /*+ * Initialize atomic variable in dummy proc so that GetLockStatusData()+ * can read it later.+ */+ pg_atomic_init_u64(&dummy->waitStart, 0);++ return dummy;
}
/************************************************************************/
diff --git a/src/backend/storage/ipc/standby.c b/src/backend/storage/ipc/standby.cindex 39a30c00f7..5877a60715 100644--- a/src/backend/storage/ipc/standby.c+++ b/src/backend/storage/ipc/standby.c@@ -540,12 +540,34 @@ void
ResolveRecoveryConflictWithLock(LOCKTAG locktag, bool logging_conflict)
{
TimestampTz ltime;
+ TimestampTz now;
Assert(InHotStandby);
ltime = GetStandbyLimitTime();
+ now = GetCurrentTimestamp();- if (GetCurrentTimestamp() >= ltime && ltime != 0)+ /*+ * Update waitStart if first time through after the startup process+ * started waiting for the lock. It should not be updated every time+ * ResolveRecoveryConflictWithLock() is called during the wait.+ *+ * Use the current time obtained for comparison with ltime as waitStart+ * (i.e., the time when this process started waiting for the lock). Since+ * getting the current time newly can cause overhead, we reuse the+ * already-obtained time to avoid that overhead.+ *+ * Note that waitStart is updated without holding the lock table's+ * partition lock, to avoid the overhead by additional lock acquisition.+ * This can cause "waitstart" in pg_locks to become NULL for a very short+ * period of time after the wait started even though "granted" is false.+ * This is OK in practice because we can assume that users are likely to+ * look at "waitstart" when waiting for the lock for a long time.+ */+ if (pg_atomic_read_u64(&MyProc->waitStart) == 0)+ pg_atomic_write_u64(&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.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..0884909a22 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;
@@ -580,6 +581,7 @@ InitAuxiliaryProcess(void)
MyProc->lwWaitMode = 0;
MyProc->waitLock = NULL;
MyProc->waitProcLock = NULL;
+ pg_atomic_init_u64(&MyProc->waitStart, 0);
#ifdef USE_ASSERT_CHECKING
{
int i;
@@ -1262,6 +1264,23 @@ ProcSleep(LOCALLOCK *locallock, LockMethod lockMethodTable)
}
else
enable_timeout_after(DEADLOCK_TIMEOUT, DeadlockTimeout);
++ /*+ * Use the current time obtained for the deadlock timeout timer as+ * waitStart (i.e., the time when this process started waiting for the+ * lock). Since getting the current time newly can cause overhead, we+ * reuse the already-obtained time to avoid that overhead.+ *+ * Note that waitStart is updated without holding the lock table's+ * partition lock, to avoid the overhead by additional lock+ * acquisition. This can cause "waitstart" in pg_locks to become NULL+ * for a very short period of time after the wait started even though+ * "granted" is false. This is OK in practice because we can assume+ * that users are likely to look at "waitstart" when waiting for the+ * lock for a long time.+ */+ pg_atomic_write_u64(&MyProc->waitStart,+ get_timeout_start_time(DEADLOCK_TIMEOUT));
}
else if (log_recovery_conflict_waits)
{
@@ -1678,6 +1697,7 @@ ProcWakeup(PGPROC *proc, ProcWaitStatus waitStatus)
proc->waitLock = NULL;
proc->waitProcLock = NULL;
proc->waitStatus = waitStatus;
+ pg_atomic_write_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/catversion.h b/src/include/catalog/catversion.hindex 638830aaac..c1a5dd4ee7 100644--- a/src/include/catalog/catversion.h+++ b/src/include/catalog/catversion.h@@ -53,6 +53,6 @@
*/
/* yyyymmddN */
-#define CATALOG_VERSION_NO 202102021+#define CATALOG_VERSION_NO 202102091
#endif
diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.datindex 4e0c9be58c..1487710d59 100644--- a/src/include/catalog/pg_proc.dat+++ b/src/include/catalog/pg_proc.dat@@ -5994,9 +5994,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..9b2a421c32 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,8 @@ 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..a777cb64a1 100644--- a/src/include/storage/proc.h+++ b/src/include/storage/proc.h@@ -181,6 +181,8 @@ 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 b632d9f2ea..10a1f34ebc 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,
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: masao.fujii@oss.nttdata.com, torikoshia@oss.nttdata.com, barwick@gmail.com, robertmhaas@gmail.com, pryzby@telsasoft.com
Subject: Re: adding wait_start column to pg_locks
In-Reply-To: <337d5311-6113-15e0-bd85-90b47b55f5ae@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