runtime/metrics: add STW stopping and total time metrics

This CL adds four new time histogram metrics:

/sched/pauses/stopping/gc:seconds
/sched/pauses/stopping/other:seconds
/sched/pauses/total/gc:seconds
/sched/pauses/total/other:seconds

The "stopping" metrics measure the time taken to start a stop-the-world
pause. i.e., how long it takes stopTheWorldWithSema to stop all Ps.
This can be used to detect STW struggling to preempt Ps.

The "total" metrics measure the total duration of a stop-the-world
pause, from starting to stop-the-world until the world is started again.
This includes the time spent in the "start" phase.

The "gc" metrics are used for GC-related STW pauses. The "other" metrics
are used for all other STW pauses.

All of these metrics start timing in stopTheWorldWithSema only after
successfully acquiring sched.lock, thus excluding lock contention on
sched.lock. The reasoning behind this is that while waiting on
sched.lock the world is not stopped at all (all other Ps can run), so
the impact of this contention is primarily limited to the goroutine
attempting to stop-the-world. Additionally, we already have some
visibility into sched.lock contention via contention profiles (#57071).

/sched/pauses/total/gc:seconds is conceptually equivalent to
/gc/pauses:seconds, so the latter is marked as deprecated and returns
the same histogram as the former.

In the implementation, there are a few minor differences:

* For both mark and sweep termination stops, /gc/pauses:seconds started
  timing prior to calling startTheWorldWithSema, thus including lock
  contention.

These details are minor enough, that I do not believe the slight change
in reporting will matter. For mark termination stops, moving timing stop
into startTheWorldWithSema does have the side effect of requiring moving
other GC metric calculations outside of the STW, as they depend on the
same end time.

Fixes #63340

Change-Id: Iacd0bab11bedab85d3dcfb982361413a7d9c0d05
Reviewed-on: https://go-review.googlesource.com/c/go/+/534161
Reviewed-by: Michael Knyszek <[email protected]>
Auto-Submit: Michael Pratt <[email protected]>
LUCI-TryBot-Result: Go LUCI <[email protected]>

Author: prattmic

src/runtime/debug.go

@@ -25,12 +25,12 @@ func GOMAXPROCS(n int) int {
 		return ret
 	}
 
-	stopTheWorldGC(stwGOMAXPROCS)
+	stw := stopTheWorldGC(stwGOMAXPROCS)
 
 	// newprocs will be processed by startTheWorld
 	newprocs = int32(n)
 
-	startTheWorldGC()
+	startTheWorldGC(stw)
 	return ret
 }
 

src/runtime/export_debuglog_test.go

@@ -35,12 +35,12 @@ func DumpDebugLog() string {
 }
 
 func ResetDebugLog() {
-	stopTheWorld(stwForTestResetDebugLog)
+	stw := stopTheWorld(stwForTestResetDebugLog)
 	for l := allDloggers; l != nil; l = l.allLink {
 		l.w.write = 0
 		l.w.tick, l.w.nano = 0, 0
 		l.w.r.begin, l.w.r.end = 0, 0
 		l.w.r.tick, l.w.r.nano = 0, 0
 	}
-	startTheWorld()
+	startTheWorld(stw)
 }

src/runtime/export_test.go

@@ -383,7 +383,7 @@ var ReadUnaligned32 = readUnaligned32
 var ReadUnaligned64 = readUnaligned64
 
 func CountPagesInUse() (pagesInUse, counted uintptr) {
-	stopTheWorld(stwForTestCountPagesInUse)
+	stw := stopTheWorld(stwForTestCountPagesInUse)
 
 	pagesInUse = mheap_.pagesInUse.Load()
 
@@ -393,7 +393,7 @@ func CountPagesInUse() (pagesInUse, counted uintptr) {
 		}
 	}
 
-	startTheWorld()
+	startTheWorld(stw)
 
 	return
 }
@@ -426,7 +426,7 @@ func (p *ProfBuf) Close() {
 }
 
 func ReadMetricsSlow(memStats *MemStats, samplesp unsafe.Pointer, len, cap int) {
-	stopTheWorld(stwForTestReadMetricsSlow)
+	stw := stopTheWorld(stwForTestReadMetricsSlow)
 
 	// Initialize the metrics beforehand because this could
 	// allocate and skew the stats.
@@ -461,13 +461,13 @@ func ReadMetricsSlow(memStats *MemStats, samplesp unsafe.Pointer, len, cap int)
 	})
 	metricsUnlock()
 
