From 92daeca45df6551dd85f92f7369eaa57a35fb8a9 Mon Sep 17 00:00:00 2001 From: Andres Freund Date: Mon, 21 Nov 2022 20:34:17 -0800 Subject: [PATCH] Add wait event for pg_usleep() in perform_spin_delay() The lwlock wait queue scalability issue fixed in a4adc31f690 was quite hard to find because of the exponential backoff and because we adjust spins_per_delay over time within a backend. To make it easier to find similar issues in the future, add a wait event for the pg_usleep() in perform_spin_delay(). Showing a wait event while spinning without sleeping would increase the overhead of spinlocks, which we do not want. We may at some later point want to have more granular wait events, but that'd be a substantial amount of work. This provides at least some insights into something currently hard to observe. Reviewed-by: Michael Paquier Reviewed-by: Robert Haas Reviewed-by: Alexander Korotkov https://postgr.es/m/20221120204310.xywrhyxyytsajuuq@awork3.anarazel.de --- doc/src/sgml/monitoring.sgml | 4 ++++ src/backend/storage/lmgr/s_lock.c | 11 +++++++++++ src/backend/utils/activity/wait_event.c | 3 +++ src/include/utils/wait_event.h | 1 + 4 files changed, 19 insertions(+) diff --git a/doc/src/sgml/monitoring.sgml b/doc/src/sgml/monitoring.sgml index e5d622d514..e2426f7210 100644 --- a/doc/src/sgml/monitoring.sgml +++ b/doc/src/sgml/monitoring.sgml @@ -2289,6 +2289,10 @@ postgres 27093 0.0 0.0 30096 2752 ? Ss 11:34 0:00 postgres: ser Waiting while sending synchronization requests to the checkpointer, because the request queue is full. + + SpinDelay + Waiting while acquiring a contended spinlock. + VacuumDelay Waiting in a cost-based vacuum delay point. diff --git a/src/backend/storage/lmgr/s_lock.c b/src/backend/storage/lmgr/s_lock.c index 4e473ec27e..c3227b11ab 100644 --- a/src/backend/storage/lmgr/s_lock.c +++ b/src/backend/storage/lmgr/s_lock.c @@ -53,6 +53,7 @@ #include "common/pg_prng.h" #include "port/atomics.h" #include "storage/s_lock.h" +#include "utils/wait_event.h" #define MIN_SPINS_PER_DELAY 10 #define MAX_SPINS_PER_DELAY 1000 @@ -136,7 +137,17 @@ perform_spin_delay(SpinDelayStatus *status) if (status->cur_delay == 0) /* first time to delay? */ status->cur_delay = MIN_DELAY_USEC; + /* + * Once we start sleeping, the overhead of reporting a wait event is + * justified. Actively spinning easily stands out in profilers, but + * sleeping with an exponential backoff is harder to spot... + * + * We might want to report something more granular at some point, but + * this is better than nothing. + */ + pgstat_report_wait_start(WAIT_EVENT_SPIN_DELAY); pg_usleep(status->cur_delay); + pgstat_report_wait_end(); #if defined(S_LOCK_TEST) fprintf(stdout, "*"); diff --git a/src/backend/utils/activity/wait_event.c b/src/backend/utils/activity/wait_event.c index 92f24a6c9b..b2abd75ddb 100644 --- a/src/backend/utils/activity/wait_event.c +++ b/src/backend/utils/activity/wait_event.c @@ -497,6 +497,9 @@ pgstat_get_wait_timeout(WaitEventTimeout w) case WAIT_EVENT_REGISTER_SYNC_REQUEST: event_name = "RegisterSyncRequest"; break; + case WAIT_EVENT_SPIN_DELAY: + event_name = "SpinDelay"; + break; case WAIT_EVENT_VACUUM_DELAY: event_name = "VacuumDelay"; break; diff --git a/src/include/utils/wait_event.h b/src/include/utils/wait_event.h index 6f2d5612e0..0b2100be4a 100644 --- a/src/include/utils/wait_event.h +++ b/src/include/utils/wait_event.h @@ -145,6 +145,7 @@ typedef enum WAIT_EVENT_RECOVERY_APPLY_DELAY, WAIT_EVENT_RECOVERY_RETRIEVE_RETRY_INTERVAL, WAIT_EVENT_REGISTER_SYNC_REQUEST, + WAIT_EVENT_SPIN_DELAY, WAIT_EVENT_VACUUM_DELAY, WAIT_EVENT_VACUUM_TRUNCATE } WaitEventTimeout;