From 8765c04adb73d2c7057a5310e3670ec1fefdc0a5 Mon Sep 17 00:00:00 2001 From: Bharath Rupireddy Date: Fri, 12 Jan 2024 06:20:47 +0000 Subject: [PATCH v1] WAL insertion stats --- doc/src/sgml/monitoring.sgml | 33 +++++++++++++++++++++ src/backend/access/transam/xlog.c | 39 +++++++++++++++++++++++++ src/backend/catalog/system_views.sql | 5 +++- src/backend/utils/activity/pgstat_wal.c | 7 +++-- src/backend/utils/adt/pgstatfuncs.c | 15 ++++++++-- src/include/catalog/pg_proc.dat | 6 ++-- src/include/pgstat.h | 6 ++++ src/test/regress/expected/rules.out | 7 +++-- 8 files changed, 107 insertions(+), 11 deletions(-) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index b804eb8b5e..61f077b246 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -3181,6 +3181,39 @@ description | Waiting for a newly initialized WAL file to reach durable storage Time at which these statistics were last reset + + + + wal_insert_lock_acquire bigint + + + Number of times WAL insertion lock was acquired + + + + + + wal_insert_lock_acquire_time double precision + + + Total amount of time spent acquiring WAL insertion lock via + LWLockAcquire request, in milliseconds + (if track_wal_io_timing is enabled, otherwise + zero). + + + + + + wal_wait_for_insert_to_finish_time double precision + + + Total amount of time spent waiting for WAL insertion to finish, + in milliseconds (if track_wal_io_timing is enabled, + otherwise zero). + + + diff --git a/src/backend/access/transam/xlog.c b/src/backend/access/transam/xlog.c index 478377c4a2..b808025fe0 100644 --- a/src/backend/access/transam/xlog.c +++ b/src/backend/access/transam/xlog.c @@ -1364,6 +1364,7 @@ static void WALInsertLockAcquire(void) { bool immed; + instr_time start; /* * It doesn't matter which of the WAL insertion locks we acquire, so try @@ -1382,6 +1383,12 @@ WALInsertLockAcquire(void) lockToTry = MyProc->pgprocno % NUM_XLOGINSERT_LOCKS; MyLockNo = lockToTry; + /* Measure WAL insertion lock acquire time. */ + if (track_wal_io_timing) + INSTR_TIME_SET_CURRENT(start); + else + INSTR_TIME_SET_ZERO(start); + /* * The insertingAt value is initially set to 0, as we don't know our * insert location yet. @@ -1399,6 +1406,20 @@ WALInsertLockAcquire(void) */ lockToTry = (lockToTry + 1) % NUM_XLOGINSERT_LOCKS; } + + /* + * Increment acquire time and number of times WAL insertion lock is + * acquired. + */ + if (track_wal_io_timing) + { + instr_time end; + + INSTR_TIME_SET_CURRENT(end); + INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_insert_lock_acquire_time, end, start); + } + + PendingWalStats.wal_insert_lock_acquire++; } /* @@ -1501,6 +1522,7 @@ WaitXLogInsertionsToFinish(XLogRecPtr upto) XLogRecPtr finishedUpto; XLogCtlInsert *Insert = &XLogCtl->Insert; int i; + instr_time start; if (MyProc == NULL) elog(PANIC, "cannot wait without a PGPROC structure"); @@ -1537,6 +1559,13 @@ WaitXLogInsertionsToFinish(XLogRecPtr upto) * out for any insertion that's still in progress. */ finishedUpto = reservedUpto; + + /* Measure wait for WAL insert to finish time. */ + if (track_wal_io_timing) + INSTR_TIME_SET_CURRENT(start); + else + INSTR_TIME_SET_ZERO(start); + for (i = 0; i < NUM_XLOGINSERT_LOCKS; i++) { XLogRecPtr insertingat = InvalidXLogRecPtr; @@ -1584,6 +1613,16 @@ WaitXLogInsertionsToFinish(XLogRecPtr upto) if (insertingat != InvalidXLogRecPtr && insertingat < finishedUpto) finishedUpto = insertingat; } + + /* Increment wait for WAL insert to finish time. */ + if (track_wal_io_timing) + { + instr_time end; + + INSTR_TIME_SET_CURRENT(end); + INSTR_TIME_ACCUM_DIFF(PendingWalStats.wal_wait_for_insert_to_finish_time, end, start); + } + return finishedUpto; } diff --git a/src/backend/catalog/system_views.sql b/src/backend/catalog/system_views.sql index e43e36f5ac..1acc21a9cd 100644 --- a/src/backend/catalog/system_views.sql +++ b/src/backend/catalog/system_views.sql @@ -1181,7 +1181,10 @@ CREATE VIEW pg_stat_wal AS w.wal_sync, w.wal_write_time, w.wal_sync_time, - w.stats_reset + w.stats_reset, + w.wal_insert_lock_acquire, + w.wal_insert_lock_acquire_time, + w.wal_wait_for_insert_to_finish_time FROM pg_stat_get_wal() w; CREATE VIEW pg_stat_progress_analyze AS diff --git a/src/backend/utils/activity/pgstat_wal.c b/src/backend/utils/activity/pgstat_wal.c index 1a3c0e1a66..c6b596fcb1 100644 --- a/src/backend/utils/activity/pgstat_wal.c +++ b/src/backend/utils/activity/pgstat_wal.c @@ -119,6 +119,9 @@ pgstat_flush_wal(bool nowait) WALSTAT_ACC(wal_sync, PendingWalStats); WALSTAT_ACC_INSTR_TIME(wal_write_time); WALSTAT_ACC_INSTR_TIME(wal_sync_time); + WALSTAT_ACC(wal_insert_lock_acquire, PendingWalStats); + WALSTAT_ACC_INSTR_TIME(wal_insert_lock_acquire_time); + WALSTAT_ACC_INSTR_TIME(wal_wait_for_insert_to_finish_time); #undef WALSTAT_ACC_INSTR_TIME #undef WALSTAT_ACC @@ -158,9 +161,7 @@ pgstat_init_wal(void) bool pgstat_have_pending_wal(void) { - return pgWalUsage.wal_records != prevWalUsage.wal_records || - PendingWalStats.wal_write != 0 || - PendingWalStats.wal_sync != 0; + return true; } void diff --git a/src/backend/utils/adt/pgstatfuncs.c b/src/backend/utils/adt/pgstatfuncs.c index 30a2063505..b320e71c2a 100644 --- a/src/backend/utils/adt/pgstatfuncs.c +++ b/src/backend/utils/adt/pgstatfuncs.c @@ -1470,7 +1470,7 @@ pg_stat_get_io(PG_FUNCTION_ARGS) Datum pg_stat_get_wal(PG_FUNCTION_ARGS) { -#define PG_STAT_GET_WAL_COLS 9 +#define PG_STAT_GET_WAL_COLS 12 TupleDesc tupdesc; Datum values[PG_STAT_GET_WAL_COLS] = {0}; bool nulls[PG_STAT_GET_WAL_COLS] = {0}; @@ -1497,7 +1497,12 @@ pg_stat_get_wal(PG_FUNCTION_ARGS) FLOAT8OID, -1, 0); TupleDescInitEntry(tupdesc, (AttrNumber) 9, "stats_reset", TIMESTAMPTZOID, -1, 0); - + TupleDescInitEntry(tupdesc, (AttrNumber) 10, "wal_insert_lock_acquire", + INT8OID, -1, 0); + TupleDescInitEntry(tupdesc, (AttrNumber) 11, "wal_insert_lock_acquire_time", + FLOAT8OID, -1, 0); + TupleDescInitEntry(tupdesc, (AttrNumber) 12, "wal_wait_for_insert_to_finish_time", + FLOAT8OID, -1, 0); BlessTupleDesc(tupdesc); /* Get statistics about WAL activity */ @@ -1524,6 +1529,12 @@ pg_stat_get_wal(PG_FUNCTION_ARGS) values[8] = TimestampTzGetDatum(wal_stats->stat_reset_timestamp); + values[9] = Int64GetDatum(wal_stats->wal_insert_lock_acquire); + + /* Convert counters from microsec to millisec for display */ + values[10] = Float8GetDatum(((double) wal_stats->wal_insert_lock_acquire_time) / 1000.0); + values[11] = Float8GetDatum(((double) wal_stats->wal_wait_for_insert_to_finish_time) / 1000.0); + /* Returns the record as Datum */ PG_RETURN_DATUM(HeapTupleGetDatum(heap_form_tuple(tupdesc, values, nulls))); } diff --git a/src/include/catalog/pg_proc.dat b/src/include/catalog/pg_proc.dat index 58811a6530..a8d562114a 100644 --- a/src/include/catalog/pg_proc.dat +++ b/src/include/catalog/pg_proc.dat @@ -5785,9 +5785,9 @@ { oid => '1136', descr => 'statistics: information about WAL activity', proname => 'pg_stat_get_wal', proisstrict => 'f', provolatile => 's', proparallel => 'r', prorettype => 'record', proargtypes => '', - proallargtypes => '{int8,int8,numeric,int8,int8,int8,float8,float8,timestamptz}', - proargmodes => '{o,o,o,o,o,o,o,o,o}', - proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset}', + proallargtypes => '{int8,int8,numeric,int8,int8,int8,float8,float8,timestamptz,int8,float8,float8}', + proargmodes => '{o,o,o,o,o,o,o,o,o,o,o,o}', + proargnames => '{wal_records,wal_fpi,wal_bytes,wal_buffers_full,wal_write,wal_sync,wal_write_time,wal_sync_time,stats_reset,wal_insert_lock_acquire,wal_insert_lock_acquire_time,wal_wait_for_insert_to_finish_time}', prosrc => 'pg_stat_get_wal' }, { oid => '6248', descr => 'statistics: information about WAL prefetching', proname => 'pg_stat_get_recovery_prefetch', prorows => '1', proretset => 't', diff --git a/src/include/pgstat.h b/src/include/pgstat.h index 2136239710..ef3179376c 100644 --- a/src/include/pgstat.h +++ b/src/include/pgstat.h @@ -439,6 +439,9 @@ typedef struct PgStat_WalStats PgStat_Counter wal_write_time; PgStat_Counter wal_sync_time; TimestampTz stat_reset_timestamp; + PgStat_Counter wal_insert_lock_acquire; + PgStat_Counter wal_insert_lock_acquire_time; + PgStat_Counter wal_wait_for_insert_to_finish_time; } PgStat_WalStats; /* @@ -454,6 +457,9 @@ typedef struct PgStat_PendingWalStats PgStat_Counter wal_sync; instr_time wal_write_time; instr_time wal_sync_time; + PgStat_Counter wal_insert_lock_acquire; + instr_time wal_insert_lock_acquire_time; + instr_time wal_wait_for_insert_to_finish_time; } PgStat_PendingWalStats; diff --git a/src/test/regress/expected/rules.out b/src/test/regress/expected/rules.out index d878a971df..46274f8da9 100644 --- a/src/test/regress/expected/rules.out +++ b/src/test/regress/expected/rules.out @@ -2233,8 +2233,11 @@ pg_stat_wal| SELECT wal_records, wal_sync, wal_write_time, wal_sync_time, - stats_reset - FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, wal_write, wal_sync, wal_write_time, wal_sync_time, stats_reset); + stats_reset, + wal_insert_lock_acquire, + wal_insert_lock_acquire_time, + wal_wait_for_insert_to_finish_time + FROM pg_stat_get_wal() w(wal_records, wal_fpi, wal_bytes, wal_buffers_full, wal_write, wal_sync, wal_write_time, wal_sync_time, stats_reset, wal_insert_lock_acquire, wal_insert_lock_acquire_time, wal_wait_for_insert_to_finish_time); pg_stat_wal_receiver| SELECT pid, status, receive_start_lsn, -- 2.34.1