-	startTheWorld()
+	startTheWorld(stw)
 }
 
 // ReadMemStatsSlow returns both the runtime-computed MemStats and
 // MemStats accumulated by scanning the heap.
 func ReadMemStatsSlow() (base, slow MemStats) {
-	stopTheWorld(stwForTestReadMemStatsSlow)
+	stw := stopTheWorld(stwForTestReadMemStatsSlow)
 
 	// Run on the system stack to avoid stack growth allocation.
 	systemstack(func() {
@@ -544,7 +544,7 @@ func ReadMemStatsSlow() (base, slow MemStats) {
 		getg().m.mallocing--
 	})
 
-	startTheWorld()
+	startTheWorld(stw)
 	return
 }
 
@@ -1324,7 +1324,7 @@ func CheckScavengedBitsCleared(mismatches []BitsMismatch) (n int, ok bool) {
 }
 
 func PageCachePagesLeaked() (leaked uintptr) {
-	stopTheWorld(stwForTestPageCachePagesLeaked)
+	stw := stopTheWorld(stwForTestPageCachePagesLeaked)
 
 	// Walk over destroyed Ps and look for unflushed caches.
 	deadp := allp[len(allp):cap(allp)]
@@ -1336,7 +1336,7 @@ func PageCachePagesLeaked() (leaked uintptr) {
 		}
 	}
 
-	startTheWorld()
+	startTheWorld(stw)
 	return
 }
 

src/runtime/heapdump.go

