Add wait event for pg_usleep() in perform_spin_delay()

anarazel · anarazel · commit 92daeca45df6 · 2022-11-21T20:34:17.000-08:00
The lwlock wait queue scalability issue fixed in a4adc31 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 <michael@paquier.xyz> Reviewed-by: Robert Haas <robertmhaas@gmail.com> Reviewed-by: Alexander Korotkov <aekorotkov@gmail.com> https://postgr.es/m/20221120204310.xywrhyxyytsajuuq@awork3.anarazel.de
diff --git 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
       <entry>Waiting while sending synchronization requests to the
        checkpointer, because the request queue is full.</entry>
      </row>
+     <row>
+      <entry><literal>SpinDelay</literal></entry>
+      <entry>Waiting while acquiring a contended spinlock.</entry>
+     </row>
      <row>
       <entry><literal>VacuumDelay</literal></entry>
       <entry>Waiting in a cost-based vacuum delay point.</entry>
diff --git 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
@@ -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
@@ -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;
