runtime/metrics: add cleanup and finalizer queue metrics

These metrics are useful for identifying finalizer and cleanup problems,
namely slow finalizers and/or cleanups holding up the queue, which can
lead to a memory leak.

Fixes #72948.

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

Author: mknyszek

src/runtime/metrics.go

@@ -169,6 +169,20 @@ func initMetrics() {
 				out.scalar = float64bits(nsToSec(in.cpuStats.UserTime))
 			},
 		},
+		"/gc/cleanups/executed:cleanups": {
+			deps: makeStatDepSet(finalStatsDep),
+			compute: func(in *statAggregate, out *metricValue) {
+				out.kind = metricKindUint64
+				out.scalar = in.finalStats.cleanupsExecuted
+			},
+		},
+		"/gc/cleanups/queued:cleanups": {
+			deps: makeStatDepSet(finalStatsDep),
+			compute: func(in *statAggregate, out *metricValue) {
+				out.kind = metricKindUint64
+				out.scalar = in.finalStats.cleanupsQueued
+			},
+		},
 		"/gc/cycles/automatic:gc-cycles": {
 			deps: makeStatDepSet(sysStatsDep),
 			compute: func(in *statAggregate, out *metricValue) {
@@ -190,6 +204,20 @@ func initMetrics() {
 				out.scalar = in.sysStats.gcCyclesDone
 			},
 		},
+		"/gc/finalizers/executed:finalizers": {
+			deps: makeStatDepSet(finalStatsDep),
+			compute: func(in *statAggregate, out *metricValue) {
+				out.kind = metricKindUint64
+				out.scalar = in.finalStats.finalizersExecuted
+			},
+		},
+		"/gc/finalizers/queued:finalizers": {
+			deps: makeStatDepSet(finalStatsDep),
+			compute: func(in *statAggregate, out *metricValue) {
+				out.kind = metricKindUint64
+				out.scalar = in.finalStats.finalizersQueued
+			},
+		},
 		"/gc/scan/globals:bytes": {
 			deps: makeStatDepSet(gcStatsDep),
 			compute: func(in *statAggregate, out *metricValue) {
@@ -514,10 +542,11 @@ func godebug_registerMetric(name string, read func() uint64) {
 type statDep uint
 
 const (
-	heapStatsDep statDep = iota // corresponds to heapStatsAggregate
-	sysStatsDep                 // corresponds to sysStatsAggregate
-	cpuStatsDep                 // corresponds to cpuStatsAggregate
-	gcStatsDep                  // corresponds to gcStatsAggregate
+	heapStatsDep  statDep = iota // corresponds to heapStatsAggregate
+	sysStatsDep                  // corresponds to sysStatsAggregate
+	cpuStatsDep                  // corresponds to cpuStatsAggregate
+	gcStatsDep                   // corresponds to gcStatsAggregate
+	finalStatsDep                // corresponds to finalStatsAggregate
 	numStatsDeps
 )
 
@@ -696,6 +725,21 @@ func (a *gcStatsAggregate) compute() {
 	a.totalScan = a.heapScan + a.stackScan + a.globalsScan
 }
 
+// finalStatsAggregate represents various finalizer/cleanup stats obtained
+// from the runtime acquired together to avoid skew and inconsistencies.
+type finalStatsAggregate struct {
+	finalizersQueued   uint64
+	finalizersExecuted uint64
+	cleanupsQueued     uint64
+	cleanupsExecuted   uint64
+}
+
+// compute populates the finalStatsAggregate with values from the runtime.
+func (a *finalStatsAggregate) compute() {
+	a.finalizersQueued, a.finalizersExecuted = finReadQueueStats()
+	a.cleanupsQueued, a.cleanupsExecuted = gcCleanups.readQueueStats()
+}
+
 // nsToSec takes a duration in nanoseconds and converts it to seconds as
 // a float64.
 func nsToSec(ns int64) float64 {
@@ -708,11 +752,12 @@ func nsToSec(ns int64) float64 {
 // as a set of these aggregates that it has populated. The aggregates
 // are populated lazily by its ensure method.
 type statAggregate struct {
-	ensured   statDepSet
-	heapStats heapStatsAggregate
-	sysStats  sysStatsAggregate
-	cpuStats  cpuStatsAggregate
-	gcStats   gcStatsAggregate
+	ensured    statDepSet
+	heapStats  heapStatsAggregate
+	sysStats   sysStatsAggregate
+	cpuStats   cpuStatsAggregate
+	gcStats    gcStatsAggregate
+	finalStats finalStatsAggregate
 }
 
 // ensure populates statistics aggregates determined by deps if they
@@ -735,6 +780,8 @@ func (a *statAggregate) ensure(deps *statDepSet) {
 			a.cpuStats.compute()
 		case gcStatsDep:
 			a.gcStats.compute()
+		case finalStatsDep:
+			a.finalStats.compute()
 		}
 	}
 	a.ensured = a.ensured.union(missing)

src/runtime/metrics/description.go

@@ -174,6 +174,22 @@ var allDesc = []Description{
 		Kind:       KindFloat64,
 		Cumulative: true,
 	},
+	{
+		Name: "/gc/cleanups/executed:cleanups",
+		Description: "Approximate total count of cleanup functions (created by runtime.AddCleanup) " +
+			"executed by the runtime. Subtract /gc/cleanups/queued:cleanups to approximate " +
+			"cleanup queue length. Useful for detecting slow cleanups holding up the queue.",
+		Kind:       KindUint64,
+		Cumulative: true,
+	},
+	{
+		Name: "/gc/cleanups/queued:cleanups",
+		Description: "Approximate total count of cleanup functions (created by runtime.AddCleanup) " +
+			"queued by the runtime for execution. Subtract from /gc/cleanups/executed:cleanups " +
+			"to approximate cleanup queue length. Useful for detecting slow cleanups holding up the queue.",
+		Kind:       KindUint64,
+		Cumulative: true,
+	},
 	{
 		Name:        "/gc/cycles/automatic:gc-cycles",
 		Description: "Count of completed GC cycles generated by the Go runtime.",
@@ -192,6 +208,23 @@ var allDesc = []Description{
 		Kind:        KindUint64,
 		Cumulative:  true,
 	},
+	{
+		Name: "/gc/finalizers/executed:finalizers",
+		Description: "Total count of finalizer functions (created by runtime.SetFinalizer) " +
+			"executed by the runtime. Subtract /gc/finalizers/queued:finalizers to approximate " +
+			"finalizer queue length. Useful for detecting finalizers overwhelming the queue, " +
+			"either by being too slow, or by there being too many of them.",
+		Kind:       KindUint64,
+		Cumulative: true,
+	},
+	{
+		Name: "/gc/finalizers/queued:finalizers",
+		Description: "Total count of finalizer functions (created by runtime.SetFinalizer) and " +
+			"queued by the runtime for execution. Subtract from /gc/finalizers/executed:finalizers " +
+			"to approximate finalizer queue length. Useful for detecting slow finalizers holding up the queue.",
+		Kind:       KindUint64,
+		Cumulative: true,
+	},
 	{
 		Name: "/gc/gogc:percent",
 		Description: "Heap size target percentage configured by the user, otherwise 100. This " +

src/runtime/metrics/doc.go

@@ -137,6 +137,19 @@ Below is the full list of supported metrics, ordered lexicographically.
 		to system CPU time measurements. Compare only with other
 		/cpu/classes metrics.
 
+	/gc/cleanups/executed:cleanups
+		Approximate total count of cleanup functions (created
+		by runtime.AddCleanup) executed by the runtime. Subtract
+		/gc/cleanups/queued:cleanups to approximate cleanup queue
+		length. Useful for detecting slow cleanups holding up the queue.
+
+	/gc/cleanups/queued:cleanups
+		Approximate total count of cleanup functions (created by
+		runtime.AddCleanup) queued by the runtime for execution.
+		Subtract from /gc/cleanups/executed:cleanups to approximate
+		cleanup queue length. Useful for detecting slow cleanups holding
+		up the queue.
+
 	/gc/cycles/automatic:gc-cycles
 		Count of completed GC cycles generated by the Go runtime.
 
@@ -146,6 +159,20 @@ Below is the full list of supported metrics, ordered lexicographically.
 	/gc/cycles/total:gc-cycles
 		Count of all completed GC cycles.
 
+	/gc/finalizers/executed:finalizers
+		Total count of finalizer functions (created by
+		runtime.SetFinalizer) executed by the runtime. Subtract
+		/gc/finalizers/queued:finalizers to approximate finalizer queue
+		length. Useful for detecting finalizers overwhelming the queue,
+		either by being too slow, or by there being too many of them.
+
+	/gc/finalizers/queued:finalizers
+		Total count of finalizer functions (created by
+		runtime.SetFinalizer) and queued by the runtime for execution.
+		Subtract from /gc/finalizers/executed:finalizers to approximate
+		finalizer queue length. Useful for detecting slow finalizers
+		holding up the queue.
+
 	/gc/gogc:percent
 		Heap size target percentage configured by the user, otherwise
 		100. This value is set by the GOGC environment variable, and the

src/runtime/metrics_test.go

@@ -499,6 +499,10 @@ func TestReadMetricsCumulative(t *testing.T) {
 		defer wg.Done()
 		for {
 			// Add more things here that could influence metrics.
+			for i := 0; i < 10; i++ {
+				runtime.AddCleanup(new(*int), func(_ struct{}) {}, struct{}{})
+				runtime.SetFinalizer(new(*int), func(_ **int) {})
+			}
 			for i := 0; i < len(readMetricsSink); i++ {
 				readMetricsSink[i] = make([]byte, 1024)
 				select {
@@ -1512,3 +1516,62 @@ func TestMetricHeapUnusedLargeObjectOverflow(t *testing.T) {
 	done <- struct{}{}
 	wg.Wait()
 }
+
+func TestReadMetricsCleanups(t *testing.T) {
+	runtime.GC()                                                // End any in-progress GC.
+	runtime.BlockUntilEmptyCleanupQueue(int64(1 * time.Second)) // Flush any queued cleanups.
+
+	var before [2]metrics.Sample
+	before[0].Name = "/gc/cleanups/queued:cleanups"
+	before[1].Name = "/gc/cleanups/executed:cleanups"
+	after := before
+
+	metrics.Read(before[:])
+
+	const N = 10
+	for i := 0; i < N; i++ {
+		runtime.AddCleanup(new(*int), func(_ struct{}) {}, struct{}{})
+	}
+
+	runtime.GC()
+	runtime.BlockUntilEmptyCleanupQueue(int64(1 * time.Second))
+
+	metrics.Read(after[:])
+
+	if v0, v1 := before[0].Value.Uint64(), after[0].Value.Uint64(); v0+N != v1 {
+		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[0].Name, N, v0, v1)
+	}
+	if v0, v1 := before[1].Value.Uint64(), after[1].Value.Uint64(); v0+N != v1 {
+		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[1].Name, N, v0, v1)
+	}
+}
+
+func TestReadMetricsFinalizers(t *testing.T) {
+	runtime.GC()                                                  // End any in-progress GC.
+	runtime.BlockUntilEmptyFinalizerQueue(int64(1 * time.Second)) // Flush any queued finalizers.
+
+	var before [2]metrics.Sample
+	before[0].Name = "/gc/finalizers/queued:finalizers"
+	before[1].Name = "/gc/finalizers/executed:finalizers"
+	after := before
+
+	metrics.Read(before[:])
+
+	const N = 10
+	for i := 0; i < N; i++ {
+		runtime.SetFinalizer(new(*int), func(_ **int) {})
+	}
+
+	runtime.GC()
+	runtime.GC()
+	runtime.BlockUntilEmptyFinalizerQueue(int64(1 * time.Second))
+
+	metrics.Read(after[:])
+
+	if v0, v1 := before[0].Value.Uint64(), after[0].Value.Uint64(); v0+N != v1 {
+		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[0].Name, N, v0, v1)
+	}
+	if v0, v1 := before[1].Value.Uint64(), after[1].Value.Uint64(); v0+N != v1 {
+		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[1].Name, N, v0, v1)
+	}
+}