@@ -20,7 +20,7 @@ import (
 
 //go:linkname runtime_debug_WriteHeapDump runtime/debug.WriteHeapDump
 func runtime_debug_WriteHeapDump(fd uintptr) {
-	stopTheWorld(stwWriteHeapDump)
+	stw := stopTheWorld(stwWriteHeapDump)
 
 	// Keep m on this G's stack instead of the system stack.
 	// Both readmemstats_m and writeheapdump_m have pretty large
@@ -37,7 +37,7 @@ func runtime_debug_WriteHeapDump(fd uintptr) {
 		writeheapdump_m(fd, &m)
 	})
 
-	startTheWorld()
+	startTheWorld(stw)
 }
 
 const (

src/runtime/histogram.go

@@ -134,6 +134,19 @@ func (h *timeHistogram) record(duration int64) {
 	h.counts[bucket*timeHistNumSubBuckets+subBucket].Add(1)
 }
 
+// write dumps the histogram to the passed metricValue as a float64 histogram.
+func (h *timeHistogram) write(out *metricValue) {
+	hist := out.float64HistOrInit(timeHistBuckets)
+	// The bottom-most bucket, containing negative values, is tracked
+	// separately as underflow, so fill that in manually and then iterate
+	// over the rest.
+	hist.counts[0] = h.underflow.Load()
+	for i := range h.counts {
+		hist.counts[i+1] = h.counts[i].Load()
+	}
+	hist.counts[len(hist.counts)-1] = h.overflow.Load()
+}
+
 const (
 	fInf    = 0x7FF0000000000000
 	fNegInf = 0xFFF0000000000000

src/runtime/metrics.go

@@ -317,15 +317,8 @@ func initMetrics() {
 		},
 		"/gc/pauses:seconds": {
 			compute: func(_ *statAggregate, out *metricValue) {
-				hist := out.float64HistOrInit(timeHistBuckets)
-				// The bottom-most bucket, containing negative values, is tracked
-				// as a separately as underflow, so fill that in manually and then
-				// iterate over the rest.
-				hist.counts[0] = memstats.gcPauseDist.underflow.Load()
-				for i := range memstats.gcPauseDist.counts {
-					hist.counts[i+1] = memstats.gcPauseDist.counts[i].Load()
-				}
-				hist.counts[len(hist.counts)-1] = memstats.gcPauseDist.overflow.Load()
+				// N.B. this is identical to /sched/pauses/total/gc:seconds.
+				sched.stwTotalTimeGC.write(out)
 			},
 		},
 		"/gc/stack/starting-size:bytes": {
@@ -451,12 +444,27 @@ func initMetrics() {
 		},
 		"/sched/latencies:seconds": {
 			compute: func(_ *statAggregate, out *metricValue) {
-				hist := out.float64HistOrInit(timeHistBuckets)
-				hist.counts[0] = sched.timeToRun.underflow.Load()
-				for i := range sched.timeToRun.counts {
-					hist.counts[i+1] = sched.timeToRun.counts[i].Load()
-				}
-				hist.counts[len(hist.counts)-1] = sched.timeToRun.overflow.Load()
+				sched.timeToRun.write(out)
+			},
+		},
+		"/sched/pauses/stopping/gc:seconds": {
+			compute: func(_ *statAggregate, out *metricValue) {
+				sched.stwStoppingTimeGC.write(out)
+			},
+		},
+		"/sched/pauses/stopping/other:seconds": {
+			compute: func(_ *statAggregate, out *metricValue) {
+				sched.stwStoppingTimeOther.write(out)
+			},
+		},
+		"/sched/pauses/total/gc:seconds": {
+			compute: func(_ *statAggregate, out *metricValue) {
+				sched.stwTotalTimeGC.write(out)
+			},
+		},
+		"/sched/pauses/total/other:seconds": {
+			compute: func(_ *statAggregate, out *metricValue) {
+				sched.stwTotalTimeOther.write(out)
 			},
 		},
 		"/sync/mutex/wait/total:seconds": {

src/runtime/metrics/description.go

@@ -96,11 +96,11 @@ var allDesc = []Description{
 		Description: "Estimated total CPU time spent with the application paused by " +
 			"the GC. Even if only one thread is running during the pause, this is " +
 			"computed as GOMAXPROCS times the pause latency because nothing else " +
-			"can be executing. This is the exact sum of samples in /gc/pause:seconds " +
-			"if each sample is multiplied by GOMAXPROCS at the time it is taken. " +
-			"This metric is an overestimate, and not directly comparable to " +
-			"system CPU time measurements. Compare only with other /cpu/classes " +
-			"metrics.",
+			"can be executing. This is the exact sum of samples in " +
+			"/sched/pauses/total/gc:seconds if each sample is multiplied by " +
+			"GOMAXPROCS at the time it is taken. This metric is an overestimate, " +
+			"and not directly comparable to system CPU time measurements. Compare " +
+			"only with other /cpu/classes metrics.",
 		Kind:       KindFloat64,
 		Cumulative: true,
 	},
@@ -289,7 +289,7 @@ var allDesc = []Description{
 	},
 	{
 		Name:        "/gc/pauses:seconds",
-		Description: "Distribution of individual GC-related stop-the-world pause latencies. Bucket counts increase monotonically.",
+		Description: "Deprecated. Prefer the identical /sched/pauses/total/gc:seconds.",
 		Kind:        KindFloat64Histogram,
 		Cumulative:  true,
 	},
@@ -415,6 +415,30 @@ var allDesc = []Description{
 		Kind:        KindFloat64Histogram,
 		Cumulative:  true,
 	},
+	{
+		Name:        "/sched/pauses/stopping/gc:seconds",
+		Description: "Distribution of individual GC-related stop-the-world stopping latencies. This is the time it takes from deciding to stop the world until all Ps are stopped. This is a subset of the total GC-related stop-the-world time (/sched/pauses/total/gc:seconds). During this time, some threads may be executing. Bucket counts increase monotonically.",
+		Kind:        KindFloat64Histogram,
+		Cumulative:  true,
+	},
+	{
+		Name:        "/sched/pauses/stopping/other:seconds",
+		Description: "Distribution of individual non-GC-related stop-the-world stopping latencies. This is the time it takes from deciding to stop the world until all Ps are stopped. This is a subset of the total non-GC-related stop-the-world time (/sched/pauses/total/other:seconds). During this time, some threads may be executing. Bucket counts increase monotonically.",
+		Kind:        KindFloat64Histogram,
+		Cumulative:  true,
+	},
+	{
+		Name:        "/sched/pauses/total/gc:seconds",
+		Description: "Distribution of individual GC-related stop-the-world pause latencies. This is the time from deciding to stop the world until the world is started again. Some of this time is spent getting all threads to stop (this is measured directly in /sched/pauses/stopping/gc:seconds), during which some threads may still be running. Bucket counts increase monotonically.",
+		Kind:        KindFloat64Histogram,
+		Cumulative:  true,
+	},
+	{
+		Name:        "/sched/pauses/total/other:seconds",
+		Description: "Distribution of individual non-GC-related stop-the-world pause latencies. This is the time from deciding to stop the world until the world is started again. Some of this time is spent getting all threads to stop (measured directly in /sched/pauses/stopping/other:seconds). Bucket counts increase monotonically.",
+		Kind:        KindFloat64Histogram,
+		Cumulative:  true,
+	},
 	{
 		Name:        "/sync/mutex/wait/total:seconds",
 		Description: "Approximate cumulative time goroutines have spent blocked on a sync.Mutex or sync.RWMutex. This metric is useful for identifying global changes in lock contention. Collect a mutex or block profile using the runtime/pprof package for more detailed contention data.",

src/runtime/metrics/doc.go

@@ -83,10 +83,10 @@ Below is the full list of supported metrics, ordered lexicographically.
 		the GC. Even if only one thread is running during the pause,
 		this is computed as GOMAXPROCS times the pause latency because
 		nothing else can be executing. This is the exact sum of samples
-		in /gc/pause:seconds if each sample is multiplied by GOMAXPROCS
-		at the time it is taken. This metric is an overestimate,
-		and not directly comparable to system CPU time measurements.
-		Compare only with other /cpu/classes metrics.
+		in /sched/pauses/total/gc:seconds if each sample is multiplied
+		by GOMAXPROCS at the time it is taken. This metric is an
+		overestimate, and not directly comparable to system CPU time
+		measurements. Compare only with other /cpu/classes metrics.
 
 	/cpu/classes/gc/total:cpu-seconds
 		Estimated total CPU time spent performing GC tasks. This metric
@@ -211,8 +211,7 @@ Below is the full list of supported metrics, ordered lexicographically.
 		1, so a value of 0 indicates that it was never enabled.
 
 	/gc/pauses:seconds
-		Distribution of individual GC-related stop-the-world pause
-		latencies. Bucket counts increase monotonically.
+		Deprecated. Prefer the identical /sched/pauses/total/gc:seconds.
 
 	/gc/scan/globals:bytes
 		The total amount of global variable space that is scannable.
@@ -411,6 +410,38 @@ Below is the full list of supported metrics, ordered lexicographically.
 		in a runnable state before actually running. Bucket counts
 		increase monotonically.
 
+	/sched/pauses/stopping/gc:seconds
+		Distribution of individual GC-related stop-the-world stopping
+		latencies. This is the time it takes from deciding to stop the
+		world until all Ps are stopped. This is a subset of the total
+		GC-related stop-the-world time (/sched/pauses/total/gc:seconds).
+		During this time, some threads may be executing. Bucket counts
+		increase monotonically.
+
+	/sched/pauses/stopping/other:seconds
+		Distribution of individual non-GC-related stop-the-world
+		stopping latencies. This is the time it takes from deciding
+		to stop the world until all Ps are stopped. This is a
+		subset of the total non-GC-related stop-the-world time
+		(/sched/pauses/total/other:seconds). During this time, some
+		threads may be executing. Bucket counts increase monotonically.
+
+	/sched/pauses/total/gc:seconds
+		Distribution of individual GC-related stop-the-world pause
+		latencies. This is the time from deciding to stop the world
+		until the world is started again. Some of this time is spent
+		getting all threads to stop (this is measured directly in
+		/sched/pauses/stopping/gc:seconds), during which some threads
+		may still be running. Bucket counts increase monotonically.
+
+	/sched/pauses/total/other:seconds
+		Distribution of individual non-GC-related stop-the-world
+		pause latencies. This is the time from deciding to stop the
+		world until the world is started again. Some of this time
+		is spent getting all threads to stop (measured directly in
+		/sched/pauses/stopping/other:seconds). Bucket counts increase
+		monotonically.
+
 	/sync/mutex/wait/total:seconds
 		Approximate cumulative time goroutines have spent blocked
 		on a sync.Mutex or sync.RWMutex. This metric is useful for