agora inbox for pgsql-hackers@postgresql.orghelp / color / mirror / Atom feed
[PATCH v7 3/3] Introduce a new track_lock_timing GUC 5+ messages / 2 participants [nested] [flat]
* [PATCH v7 3/3] Introduce a new track_lock_timing GUC @ 2026-02-20 06:13 Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 0 siblings, 0 replies; 5+ messages in thread From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw) A new GUC (track_lock_timing) is added and defaults to on. If on, timed_waits and wait_time counters are incremented if the session waited longer than deadlock_timeout to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb. --- doc/src/sgml/config.sgml | 19 ++ doc/src/sgml/monitoring.sgml | 4 +- src/backend/storage/lmgr/proc.c | 165 ++++++++++-------- src/backend/utils/misc/guc_parameters.dat | 6 + src/backend/utils/misc/postgresql.conf.sample | 1 + src/include/pgstat.h | 1 + src/test/isolation/expected/stats.out | 24 +-- src/test/isolation/expected/stats_1.out | 24 +-- src/test/isolation/specs/stats.spec | 24 +-- 9 files changed, 153 insertions(+), 115 deletions(-) 7.5% doc/src/sgml/ 48.4% src/backend/storage/lmgr/ 35.8% src/test/isolation/expected/ 6.0% src/test/isolation/specs/ diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 20dbcaeb3ee..1e6778576ea 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8841,6 +8841,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; </listitem> </varlistentry> + <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing"> + <term><varname>track_lock_timing</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>track_lock_timing</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + Enables timing of lock waits. This parameter is on by default, as it tracks + only the timings for successful acquisitions that waited longer than + <xref linkend="guc-deadlock-timeout"/>. Lock timing information is + displayed in the <link linkend="monitoring-pg-stat-lock-view"> + <structname>pg_stat_lock</structname></link> view. + Only superusers and users with the appropriate <literal>SET</literal> + privilege can change this setting. + </para> + </listitem> + </varlistentry> + <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing"> <term><varname>track_wal_io_timing</varname> (<type>boolean</type>) <indexterm> diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index cfcb8189418..277275fdcb5 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3193,7 +3193,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Number of times a lock of this type had to wait because of a - conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/> + conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> @@ -3207,7 +3207,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Total time spent waiting for locks of this type, in milliseconds. - Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and + Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index bee4a3c2b89..18e42959e96 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -62,6 +62,7 @@ int IdleInTransactionSessionTimeout = 0; int TransactionTimeout = 0; int IdleSessionTimeout = 0; bool log_lock_waits = true; +bool track_lock_timing = true; /* Pointer to this process's PGPROC struct, if any */ PGPROC *MyProc = NULL; @@ -1545,99 +1546,110 @@ ProcSleep(LOCALLOCK *locallock) /* * If awoken after the deadlock check interrupt has run, and - * log_lock_waits is on, then report about the wait. + * log_lock_waits or track_lock_timing is on, then report or track + * about the wait. */ - if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) + if ((log_lock_waits || track_lock_timing) && + deadlock_state != DS_NOT_YET_CHECKED) { - StringInfoData buf, - lock_waiters_sbuf, - lock_holders_sbuf; - const char *modename; long secs; int usecs; long msecs; - int lockHoldersNum = 0; - initStringInfo(&buf); - initStringInfo(&lock_waiters_sbuf); - initStringInfo(&lock_holders_sbuf); - - DescribeLockTag(&buf, &locallock->tag.lock); - modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, - lockmode); TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT), GetCurrentTimestamp(), &secs, &usecs); msecs = secs * 1000 + usecs / 1000; usecs = usecs % 1000; - /* Gather a list of all lock holders and waiters */ - LWLockAcquire(partitionLock, LW_SHARED); - GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, - &lock_waiters_sbuf, &lockHoldersNum); - LWLockRelease(partitionLock); - - if (deadlock_state == DS_SOFT_DEADLOCK) - ereport(LOG, - (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (deadlock_state == DS_HARD_DEADLOCK) - { - /* - * This message is a bit redundant with the error that will be - * reported subsequently, but in some cases the error report - * might not make it to the log (eg, if it's caught by an - * exception handler), and we want to ensure all long-wait - * events get logged. - */ - ereport(LOG, - (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - } - - if (myWaitStatus == PROC_WAIT_STATUS_WAITING) - ereport(LOG, - (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (myWaitStatus == PROC_WAIT_STATUS_OK) - { - /* Increment the timed lock statistics counters */ + /* Increment the timed lock statistics counters */ + if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK) pgstat_count_lock_timed_wait(locallock->tag.lock.locktag_type, msecs); - ereport(LOG, - (errmsg("process %d acquired %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs))); - } - else + if (log_lock_waits) { - Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); - - /* - * Currently, the deadlock checker always kicks its own - * process, which means that we'll only see - * PROC_WAIT_STATUS_ERROR when deadlock_state == - * DS_HARD_DEADLOCK, and there's no need to print redundant - * messages. But for completeness and future-proofing, print - * a message if it looks like someone else kicked us off the - * lock. - */ - if (deadlock_state != DS_HARD_DEADLOCK) + StringInfoData buf, + lock_waiters_sbuf, + lock_holders_sbuf; + const char *modename; + int lockHoldersNum = 0; + + initStringInfo(&buf); + initStringInfo(&lock_waiters_sbuf); + initStringInfo(&lock_holders_sbuf); + + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + + /* Gather a list of all lock holders and waiters */ + LWLockAcquire(partitionLock, LW_SHARED); + GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, + &lock_waiters_sbuf, &lockHoldersNum); + LWLockRelease(partitionLock); + + if (deadlock_state == DS_SOFT_DEADLOCK) ereport(LOG, - (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", MyProcPid, modename, buf.data, msecs, usecs), (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", "Processes holding the lock: %s. Wait queue: %s.", lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + else if (deadlock_state == DS_HARD_DEADLOCK) + { + /* + * This message is a bit redundant with the error that + * will be reported subsequently, but in some cases the + * error report might not make it to the log (eg, if it's + * caught by an exception handler), and we want to ensure + * all long-wait events get logged. + */ + ereport(LOG, + (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + if (myWaitStatus == PROC_WAIT_STATUS_WAITING) + ereport(LOG, + (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + + else if (myWaitStatus == PROC_WAIT_STATUS_OK) + ereport(LOG, + (errmsg("process %d acquired %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs))); + else + { + Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); + + /* + * Currently, the deadlock checker always kicks its own + * process, which means that we'll only see + * PROC_WAIT_STATUS_ERROR when deadlock_state == + * DS_HARD_DEADLOCK, and there's no need to print + * redundant messages. But for completeness and + * future-proofing, print a message if it looks like + * someone else kicked us off the lock. + */ + if (deadlock_state != DS_HARD_DEADLOCK) + ereport(LOG, + (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + pfree(buf.data); + pfree(lock_holders_sbuf.data); + pfree(lock_waiters_sbuf.data); } /* @@ -1645,14 +1657,13 @@ ProcSleep(LOCALLOCK *locallock) * state so we don't print the above messages again. */ deadlock_state = DS_NO_DEADLOCK; - - pfree(buf.data); - pfree(lock_holders_sbuf.data); - pfree(lock_waiters_sbuf.data); } } while (myWaitStatus == PROC_WAIT_STATUS_WAITING); - /* Count lock waits unconditionally, regardless of log_lock_waits */ + /* + * Count lock waits unconditionally, regardless of log_lock_waits or + * track_lock_timing. + */ pgstat_count_lock_waits(locallock->tag.lock.locktag_type); /* diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index 9507778415d..c21e6c6ea4e 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -3110,6 +3110,12 @@ boot_val => 'false', }, +{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', + short_desc => 'Collects timing statistics for lock acquisition.', + variable => 'track_lock_timing', + boot_val => 'true', +}, + { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', short_desc => 'Collects timing statistics for WAL I/O activity.', variable => 'track_wal_io_timing', diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index f938cc65a3a..8a3a704aaa5 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -685,6 +685,7 @@ #track_counts = on #track_cost_delay_timing = off #track_io_timing = off +#track_lock_timing = on #track_wal_io_timing = off #track_functions = none # none, pl, all #stats_fetch_consistency = cache # cache, none, snapshot diff --git a/src/include/pgstat.h b/src/include/pgstat.h index a4cc006794d..62a9dc1b35e 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -840,6 +840,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void); extern PGDLLIMPORT bool pgstat_track_counts; extern PGDLLIMPORT int pgstat_track_functions; extern PGDLLIMPORT int pgstat_fetch_consistency; +extern PGDLLIMPORT bool track_lock_timing; /* diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out index 86d70a0705c..f9cd78f03b3 100644 --- a/src/test/isolation/expected/stats.out +++ b/src/test/isolation/expected/stats.out @@ -3752,7 +3752,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3765,9 +3765,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3794,7 +3794,7 @@ t |t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3807,9 +3807,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3837,7 +3837,7 @@ t |t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3850,9 +3850,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3899,7 +3899,7 @@ t |t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3912,9 +3912,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out index 4e4c68b4525..955f6ff5ec0 100644 --- a/src/test/isolation/expected/stats_1.out +++ b/src/test/isolation/expected/stats_1.out @@ -3776,7 +3776,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3789,9 +3789,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3818,7 +3818,7 @@ t |t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3831,9 +3831,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3861,7 +3861,7 @@ t |t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3874,9 +3874,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3923,7 +3923,7 @@ t |t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3936,9 +3936,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec index d4b53545198..7c8e2a9214e 100644 --- a/src/test/isolation/specs/stats.spec +++ b/src/test/isolation/specs/stats.spec @@ -132,7 +132,7 @@ step s1_slru_check_stats { # Lock stats steps step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s1_set_log_lock_waits { SET log_lock_waits = on; } +step s1_set_track_lock_timing { SET track_lock_timing = on; } step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); } step s1_sleep { SELECT pg_sleep(0.5); } step s1_lock_relation { LOCK TABLE test_stat_tab; } @@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use', # Lock stats steps step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s2_set_log_lock_waits { SET log_lock_waits = on; } -step s2_unset_log_lock_waits { SET log_lock_waits = off; } +step s2_set_track_lock_timing { SET track_lock_timing = on; } +step s2_unset_track_lock_timing { SET track_lock_timing = off; } step s2_report_stat_lock_relation { SELECT waits > 0, timed_waits = waits, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; } step s2_report_stat_lock_transactionid { SELECT waits > 0, timed_waits = waits, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; } step s2_report_stat_lock_advisory { SELECT waits > 0, timed_waits = waits, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; } @@ -793,9 +793,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin @@ -811,9 +811,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 @@ -830,9 +830,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff @@ -843,14 +843,14 @@ permutation s2_commit s2_report_stat_lock_advisory -# Ensure log_lock_waits behaves correctly +# Ensure track_lock_timing behaves correctly permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_unset_log_lock_waits + s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin -- 2.34.1 --gJ14Jcshhoq1cFBD-- ^ permalink raw reply [nested|flat] 5+ messages in thread
* [PATCH v8 3/3] Introduce a new track_lock_timing GUC @ 2026-02-20 06:13 Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 0 siblings, 0 replies; 5+ messages in thread From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw) A new GUC (track_lock_timing) is added and defaults to on. If on, waits and wait_time counters are incremented if the session waited longer than deadlock_timeout to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb. --- doc/src/sgml/config.sgml | 19 +++ doc/src/sgml/monitoring.sgml | 4 +- src/backend/storage/lmgr/proc.c | 160 +++++++++--------- src/backend/utils/misc/guc_parameters.dat | 6 + src/backend/utils/misc/postgresql.conf.sample | 1 + src/include/pgstat.h | 1 + src/test/isolation/expected/stats.out | 24 +-- src/test/isolation/expected/stats_1.out | 24 +-- src/test/isolation/specs/stats.spec | 24 +-- 9 files changed, 149 insertions(+), 114 deletions(-) 7.6% doc/src/sgml/ 47.7% src/backend/storage/lmgr/ 36.3% src/test/isolation/expected/ 6.1% src/test/isolation/specs/ diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index f670e2d4c31..1d3acb697da 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8842,6 +8842,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; </listitem> </varlistentry> + <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing"> + <term><varname>track_lock_timing</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>track_lock_timing</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + Enables timing of lock waits. This parameter is on by default, as it tracks + only the timings for successful acquisitions that waited longer than + <xref linkend="guc-deadlock-timeout"/>. Lock timing information is + displayed in the <link linkend="monitoring-pg-stat-lock-view"> + <structname>pg_stat_lock</structname></link> view. + Only superusers and users with the appropriate <literal>SET</literal> + privilege can change this setting. + </para> + </listitem> + </varlistentry> + <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing"> <term><varname>track_wal_io_timing</varname> (<type>boolean</type>) <indexterm> diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 3a196bc305c..75c3e036860 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3181,7 +3181,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Number of times a lock of this type had to wait because of a - conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/> + conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> @@ -3195,7 +3195,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Total time spent waiting for locks of this type, in milliseconds. - Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and + Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index e38c8820103..7681f87f078 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -62,6 +62,7 @@ int IdleInTransactionSessionTimeout = 0; int TransactionTimeout = 0; int IdleSessionTimeout = 0; bool log_lock_waits = true; +bool track_lock_timing = true; /* Pointer to this process's PGPROC struct, if any */ PGPROC *MyProc = NULL; @@ -1547,99 +1548,110 @@ ProcSleep(LOCALLOCK *locallock) /* * If awoken after the deadlock check interrupt has run, and - * log_lock_waits is on, then report about the wait. + * log_lock_waits or track_lock_timing is on, then report or track + * about the wait. */ - if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) + if ((log_lock_waits || track_lock_timing) && + deadlock_state != DS_NOT_YET_CHECKED) { - StringInfoData buf, - lock_waiters_sbuf, - lock_holders_sbuf; - const char *modename; long secs; int usecs; long msecs; - int lockHoldersNum = 0; - initStringInfo(&buf); - initStringInfo(&lock_waiters_sbuf); - initStringInfo(&lock_holders_sbuf); - - DescribeLockTag(&buf, &locallock->tag.lock); - modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, - lockmode); TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT), GetCurrentTimestamp(), &secs, &usecs); msecs = secs * 1000 + usecs / 1000; usecs = usecs % 1000; - /* Gather a list of all lock holders and waiters */ - LWLockAcquire(partitionLock, LW_SHARED); - GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, - &lock_waiters_sbuf, &lockHoldersNum); - LWLockRelease(partitionLock); - - if (deadlock_state == DS_SOFT_DEADLOCK) - ereport(LOG, - (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (deadlock_state == DS_HARD_DEADLOCK) - { - /* - * This message is a bit redundant with the error that will be - * reported subsequently, but in some cases the error report - * might not make it to the log (eg, if it's caught by an - * exception handler), and we want to ensure all long-wait - * events get logged. - */ - ereport(LOG, - (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - } - - if (myWaitStatus == PROC_WAIT_STATUS_WAITING) - ereport(LOG, - (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (myWaitStatus == PROC_WAIT_STATUS_OK) - { - /* Increment the lock statistics counters */ + /* Increment the lock statistics counters */ + if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK) pgstat_count_lock_waits(locallock->tag.lock.locktag_type, msecs); - ereport(LOG, - (errmsg("process %d acquired %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs))); - } - else + if (log_lock_waits) { - Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); - - /* - * Currently, the deadlock checker always kicks its own - * process, which means that we'll only see - * PROC_WAIT_STATUS_ERROR when deadlock_state == - * DS_HARD_DEADLOCK, and there's no need to print redundant - * messages. But for completeness and future-proofing, print - * a message if it looks like someone else kicked us off the - * lock. - */ - if (deadlock_state != DS_HARD_DEADLOCK) + StringInfoData buf, + lock_waiters_sbuf, + lock_holders_sbuf; + const char *modename; + int lockHoldersNum = 0; + + initStringInfo(&buf); + initStringInfo(&lock_waiters_sbuf); + initStringInfo(&lock_holders_sbuf); + + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + + /* Gather a list of all lock holders and waiters */ + LWLockAcquire(partitionLock, LW_SHARED); + GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, + &lock_waiters_sbuf, &lockHoldersNum); + LWLockRelease(partitionLock); + + if (deadlock_state == DS_SOFT_DEADLOCK) + ereport(LOG, + (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + else if (deadlock_state == DS_HARD_DEADLOCK) + { + /* + * This message is a bit redundant with the error that + * will be reported subsequently, but in some cases the + * error report might not make it to the log (eg, if it's + * caught by an exception handler), and we want to ensure + * all long-wait events get logged. + */ ereport(LOG, - (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", MyProcPid, modename, buf.data, msecs, usecs), (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", "Processes holding the lock: %s. Wait queue: %s.", lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + if (myWaitStatus == PROC_WAIT_STATUS_WAITING) + ereport(LOG, + (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + + else if (myWaitStatus == PROC_WAIT_STATUS_OK) + ereport(LOG, + (errmsg("process %d acquired %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs))); + else + { + Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); + + /* + * Currently, the deadlock checker always kicks its own + * process, which means that we'll only see + * PROC_WAIT_STATUS_ERROR when deadlock_state == + * DS_HARD_DEADLOCK, and there's no need to print + * redundant messages. But for completeness and + * future-proofing, print a message if it looks like + * someone else kicked us off the lock. + */ + if (deadlock_state != DS_HARD_DEADLOCK) + ereport(LOG, + (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + pfree(buf.data); + pfree(lock_holders_sbuf.data); + pfree(lock_waiters_sbuf.data); } /* @@ -1647,10 +1659,6 @@ ProcSleep(LOCALLOCK *locallock) * state so we don't print the above messages again. */ deadlock_state = DS_NO_DEADLOCK; - - pfree(buf.data); - pfree(lock_holders_sbuf.data); - pfree(lock_waiters_sbuf.data); } } while (myWaitStatus == PROC_WAIT_STATUS_WAITING); diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index 9507778415d..c21e6c6ea4e 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -3110,6 +3110,12 @@ boot_val => 'false', }, +{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', + short_desc => 'Collects timing statistics for lock acquisition.', + variable => 'track_lock_timing', + boot_val => 'true', +}, + { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', short_desc => 'Collects timing statistics for WAL I/O activity.', variable => 'track_wal_io_timing', diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index f938cc65a3a..8a3a704aaa5 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -685,6 +685,7 @@ #track_counts = on #track_cost_delay_timing = off #track_io_timing = off +#track_lock_timing = on #track_wal_io_timing = off #track_functions = none # none, pl, all #stats_fetch_consistency = cache # cache, none, snapshot diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 1c261e2c7a8..1ba7d98d06b 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -843,6 +843,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void); extern PGDLLIMPORT bool pgstat_track_counts; extern PGDLLIMPORT int pgstat_track_functions; extern PGDLLIMPORT int pgstat_fetch_consistency; +extern PGDLLIMPORT bool track_lock_timing; /* diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out index 3cae3052e40..4f7ad061549 100644 --- a/src/test/isolation/expected/stats.out +++ b/src/test/isolation/expected/stats.out @@ -3752,7 +3752,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3765,9 +3765,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3794,7 +3794,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3807,9 +3807,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3837,7 +3837,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3850,9 +3850,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3899,7 +3899,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3912,9 +3912,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out index ea4fd97a9a5..e1a60d41bad 100644 --- a/src/test/isolation/expected/stats_1.out +++ b/src/test/isolation/expected/stats_1.out @@ -3776,7 +3776,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3789,9 +3789,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3818,7 +3818,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3831,9 +3831,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3861,7 +3861,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3874,9 +3874,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3923,7 +3923,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3936,9 +3936,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec index 42be68c545f..81b45a801d9 100644 --- a/src/test/isolation/specs/stats.spec +++ b/src/test/isolation/specs/stats.spec @@ -132,7 +132,7 @@ step s1_slru_check_stats { # Lock stats steps step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s1_set_log_lock_waits { SET log_lock_waits = on; } +step s1_set_track_lock_timing { SET track_lock_timing = on; } step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); } step s1_sleep { SELECT pg_sleep(0.5); } step s1_lock_relation { LOCK TABLE test_stat_tab; } @@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use', # Lock stats steps step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s2_set_log_lock_waits { SET log_lock_waits = on; } -step s2_unset_log_lock_waits { SET log_lock_waits = off; } +step s2_set_track_lock_timing { SET track_lock_timing = on; } +step s2_unset_track_lock_timing { SET track_lock_timing = off; } step s2_report_stat_lock_relation { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; } step s2_report_stat_lock_transactionid { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; } step s2_report_stat_lock_advisory { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; } @@ -793,9 +793,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin @@ -811,9 +811,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 @@ -830,9 +830,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff @@ -843,14 +843,14 @@ permutation s2_commit s2_report_stat_lock_advisory -# Ensure log_lock_waits behaves correctly +# Ensure track_lock_timing behaves correctly permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_unset_log_lock_waits + s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin -- 2.34.1 --CwwtKyeZcJiDzEBE-- ^ permalink raw reply [nested|flat] 5+ messages in thread
* [PATCH v8 3/3] Introduce a new track_lock_timing GUC @ 2026-02-20 06:13 Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 0 siblings, 0 replies; 5+ messages in thread From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw) A new GUC (track_lock_timing) is added and defaults to on. If on, waits and wait_time counters are incremented if the session waited longer than deadlock_timeout to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb. --- doc/src/sgml/config.sgml | 19 +++ doc/src/sgml/monitoring.sgml | 4 +- src/backend/storage/lmgr/proc.c | 160 +++++++++--------- src/backend/utils/misc/guc_parameters.dat | 6 + src/backend/utils/misc/postgresql.conf.sample | 1 + src/include/pgstat.h | 1 + src/test/isolation/expected/stats.out | 24 +-- src/test/isolation/expected/stats_1.out | 24 +-- src/test/isolation/specs/stats.spec | 24 +-- 9 files changed, 149 insertions(+), 114 deletions(-) 7.6% doc/src/sgml/ 47.7% src/backend/storage/lmgr/ 36.3% src/test/isolation/expected/ 6.1% src/test/isolation/specs/ diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index f670e2d4c31..1d3acb697da 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8842,6 +8842,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; </listitem> </varlistentry> + <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing"> + <term><varname>track_lock_timing</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>track_lock_timing</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + Enables timing of lock waits. This parameter is on by default, as it tracks + only the timings for successful acquisitions that waited longer than + <xref linkend="guc-deadlock-timeout"/>. Lock timing information is + displayed in the <link linkend="monitoring-pg-stat-lock-view"> + <structname>pg_stat_lock</structname></link> view. + Only superusers and users with the appropriate <literal>SET</literal> + privilege can change this setting. + </para> + </listitem> + </varlistentry> + <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing"> <term><varname>track_wal_io_timing</varname> (<type>boolean</type>) <indexterm> diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 3a196bc305c..75c3e036860 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3181,7 +3181,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Number of times a lock of this type had to wait because of a - conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/> + conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> @@ -3195,7 +3195,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Total time spent waiting for locks of this type, in milliseconds. - Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and + Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index e38c8820103..7681f87f078 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -62,6 +62,7 @@ int IdleInTransactionSessionTimeout = 0; int TransactionTimeout = 0; int IdleSessionTimeout = 0; bool log_lock_waits = true; +bool track_lock_timing = true; /* Pointer to this process's PGPROC struct, if any */ PGPROC *MyProc = NULL; @@ -1547,99 +1548,110 @@ ProcSleep(LOCALLOCK *locallock) /* * If awoken after the deadlock check interrupt has run, and - * log_lock_waits is on, then report about the wait. + * log_lock_waits or track_lock_timing is on, then report or track + * about the wait. */ - if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) + if ((log_lock_waits || track_lock_timing) && + deadlock_state != DS_NOT_YET_CHECKED) { - StringInfoData buf, - lock_waiters_sbuf, - lock_holders_sbuf; - const char *modename; long secs; int usecs; long msecs; - int lockHoldersNum = 0; - initStringInfo(&buf); - initStringInfo(&lock_waiters_sbuf); - initStringInfo(&lock_holders_sbuf); - - DescribeLockTag(&buf, &locallock->tag.lock); - modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, - lockmode); TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT), GetCurrentTimestamp(), &secs, &usecs); msecs = secs * 1000 + usecs / 1000; usecs = usecs % 1000; - /* Gather a list of all lock holders and waiters */ - LWLockAcquire(partitionLock, LW_SHARED); - GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, - &lock_waiters_sbuf, &lockHoldersNum); - LWLockRelease(partitionLock); - - if (deadlock_state == DS_SOFT_DEADLOCK) - ereport(LOG, - (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (deadlock_state == DS_HARD_DEADLOCK) - { - /* - * This message is a bit redundant with the error that will be - * reported subsequently, but in some cases the error report - * might not make it to the log (eg, if it's caught by an - * exception handler), and we want to ensure all long-wait - * events get logged. - */ - ereport(LOG, - (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - } - - if (myWaitStatus == PROC_WAIT_STATUS_WAITING) - ereport(LOG, - (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (myWaitStatus == PROC_WAIT_STATUS_OK) - { - /* Increment the lock statistics counters */ + /* Increment the lock statistics counters */ + if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK) pgstat_count_lock_waits(locallock->tag.lock.locktag_type, msecs); - ereport(LOG, - (errmsg("process %d acquired %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs))); - } - else + if (log_lock_waits) { - Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); - - /* - * Currently, the deadlock checker always kicks its own - * process, which means that we'll only see - * PROC_WAIT_STATUS_ERROR when deadlock_state == - * DS_HARD_DEADLOCK, and there's no need to print redundant - * messages. But for completeness and future-proofing, print - * a message if it looks like someone else kicked us off the - * lock. - */ - if (deadlock_state != DS_HARD_DEADLOCK) + StringInfoData buf, + lock_waiters_sbuf, + lock_holders_sbuf; + const char *modename; + int lockHoldersNum = 0; + + initStringInfo(&buf); + initStringInfo(&lock_waiters_sbuf); + initStringInfo(&lock_holders_sbuf); + + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + + /* Gather a list of all lock holders and waiters */ + LWLockAcquire(partitionLock, LW_SHARED); + GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, + &lock_waiters_sbuf, &lockHoldersNum); + LWLockRelease(partitionLock); + + if (deadlock_state == DS_SOFT_DEADLOCK) + ereport(LOG, + (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + else if (deadlock_state == DS_HARD_DEADLOCK) + { + /* + * This message is a bit redundant with the error that + * will be reported subsequently, but in some cases the + * error report might not make it to the log (eg, if it's + * caught by an exception handler), and we want to ensure + * all long-wait events get logged. + */ ereport(LOG, - (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", MyProcPid, modename, buf.data, msecs, usecs), (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", "Processes holding the lock: %s. Wait queue: %s.", lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + if (myWaitStatus == PROC_WAIT_STATUS_WAITING) + ereport(LOG, + (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + + else if (myWaitStatus == PROC_WAIT_STATUS_OK) + ereport(LOG, + (errmsg("process %d acquired %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs))); + else + { + Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); + + /* + * Currently, the deadlock checker always kicks its own + * process, which means that we'll only see + * PROC_WAIT_STATUS_ERROR when deadlock_state == + * DS_HARD_DEADLOCK, and there's no need to print + * redundant messages. But for completeness and + * future-proofing, print a message if it looks like + * someone else kicked us off the lock. + */ + if (deadlock_state != DS_HARD_DEADLOCK) + ereport(LOG, + (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + pfree(buf.data); + pfree(lock_holders_sbuf.data); + pfree(lock_waiters_sbuf.data); } /* @@ -1647,10 +1659,6 @@ ProcSleep(LOCALLOCK *locallock) * state so we don't print the above messages again. */ deadlock_state = DS_NO_DEADLOCK; - - pfree(buf.data); - pfree(lock_holders_sbuf.data); - pfree(lock_waiters_sbuf.data); } } while (myWaitStatus == PROC_WAIT_STATUS_WAITING); diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index 9507778415d..c21e6c6ea4e 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -3110,6 +3110,12 @@ boot_val => 'false', }, +{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', + short_desc => 'Collects timing statistics for lock acquisition.', + variable => 'track_lock_timing', + boot_val => 'true', +}, + { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', short_desc => 'Collects timing statistics for WAL I/O activity.', variable => 'track_wal_io_timing', diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index f938cc65a3a..8a3a704aaa5 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -685,6 +685,7 @@ #track_counts = on #track_cost_delay_timing = off #track_io_timing = off +#track_lock_timing = on #track_wal_io_timing = off #track_functions = none # none, pl, all #stats_fetch_consistency = cache # cache, none, snapshot diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 1c261e2c7a8..1ba7d98d06b 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -843,6 +843,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void); extern PGDLLIMPORT bool pgstat_track_counts; extern PGDLLIMPORT int pgstat_track_functions; extern PGDLLIMPORT int pgstat_fetch_consistency; +extern PGDLLIMPORT bool track_lock_timing; /* diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out index 3cae3052e40..4f7ad061549 100644 --- a/src/test/isolation/expected/stats.out +++ b/src/test/isolation/expected/stats.out @@ -3752,7 +3752,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3765,9 +3765,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3794,7 +3794,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3807,9 +3807,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3837,7 +3837,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3850,9 +3850,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3899,7 +3899,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3912,9 +3912,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out index ea4fd97a9a5..e1a60d41bad 100644 --- a/src/test/isolation/expected/stats_1.out +++ b/src/test/isolation/expected/stats_1.out @@ -3776,7 +3776,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3789,9 +3789,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3818,7 +3818,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3831,9 +3831,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3861,7 +3861,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3874,9 +3874,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3923,7 +3923,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3936,9 +3936,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec index 42be68c545f..81b45a801d9 100644 --- a/src/test/isolation/specs/stats.spec +++ b/src/test/isolation/specs/stats.spec @@ -132,7 +132,7 @@ step s1_slru_check_stats { # Lock stats steps step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s1_set_log_lock_waits { SET log_lock_waits = on; } +step s1_set_track_lock_timing { SET track_lock_timing = on; } step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); } step s1_sleep { SELECT pg_sleep(0.5); } step s1_lock_relation { LOCK TABLE test_stat_tab; } @@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use', # Lock stats steps step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s2_set_log_lock_waits { SET log_lock_waits = on; } -step s2_unset_log_lock_waits { SET log_lock_waits = off; } +step s2_set_track_lock_timing { SET track_lock_timing = on; } +step s2_unset_track_lock_timing { SET track_lock_timing = off; } step s2_report_stat_lock_relation { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; } step s2_report_stat_lock_transactionid { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; } step s2_report_stat_lock_advisory { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; } @@ -793,9 +793,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin @@ -811,9 +811,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 @@ -830,9 +830,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff @@ -843,14 +843,14 @@ permutation s2_commit s2_report_stat_lock_advisory -# Ensure log_lock_waits behaves correctly +# Ensure track_lock_timing behaves correctly permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_unset_log_lock_waits + s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin -- 2.34.1 --CwwtKyeZcJiDzEBE-- ^ permalink raw reply [nested|flat] 5+ messages in thread
* [PATCH v9 3/3] Introduce a new track_lock_timing GUC @ 2026-02-20 06:13 Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 0 siblings, 0 replies; 5+ messages in thread From: Bertrand Drouvot @ 2026-02-20 06:13 UTC (permalink / raw) A new GUC (track_lock_timing) is added and defaults to on. If on, waits and wait_time counters are incremented if the session waited longer than deadlock_timeout to acquire the lock. It's on by default, as this is the same idea as 2aac62be8cb. --- doc/src/sgml/config.sgml | 19 ++ doc/src/sgml/monitoring.sgml | 4 +- src/backend/storage/lmgr/proc.c | 185 +++++++++--------- src/backend/utils/misc/guc_parameters.dat | 6 + src/backend/utils/misc/postgresql.conf.sample | 1 + src/include/pgstat.h | 1 + src/test/isolation/expected/stats.out | 24 +-- src/test/isolation/expected/stats_1.out | 24 +-- src/test/isolation/specs/stats.spec | 24 +-- 9 files changed, 161 insertions(+), 127 deletions(-) 7.3% doc/src/sgml/ 50.0% src/backend/storage/lmgr/ 34.7% src/test/isolation/expected/ 5.8% src/test/isolation/specs/ diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 8cdd826fbd3..69938ba3cdc 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -8857,6 +8857,25 @@ COPY postgres_log FROM '/full/path/to/logfile.csv' WITH csv; </listitem> </varlistentry> + <varlistentry id="guc-track-lock-timing" xreflabel="track_lock_timing"> + <term><varname>track_lock_timing</varname> (<type>boolean</type>) + <indexterm> + <primary><varname>track_lock_timing</varname> configuration parameter</primary> + </indexterm> + </term> + <listitem> + <para> + Enables timing of lock waits. This parameter is on by default, as it tracks + only the timings for successful acquisitions that waited longer than + <xref linkend="guc-deadlock-timeout"/>. Lock timing information is + displayed in the <link linkend="monitoring-pg-stat-lock-view"> + <structname>pg_stat_lock</structname></link> view. + Only superusers and users with the appropriate <literal>SET</literal> + privilege can change this setting. + </para> + </listitem> + </varlistentry> + <varlistentry id="guc-track-wal-io-timing" xreflabel="track_wal_io_timing"> <term><varname>track_wal_io_timing</varname> (<type>boolean</type>) <indexterm> diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index 221ee28cc7b..6ae9cc7635d 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3340,7 +3340,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Number of times a lock of this type had to wait because of a - conflicting lock. Only incremented when <xref linkend="guc-log-lock-waits"/> + conflicting lock. Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> @@ -3354,7 +3354,7 @@ description | Waiting for a newly initialized WAL file to reach durable storage </para> <para> Total time spent waiting for locks of this type, in milliseconds. - Only incremented when <xref linkend="guc-log-lock-waits"/> is enabled and + Only incremented when <xref linkend="guc-track-lock-timing"/> is enabled and the lock was successfully acquired after waiting longer than <xref linkend="guc-deadlock-timeout"/>. </para> diff --git a/src/backend/storage/lmgr/proc.c b/src/backend/storage/lmgr/proc.c index 263dc88b735..e9b7b5fd4c9 100644 --- a/src/backend/storage/lmgr/proc.c +++ b/src/backend/storage/lmgr/proc.c @@ -63,6 +63,7 @@ int IdleInTransactionSessionTimeout = 0; int TransactionTimeout = 0; int IdleSessionTimeout = 0; bool log_lock_waits = true; +bool track_lock_timing = true; /* Pointer to this process's PGPROC struct, if any */ PGPROC *MyProc = NULL; @@ -1550,115 +1551,125 @@ ProcSleep(LOCALLOCK *locallock) /* * If awoken after the deadlock check interrupt has run, and - * log_lock_waits is on, then report about the wait. + * log_lock_waits or track_lock_timing is on, then report or track + * about the wait. */ - if (log_lock_waits && deadlock_state != DS_NOT_YET_CHECKED) + if ((log_lock_waits || track_lock_timing) && + deadlock_state != DS_NOT_YET_CHECKED) { - StringInfoData buf, - lock_waiters_sbuf, - lock_holders_sbuf; - const char *modename; long secs; int usecs; long msecs; - int lockHoldersNum = 0; - initStringInfo(&buf); - initStringInfo(&lock_waiters_sbuf); - initStringInfo(&lock_holders_sbuf); - - DescribeLockTag(&buf, &locallock->tag.lock); - modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, - lockmode); TimestampDifference(get_timeout_start_time(DEADLOCK_TIMEOUT), GetCurrentTimestamp(), &secs, &usecs); msecs = secs * 1000 + usecs / 1000; usecs = usecs % 1000; - /* Gather a list of all lock holders and waiters */ - LWLockAcquire(partitionLock, LW_SHARED); - GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, - &lock_waiters_sbuf, &lockHoldersNum); - LWLockRelease(partitionLock); - - if (deadlock_state == DS_SOFT_DEADLOCK) - ereport(LOG, - (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - else if (deadlock_state == DS_HARD_DEADLOCK) - { - /* - * This message is a bit redundant with the error that will be - * reported subsequently, but in some cases the error report - * might not make it to the log (eg, if it's caught by an - * exception handler), and we want to ensure all long-wait - * events get logged. - */ - ereport(LOG, - (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs), - (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", - "Processes holding the lock: %s. Wait queue: %s.", - lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - } + /* Increment the lock statistics counters */ + if (track_lock_timing && myWaitStatus == PROC_WAIT_STATUS_OK) + pgstat_count_lock_waits(locallock->tag.lock.locktag_type, msecs); - if (myWaitStatus == PROC_WAIT_STATUS_WAITING) + if (log_lock_waits) { - /* - * Guard the "still waiting on lock" log message so it is - * reported at most once while waiting for the lock. - * - * Without this guard, the message can be emitted whenever the - * lock-wait sleep is interrupted (for example by SIGHUP for - * config reload or by client_connection_check_interval). For - * example, if client_connection_check_interval is set very - * low (e.g., 100 ms), the message could be logged repeatedly, - * flooding the log and making it difficult to use. - */ - if (!logged_lock_wait) - { + StringInfoData buf, + lock_waiters_sbuf, + lock_holders_sbuf; + const char *modename; + int lockHoldersNum = 0; + + initStringInfo(&buf); + initStringInfo(&lock_waiters_sbuf); + initStringInfo(&lock_holders_sbuf); + + DescribeLockTag(&buf, &locallock->tag.lock); + modename = GetLockmodeName(locallock->tag.lock.locktag_lockmethodid, + lockmode); + + /* Gather a list of all lock holders and waiters */ + LWLockAcquire(partitionLock, LW_SHARED); + GetLockHoldersAndWaiters(locallock, &lock_holders_sbuf, + &lock_waiters_sbuf, &lockHoldersNum); + LWLockRelease(partitionLock); + + if (deadlock_state == DS_SOFT_DEADLOCK) ereport(LOG, - (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", + (errmsg("process %d avoided deadlock for %s on %s by rearranging queue order after %ld.%03d ms", MyProcPid, modename, buf.data, msecs, usecs), (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", "Processes holding the lock: %s. Wait queue: %s.", lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); - logged_lock_wait = true; - } - } - else if (myWaitStatus == PROC_WAIT_STATUS_OK) - { - /* Increment the lock statistics counters */ - pgstat_count_lock_waits(locallock->tag.lock.locktag_type, msecs); - - ereport(LOG, - (errmsg("process %d acquired %s on %s after %ld.%03d ms", - MyProcPid, modename, buf.data, msecs, usecs))); - } - else - { - Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); - - /* - * Currently, the deadlock checker always kicks its own - * process, which means that we'll only see - * PROC_WAIT_STATUS_ERROR when deadlock_state == - * DS_HARD_DEADLOCK, and there's no need to print redundant - * messages. But for completeness and future-proofing, print - * a message if it looks like someone else kicked us off the - * lock. - */ - if (deadlock_state != DS_HARD_DEADLOCK) + else if (deadlock_state == DS_HARD_DEADLOCK) + { + /* + * This message is a bit redundant with the error that + * will be reported subsequently, but in some cases the + * error report might not make it to the log (eg, if it's + * caught by an exception handler), and we want to ensure + * all long-wait events get logged. + */ ereport(LOG, - (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + (errmsg("process %d detected deadlock while waiting for %s on %s after %ld.%03d ms", MyProcPid, modename, buf.data, msecs, usecs), (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", "Processes holding the lock: %s. Wait queue: %s.", lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + if (myWaitStatus == PROC_WAIT_STATUS_WAITING) + { + /* + * Guard the "still waiting on lock" log message so it is + * reported at most once while waiting for the lock. + * + * Without this guard, the message can be emitted whenever + * the lock-wait sleep is interrupted (for example by + * SIGHUP for config reload or by + * client_connection_check_interval). For example, if + * client_connection_check_interval is set very low (e.g., + * 100 ms), the message could be logged repeatedly, + * flooding the log and making it difficult to use. + */ + if (!logged_lock_wait) + { + ereport(LOG, + (errmsg("process %d still waiting for %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + logged_lock_wait = true; + } + } + else if (myWaitStatus == PROC_WAIT_STATUS_OK) + ereport(LOG, + (errmsg("process %d acquired %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs))); + else + { + Assert(myWaitStatus == PROC_WAIT_STATUS_ERROR); + + /* + * Currently, the deadlock checker always kicks its own + * process, which means that we'll only see + * PROC_WAIT_STATUS_ERROR when deadlock_state == + * DS_HARD_DEADLOCK, and there's no need to print + * redundant messages. But for completeness and + * future-proofing, print a message if it looks like + * someone else kicked us off the lock. + */ + if (deadlock_state != DS_HARD_DEADLOCK) + ereport(LOG, + (errmsg("process %d failed to acquire %s on %s after %ld.%03d ms", + MyProcPid, modename, buf.data, msecs, usecs), + (errdetail_log_plural("Process holding the lock: %s. Wait queue: %s.", + "Processes holding the lock: %s. Wait queue: %s.", + lockHoldersNum, lock_holders_sbuf.data, lock_waiters_sbuf.data)))); + } + + pfree(buf.data); + pfree(lock_holders_sbuf.data); + pfree(lock_waiters_sbuf.data); } /* @@ -1666,10 +1677,6 @@ ProcSleep(LOCALLOCK *locallock) * state so we don't print the above messages again. */ deadlock_state = DS_NO_DEADLOCK; - - pfree(buf.data); - pfree(lock_holders_sbuf.data); - pfree(lock_waiters_sbuf.data); } } while (myWaitStatus == PROC_WAIT_STATUS_WAITING); diff --git a/src/backend/utils/misc/guc_parameters.dat b/src/backend/utils/misc/guc_parameters.dat index a5a0edf2534..7055dc88e0d 100644 --- a/src/backend/utils/misc/guc_parameters.dat +++ b/src/backend/utils/misc/guc_parameters.dat @@ -3110,6 +3110,12 @@ boot_val => 'false', }, +{ name => 'track_lock_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', + short_desc => 'Collects timing statistics for lock acquisition.', + variable => 'track_lock_timing', + boot_val => 'true', +}, + { name => 'track_wal_io_timing', type => 'bool', context => 'PGC_SUSET', group => 'STATS_CUMULATIVE', short_desc => 'Collects timing statistics for WAL I/O activity.', variable => 'track_wal_io_timing', diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index e686d88afc4..5d057608fe1 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -685,6 +685,7 @@ #track_counts = on #track_cost_delay_timing = off #track_io_timing = off +#track_lock_timing = on #track_wal_io_timing = off #track_functions = none # none, pl, all #stats_fetch_consistency = cache # cache, none, snapshot diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 06e2638e788..95006dc139c 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -842,6 +842,7 @@ extern PgStat_WalStats *pgstat_fetch_stat_wal(void); extern PGDLLIMPORT bool pgstat_track_counts; extern PGDLLIMPORT int pgstat_track_functions; extern PGDLLIMPORT int pgstat_fetch_consistency; +extern PGDLLIMPORT bool track_lock_timing; /* diff --git a/src/test/isolation/expected/stats.out b/src/test/isolation/expected/stats.out index 3cae3052e40..4f7ad061549 100644 --- a/src/test/isolation/expected/stats.out +++ b/src/test/isolation/expected/stats.out @@ -3752,7 +3752,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3765,9 +3765,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3794,7 +3794,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3807,9 +3807,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3837,7 +3837,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3850,9 +3850,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3899,7 +3899,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3912,9 +3912,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/expected/stats_1.out b/src/test/isolation/expected/stats_1.out index ea4fd97a9a5..e1a60d41bad 100644 --- a/src/test/isolation/expected/stats_1.out +++ b/src/test/isolation/expected/stats_1.out @@ -3776,7 +3776,7 @@ test_stat_func| 1|t |t step s1_commit: COMMIT; -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3789,9 +3789,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; @@ -3818,7 +3818,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 s2_begin s2_ff s2_table_update_k1 s1_sleep s1_commit s2_commit s2_report_stat_lock_transactionid pg_stat_force_next_flush ------------------------ @@ -3831,9 +3831,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_table_insert: INSERT INTO test_stat_tab(key, value) VALUES('k1', 1), ('k2', 1), ('k3', 1); step s1_begin: BEGIN; step s1_table_update_k1: UPDATE test_stat_tab SET value = value + 1 WHERE key = 'k1'; @@ -3861,7 +3861,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_set_log_lock_waits s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff s2_lock_advisory_lock s1_sleep s1_lock_advisory_unlock s2_lock_advisory_unlock s2_commit s2_report_stat_lock_advisory pg_stat_force_next_flush ------------------------ @@ -3874,9 +3874,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_set_log_lock_waits: SET log_lock_waits = on; +step s2_set_track_lock_timing: SET track_lock_timing = on; step s1_lock_advisory_lock: SELECT pg_advisory_lock(1); pg_advisory_lock ---------------- @@ -3923,7 +3923,7 @@ t |t (1 row) -starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_log_lock_waits s2_set_deadlock_timeout s2_unset_log_lock_waits s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation +starting permutation: s1_set_deadlock_timeout s1_reset_stat_lock s1_set_track_lock_timing s2_set_deadlock_timeout s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin s2_ff s2_lock_relation s1_sleep s1_commit s2_commit s2_report_stat_lock_relation pg_stat_force_next_flush ------------------------ @@ -3936,9 +3936,9 @@ pg_stat_reset_shared (1 row) -step s1_set_log_lock_waits: SET log_lock_waits = on; +step s1_set_track_lock_timing: SET track_lock_timing = on; step s2_set_deadlock_timeout: SET deadlock_timeout = '10ms'; -step s2_unset_log_lock_waits: SET log_lock_waits = off; +step s2_unset_track_lock_timing: SET track_lock_timing = off; step s1_begin: BEGIN; step s1_lock_relation: LOCK TABLE test_stat_tab; step s2_begin: BEGIN; diff --git a/src/test/isolation/specs/stats.spec b/src/test/isolation/specs/stats.spec index 42be68c545f..81b45a801d9 100644 --- a/src/test/isolation/specs/stats.spec +++ b/src/test/isolation/specs/stats.spec @@ -132,7 +132,7 @@ step s1_slru_check_stats { # Lock stats steps step s1_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s1_set_log_lock_waits { SET log_lock_waits = on; } +step s1_set_track_lock_timing { SET track_lock_timing = on; } step s1_reset_stat_lock { SELECT pg_stat_reset_shared('lock'); } step s1_sleep { SELECT pg_sleep(0.5); } step s1_lock_relation { LOCK TABLE test_stat_tab; } @@ -174,8 +174,8 @@ step s2_big_notify { SELECT pg_notify('stats_test_use', # Lock stats steps step s2_set_deadlock_timeout { SET deadlock_timeout = '10ms'; } -step s2_set_log_lock_waits { SET log_lock_waits = on; } -step s2_unset_log_lock_waits { SET log_lock_waits = off; } +step s2_set_track_lock_timing { SET track_lock_timing = on; } +step s2_unset_track_lock_timing { SET track_lock_timing = off; } step s2_report_stat_lock_relation { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'relation'; } step s2_report_stat_lock_transactionid { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'transactionid'; } step s2_report_stat_lock_advisory { SELECT waits > 0, wait_time > 500 FROM pg_stat_lock WHERE locktype = 'advisory'; } @@ -793,9 +793,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_begin s1_lock_relation s2_begin @@ -811,9 +811,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_table_insert s1_begin s1_table_update_k1 @@ -830,9 +830,9 @@ permutation permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_set_log_lock_waits + s2_set_track_lock_timing s1_lock_advisory_lock s2_begin s2_ff @@ -843,14 +843,14 @@ permutation s2_commit s2_report_stat_lock_advisory -# Ensure log_lock_waits behaves correctly +# Ensure track_lock_timing behaves correctly permutation s1_set_deadlock_timeout s1_reset_stat_lock - s1_set_log_lock_waits + s1_set_track_lock_timing s2_set_deadlock_timeout - s2_unset_log_lock_waits + s2_unset_track_lock_timing s1_begin s1_lock_relation s2_begin -- 2.34.1 --nK2xgkLTeiiswcxd-- ^ permalink raw reply [nested|flat] 5+ messages in thread
* [PATCH v48 2/7] Give 'options' parameter to table_delete/table_update @ 2026-03-30 11:27 Álvaro Herrera <alvherre@kurilemu.de> 0 siblings, 0 replies; 5+ messages in thread From: Álvaro Herrera @ 2026-03-30 11:27 UTC (permalink / raw) The table_insert() method already has an equivalent argument, so this makes sense just on consistency grounds, for future growth. table_delete() can immediately use it to carry the 'changingPart' boolean (which is arguably misplaced in the current API); for table_update we don't have any options at present, but an upcoming patch would add one. Discussion: https://postgr.es/m/202603171606.kf6pmhscqbqz@alvherre.pgsql --- src/backend/access/heap/heapam.c | 16 ++++++++++------ src/backend/access/heap/heapam_handler.c | 13 ++++++++----- src/backend/access/table/tableam.c | 6 +++--- src/backend/executor/nodeModifyTable.c | 9 +++++++-- src/include/access/heapam.h | 7 ++++--- src/include/access/tableam.h | 23 +++++++++++++++-------- 6 files changed, 47 insertions(+), 27 deletions(-) diff --git a/src/backend/access/heap/heapam.c b/src/backend/access/heap/heapam.c index d34136d2e94..0645b2d5f58 100644 --- a/src/backend/access/heap/heapam.c +++ b/src/backend/access/heap/heapam.c @@ -2862,8 +2862,8 @@ xmax_infomask_changed(uint16 new_infomask, uint16 old_infomask) */ TM_Result heap_delete(Relation relation, const ItemPointerData *tid, - CommandId cid, Snapshot crosscheck, bool wait, - TM_FailureData *tmfd, bool changingPart) + CommandId cid, uint32 options, Snapshot crosscheck, + bool wait, TM_FailureData *tmfd) { TM_Result result; TransactionId xid = GetCurrentTransactionId(); @@ -2876,6 +2876,7 @@ heap_delete(Relation relation, const ItemPointerData *tid, TransactionId new_xmax; uint16 new_infomask, new_infomask2; + bool changingPart = (options & TABLE_DELETE_CHANGING_PARTITION) != 0; bool have_tuple_lock = false; bool iscombo; bool all_visible_cleared = false; @@ -3290,9 +3291,11 @@ simple_heap_delete(Relation relation, const ItemPointerData *tid) TM_FailureData tmfd; result = heap_delete(relation, tid, - GetCurrentCommandId(true), InvalidSnapshot, + GetCurrentCommandId(true), + 0, + InvalidSnapshot, true /* wait for commit */ , - &tmfd, false /* changingPart */ ); + &tmfd); switch (result) { case TM_SelfModified: @@ -3331,7 +3334,7 @@ simple_heap_delete(Relation relation, const ItemPointerData *tid) */ TM_Result heap_update(Relation relation, const ItemPointerData *otid, HeapTuple newtup, - CommandId cid, Snapshot crosscheck, bool wait, + CommandId cid, uint32 options, Snapshot crosscheck, bool wait, TM_FailureData *tmfd, LockTupleMode *lockmode, TU_UpdateIndexes *update_indexes) { @@ -4585,7 +4588,8 @@ simple_heap_update(Relation relation, const ItemPointerData *otid, HeapTuple tup LockTupleMode lockmode; result = heap_update(relation, otid, tup, - GetCurrentCommandId(true), InvalidSnapshot, + GetCurrentCommandId(true), 0, + InvalidSnapshot, true /* wait for commit */ , &tmfd, &lockmode, update_indexes); switch (result) diff --git a/src/backend/access/heap/heapam_handler.c b/src/backend/access/heap/heapam_handler.c index cdd153c6b6d..69debeff516 100644 --- a/src/backend/access/heap/heapam_handler.c +++ b/src/backend/access/heap/heapam_handler.c @@ -313,21 +313,23 @@ heapam_tuple_complete_speculative(Relation relation, TupleTableSlot *slot, static TM_Result heapam_tuple_delete(Relation relation, ItemPointer tid, CommandId cid, - Snapshot snapshot, Snapshot crosscheck, bool wait, - TM_FailureData *tmfd, bool changingPart) + uint32 options, Snapshot snapshot, Snapshot crosscheck, + bool wait, TM_FailureData *tmfd) { /* * Currently Deleting of index tuples are handled at vacuum, in case if * the storage itself is cleaning the dead tuples by itself, it is the * time to call the index tuple deletion also. */ - return heap_delete(relation, tid, cid, crosscheck, wait, tmfd, changingPart); + return heap_delete(relation, tid, cid, options, crosscheck, wait, + tmfd); } static TM_Result heapam_tuple_update(Relation relation, ItemPointer otid, TupleTableSlot *slot, - CommandId cid, Snapshot snapshot, Snapshot crosscheck, + CommandId cid, uint32 options pg_attribute_unused(), + Snapshot snapshot, Snapshot crosscheck, bool wait, TM_FailureData *tmfd, LockTupleMode *lockmode, TU_UpdateIndexes *update_indexes) { @@ -339,7 +341,8 @@ heapam_tuple_update(Relation relation, ItemPointer otid, TupleTableSlot *slot, slot->tts_tableOid = RelationGetRelid(relation); tuple->t_tableOid = slot->tts_tableOid; - result = heap_update(relation, otid, tuple, cid, crosscheck, wait, + result = heap_update(relation, otid, tuple, cid, options, + crosscheck, wait, tmfd, lockmode, update_indexes); ItemPointerCopy(&tuple->t_self, &slot->tts_tid); diff --git a/src/backend/access/table/tableam.c b/src/backend/access/table/tableam.c index 86481d7c029..68ff0966f1c 100644 --- a/src/backend/access/table/tableam.c +++ b/src/backend/access/table/tableam.c @@ -320,9 +320,9 @@ simple_table_tuple_delete(Relation rel, ItemPointer tid, Snapshot snapshot) result = table_tuple_delete(rel, tid, GetCurrentCommandId(true), - snapshot, InvalidSnapshot, + 0, snapshot, InvalidSnapshot, true /* wait for commit */ , - &tmfd, false /* changingPart */ ); + &tmfd); switch (result) { @@ -369,7 +369,7 @@ simple_table_tuple_update(Relation rel, ItemPointer otid, result = table_tuple_update(rel, otid, slot, GetCurrentCommandId(true), - snapshot, InvalidSnapshot, + 0, snapshot, InvalidSnapshot, true /* wait for commit */ , &tmfd, &lockmode, update_indexes); diff --git a/src/backend/executor/nodeModifyTable.c b/src/backend/executor/nodeModifyTable.c index 582bcc367c0..76728f08734 100644 --- a/src/backend/executor/nodeModifyTable.c +++ b/src/backend/executor/nodeModifyTable.c @@ -1522,14 +1522,18 @@ ExecDeleteAct(ModifyTableContext *context, ResultRelInfo *resultRelInfo, ItemPointer tupleid, bool changingPart) { EState *estate = context->estate; + uint32 options = 0; + + if (changingPart) + options |= TABLE_DELETE_CHANGING_PARTITION; return table_tuple_delete(resultRelInfo->ri_RelationDesc, tupleid, estate->es_output_cid, + options, estate->es_snapshot, estate->es_crosscheck_snapshot, true /* wait for commit */ , - &context->tmfd, - changingPart); + &context->tmfd); } /* @@ -2331,6 +2335,7 @@ lreplace: */ result = table_tuple_update(resultRelationDesc, tupleid, slot, estate->es_output_cid, + 0, estate->es_snapshot, estate->es_crosscheck_snapshot, true /* wait for commit */ , diff --git a/src/include/access/heapam.h b/src/include/access/heapam.h index f46c83e88f3..54067b828e4 100644 --- a/src/include/access/heapam.h +++ b/src/include/access/heapam.h @@ -382,13 +382,14 @@ extern void heap_multi_insert(Relation relation, TupleTableSlot **slots, int ntuples, CommandId cid, uint32 options, BulkInsertState bistate); extern TM_Result heap_delete(Relation relation, const ItemPointerData *tid, - CommandId cid, Snapshot crosscheck, bool wait, - TM_FailureData *tmfd, bool changingPart); + CommandId cid, uint32 options, Snapshot crosscheck, + bool wait, TM_FailureData *tmfd); extern void heap_finish_speculative(Relation relation, const ItemPointerData *tid); extern void heap_abort_speculative(Relation relation, const ItemPointerData *tid); extern TM_Result heap_update(Relation relation, const ItemPointerData *otid, HeapTuple newtup, - CommandId cid, Snapshot crosscheck, bool wait, + CommandId cid, uint32 options, + Snapshot crosscheck, bool wait, TM_FailureData *tmfd, LockTupleMode *lockmode, TU_UpdateIndexes *update_indexes); extern TM_Result heap_lock_tuple(Relation relation, HeapTuple tuple, diff --git a/src/include/access/tableam.h b/src/include/access/tableam.h index 57892152957..c3b4429d9b9 100644 --- a/src/include/access/tableam.h +++ b/src/include/access/tableam.h @@ -288,6 +288,11 @@ typedef struct TM_IndexDeleteOp /* Follow update chain and lock latest version of tuple */ #define TUPLE_LOCK_FLAG_FIND_LAST_VERSION (1 << 1) +/* "options" flag bits for table_tuple_delete */ +#define TABLE_DELETE_CHANGING_PARTITION (1 << 0) + +/* "options" flag bits for table_tuple_update */ +/* XXX none at present */ /* Typedef for callback function for table_index_build_scan */ typedef void (*IndexBuildCallback) (Relation index, @@ -559,17 +564,18 @@ typedef struct TableAmRoutine TM_Result (*tuple_delete) (Relation rel, ItemPointer tid, CommandId cid, + uint32 options, Snapshot snapshot, Snapshot crosscheck, bool wait, - TM_FailureData *tmfd, - bool changingPart); + TM_FailureData *tmfd); /* see table_tuple_update() for reference about parameters */ TM_Result (*tuple_update) (Relation rel, ItemPointer otid, TupleTableSlot *slot, CommandId cid, + uint32 options, Snapshot snapshot, Snapshot crosscheck, bool wait, @@ -1534,12 +1540,12 @@ table_multi_insert(Relation rel, TupleTableSlot **slots, int nslots, */ static inline TM_Result table_tuple_delete(Relation rel, ItemPointer tid, CommandId cid, - Snapshot snapshot, Snapshot crosscheck, bool wait, - TM_FailureData *tmfd, bool changingPart) + uint32 options, Snapshot snapshot, Snapshot crosscheck, + bool wait, TM_FailureData *tmfd) { - return rel->rd_tableam->tuple_delete(rel, tid, cid, + return rel->rd_tableam->tuple_delete(rel, tid, cid, options, snapshot, crosscheck, - wait, tmfd, changingPart); + wait, tmfd); } /* @@ -1579,12 +1585,13 @@ table_tuple_delete(Relation rel, ItemPointer tid, CommandId cid, */ static inline TM_Result table_tuple_update(Relation rel, ItemPointer otid, TupleTableSlot *slot, - CommandId cid, Snapshot snapshot, Snapshot crosscheck, + CommandId cid, uint32 options, + Snapshot snapshot, Snapshot crosscheck, bool wait, TM_FailureData *tmfd, LockTupleMode *lockmode, TU_UpdateIndexes *update_indexes) { return rel->rd_tableam->tuple_update(rel, otid, slot, - cid, snapshot, crosscheck, + cid, options, snapshot, crosscheck, wait, tmfd, lockmode, update_indexes); } -- 2.47.3 --qfkt2ktdpcfeypib Content-Type: text/x-diff; charset=utf-8 Content-Disposition: attachment; filename="v48-0003-Rename-cluster.c-h-repack.c-h.patch" ^ permalink raw reply [nested|flat] 5+ messages in thread
end of thread, other threads:[~2026-03-30 11:27 UTC | newest] Thread overview: 5+ messages (download: mbox mbox.gz follow: Atom feed) -- links below jump to the message on this page -- 2026-02-20 06:13 [PATCH v8 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 2026-02-20 06:13 [PATCH v9 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 2026-02-20 06:13 [PATCH v7 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 2026-02-20 06:13 [PATCH v8 3/3] Introduce a new track_lock_timing GUC Bertrand Drouvot <bertranddrouvot.pg@gmail.com> 2026-03-30 11:27 [PATCH v48 2/7] Give 'options' parameter to table_delete/table_update Álvaro Herrera <alvherre@kurilemu.de>
This inbox is served by agora; see mirroring instructions for how to clone and mirror all data and code used for this inbox