Source file src/runtime/metrics_test.go

     1  // Copyright 2020 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  package runtime_test
     6  
     7  import (
     8  	"bytes"
     9  	"internal/abi"
    10  	"internal/goexperiment"
    11  	"internal/profile"
    12  	"internal/testenv"
    13  	"os"
    14  	"reflect"
    15  	"runtime"
    16  	"runtime/debug"
    17  	"runtime/metrics"
    18  	"runtime/pprof"
    19  	"runtime/trace"
    20  	"slices"
    21  	"sort"
    22  	"strings"
    23  	"sync"
    24  	"sync/atomic"
    25  	"testing"
    26  	"time"
    27  	"unsafe"
    28  )
    29  
    30  func prepareAllMetricsSamples() (map[string]metrics.Description, []metrics.Sample) {
    31  	all := metrics.All()
    32  	samples := make([]metrics.Sample, len(all))
    33  	descs := make(map[string]metrics.Description)
    34  	for i := range all {
    35  		samples[i].Name = all[i].Name
    36  		descs[all[i].Name] = all[i]
    37  	}
    38  	return descs, samples
    39  }
    40  
    41  func TestReadMetrics(t *testing.T) {
    42  	// Run a GC cycle to get some of the stats to be non-zero.
    43  	runtime.GC()
    44  
    45  	// Set an arbitrary memory limit to check the metric for it
    46  	limit := int64(512 * 1024 * 1024)
    47  	oldLimit := debug.SetMemoryLimit(limit)
    48  	defer debug.SetMemoryLimit(oldLimit)
    49  
    50  	// Set a GC percent to check the metric for it
    51  	gcPercent := 99
    52  	oldGCPercent := debug.SetGCPercent(gcPercent)
    53  	defer debug.SetGCPercent(oldGCPercent)
    54  
    55  	// Tests whether readMetrics produces values aligning
    56  	// with ReadMemStats while the world is stopped.
    57  	var mstats runtime.MemStats
    58  	_, samples := prepareAllMetricsSamples()
    59  	runtime.ReadMetricsSlow(&mstats, unsafe.Pointer(&samples[0]), len(samples), cap(samples))
    60  
    61  	checkUint64 := func(t *testing.T, m string, got, want uint64) {
    62  		t.Helper()
    63  		if got != want {
    64  			t.Errorf("metric %q: got %d, want %d", m, got, want)
    65  		}
    66  	}
    67  
    68  	// Check to make sure the values we read line up with other values we read.
    69  	var allocsBySize, gcPauses, schedPausesTotalGC *metrics.Float64Histogram
    70  	var tinyAllocs uint64
    71  	var mallocs, frees uint64
    72  	for i := range samples {
    73  		switch name := samples[i].Name; name {
    74  		case "/cgo/go-to-c-calls:calls":
    75  			checkUint64(t, name, samples[i].Value.Uint64(), uint64(runtime.NumCgoCall()))
    76  		case "/memory/classes/heap/free:bytes":
    77  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.HeapIdle-mstats.HeapReleased)
    78  		case "/memory/classes/heap/released:bytes":
    79  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.HeapReleased)
    80  		case "/memory/classes/heap/objects:bytes":
    81  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.HeapAlloc)
    82  		case "/memory/classes/heap/unused:bytes":
    83  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.HeapInuse-mstats.HeapAlloc)
    84  		case "/memory/classes/heap/stacks:bytes":
    85  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.StackInuse)
    86  		case "/memory/classes/metadata/mcache/free:bytes":
    87  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.MCacheSys-mstats.MCacheInuse)
    88  		case "/memory/classes/metadata/mcache/inuse:bytes":
    89  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.MCacheInuse)
    90  		case "/memory/classes/metadata/mspan/free:bytes":
    91  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.MSpanSys-mstats.MSpanInuse)
    92  		case "/memory/classes/metadata/mspan/inuse:bytes":
    93  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.MSpanInuse)
    94  		case "/memory/classes/metadata/other:bytes":
    95  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.GCSys)
    96  		case "/memory/classes/os-stacks:bytes":
    97  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.StackSys-mstats.StackInuse)
    98  		case "/memory/classes/other:bytes":
    99  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.OtherSys)
   100  		case "/memory/classes/profiling/buckets:bytes":
   101  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.BuckHashSys)
   102  		case "/memory/classes/total:bytes":
   103  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.Sys)
   104  		case "/gc/heap/allocs-by-size:bytes":
   105  			hist := samples[i].Value.Float64Histogram()
   106  			// Skip size class 0 in BySize, because it's always empty and not represented
   107  			// in the histogram.
   108  			for i, sc := range mstats.BySize[1:] {
   109  				if b, s := hist.Buckets[i+1], float64(sc.Size+1); b != s {
   110  					t.Errorf("bucket does not match size class: got %f, want %f", b, s)
   111  					// The rest of the checks aren't expected to work anyway.
   112  					continue
   113  				}
   114  				if c, m := hist.Counts[i], sc.Mallocs; c != m {
   115  					t.Errorf("histogram counts do not much BySize for class %d: got %d, want %d", i, c, m)
   116  				}
   117  			}
   118  			allocsBySize = hist
   119  		case "/gc/heap/allocs:bytes":
   120  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.TotalAlloc)
   121  		case "/gc/heap/frees-by-size:bytes":
   122  			hist := samples[i].Value.Float64Histogram()
   123  			// Skip size class 0 in BySize, because it's always empty and not represented
   124  			// in the histogram.
   125  			for i, sc := range mstats.BySize[1:] {
   126  				if b, s := hist.Buckets[i+1], float64(sc.Size+1); b != s {
   127  					t.Errorf("bucket does not match size class: got %f, want %f", b, s)
   128  					// The rest of the checks aren't expected to work anyway.
   129  					continue
   130  				}
   131  				if c, f := hist.Counts[i], sc.Frees; c != f {
   132  					t.Errorf("histogram counts do not match BySize for class %d: got %d, want %d", i, c, f)
   133  				}
   134  			}
   135  		case "/gc/heap/frees:bytes":
   136  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.TotalAlloc-mstats.HeapAlloc)
   137  		case "/gc/heap/tiny/allocs:objects":
   138  			// Currently, MemStats adds tiny alloc count to both Mallocs AND Frees.
   139  			// The reason for this is because MemStats couldn't be extended at the time
   140  			// but there was a desire to have Mallocs at least be a little more representative,
   141  			// while having Mallocs - Frees still represent a live object count.
   142  			// Unfortunately, MemStats doesn't actually export a large allocation count,
   143  			// so it's impossible to pull this number out directly.
   144  			//
   145  			// Check tiny allocation count outside of this loop, by using the allocs-by-size
   146  			// histogram in order to figure out how many large objects there are.
   147  			tinyAllocs = samples[i].Value.Uint64()
   148  			// Because the next two metrics tests are checking against Mallocs and Frees,
   149  			// we can't check them directly for the same reason: we need to account for tiny
   150  			// allocations included in Mallocs and Frees.
   151  		case "/gc/heap/allocs:objects":
   152  			mallocs = samples[i].Value.Uint64()
   153  		case "/gc/heap/frees:objects":
   154  			frees = samples[i].Value.Uint64()
   155  		case "/gc/heap/live:bytes":
   156  			// Check for "obviously wrong" values. We can't check a stronger invariant,
   157  			// such as live <= HeapAlloc, because live is not 100% accurate. It's computed
   158  			// under racy conditions, and some objects may be double-counted (this is
   159  			// intentional and necessary for GC performance).
   160  			//
   161  			// Instead, check against a much more reasonable upper-bound: the amount of
   162  			// mapped heap memory. We can't possibly overcount to the point of exceeding
   163  			// total mapped heap memory, except if there's an accounting bug.
   164  			if live := samples[i].Value.Uint64(); live > mstats.HeapSys {
   165  				t.Errorf("live bytes: %d > heap sys: %d", live, mstats.HeapSys)
   166  			} else if live == 0 {
   167  				// Might happen if we don't call runtime.GC() above.
   168  				t.Error("live bytes is 0")
   169  			}
   170  		case "/gc/gomemlimit:bytes":
   171  			checkUint64(t, name, samples[i].Value.Uint64(), uint64(limit))
   172  		case "/gc/heap/objects:objects":
   173  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.HeapObjects)
   174  		case "/gc/heap/goal:bytes":
   175  			checkUint64(t, name, samples[i].Value.Uint64(), mstats.NextGC)
   176  		case "/gc/gogc:percent":
   177  			checkUint64(t, name, samples[i].Value.Uint64(), uint64(gcPercent))
   178  		case "/gc/cycles/automatic:gc-cycles":
   179  			checkUint64(t, name, samples[i].Value.Uint64(), uint64(mstats.NumGC-mstats.NumForcedGC))
   180  		case "/gc/cycles/forced:gc-cycles":
   181  			checkUint64(t, name, samples[i].Value.Uint64(), uint64(mstats.NumForcedGC))
   182  		case "/gc/cycles/total:gc-cycles":
   183  			checkUint64(t, name, samples[i].Value.Uint64(), uint64(mstats.NumGC))
   184  		case "/gc/pauses:seconds":
   185  			gcPauses = samples[i].Value.Float64Histogram()
   186  		case "/sched/pauses/total/gc:seconds":
   187  			schedPausesTotalGC = samples[i].Value.Float64Histogram()
   188  		}
   189  	}
   190  
   191  	// Check tinyAllocs.
   192  	nonTinyAllocs := uint64(0)
   193  	for _, c := range allocsBySize.Counts {
   194  		nonTinyAllocs += c
   195  	}
   196  	checkUint64(t, "/gc/heap/tiny/allocs:objects", tinyAllocs, mstats.Mallocs-nonTinyAllocs)
   197  
   198  	// Check allocation and free counts.
   199  	checkUint64(t, "/gc/heap/allocs:objects", mallocs, mstats.Mallocs-tinyAllocs)
   200  	checkUint64(t, "/gc/heap/frees:objects", frees, mstats.Frees-tinyAllocs)
   201  
   202  	// Verify that /gc/pauses:seconds is a copy of /sched/pauses/total/gc:seconds
   203  	if !slices.Equal(gcPauses.Buckets, schedPausesTotalGC.Buckets) {
   204  		t.Errorf("/gc/pauses:seconds buckets %v do not match /sched/pauses/total/gc:seconds buckets %v", gcPauses.Buckets, schedPausesTotalGC.Counts)
   205  	}
   206  	if !slices.Equal(gcPauses.Counts, schedPausesTotalGC.Counts) {
   207  		t.Errorf("/gc/pauses:seconds counts %v do not match /sched/pauses/total/gc:seconds counts %v", gcPauses.Counts, schedPausesTotalGC.Counts)
   208  	}
   209  }
   210  
   211  func TestReadMetricsConsistency(t *testing.T) {
   212  	// Tests whether readMetrics produces consistent, sensible values.
   213  	// The values are read concurrently with the runtime doing other
   214  	// things (e.g. allocating) so what we read can't reasonably compared
   215  	// to other runtime values (e.g. MemStats).
   216  
   217  	// Run a few GC cycles to get some of the stats to be non-zero.
   218  	runtime.GC()
   219  	runtime.GC()
   220  	runtime.GC()
   221  
   222  	// Set GOMAXPROCS high then sleep briefly to ensure we generate
   223  	// some idle time.
   224  	oldmaxprocs := runtime.GOMAXPROCS(10)
   225  	time.Sleep(time.Millisecond)
   226  	runtime.GOMAXPROCS(oldmaxprocs)
   227  
   228  	// Read all the supported metrics through the metrics package.
   229  	descs, samples := prepareAllMetricsSamples()
   230  	metrics.Read(samples)
   231  
   232  	// Check to make sure the values we read make sense.
   233  	var totalVirtual struct {
   234  		got, want uint64
   235  	}
   236  	var objects struct {
   237  		alloc, free             *metrics.Float64Histogram
   238  		allocs, frees           uint64
   239  		allocdBytes, freedBytes uint64
   240  		total, totalBytes       uint64
   241  	}
   242  	var gc struct {
   243  		numGC  uint64
   244  		pauses uint64
   245  	}
   246  	var totalScan struct {
   247  		got, want uint64
   248  	}
   249  	var cpu struct {
   250  		gcAssist    float64
   251  		gcDedicated float64
   252  		gcIdle      float64
   253  		gcPause     float64
   254  		gcTotal     float64
   255  
   256  		idle float64
   257  		user float64
   258  
   259  		scavengeAssist float64
   260  		scavengeBg     float64
   261  		scavengeTotal  float64
   262  
   263  		total float64
   264  	}
   265  	for i := range samples {
   266  		kind := samples[i].Value.Kind()
   267  		if want := descs[samples[i].Name].Kind; kind != want {
   268  			t.Errorf("supported metric %q has unexpected kind: got %d, want %d", samples[i].Name, kind, want)
   269  			continue
   270  		}
   271  		if samples[i].Name != "/memory/classes/total:bytes" && strings.HasPrefix(samples[i].Name, "/memory/classes") {
   272  			v := samples[i].Value.Uint64()
   273  			totalVirtual.want += v
   274  
   275  			// None of these stats should ever get this big.
   276  			// If they do, there's probably overflow involved,
   277  			// usually due to bad accounting.
   278  			if int64(v) < 0 {
   279  				t.Errorf("%q has high/negative value: %d", samples[i].Name, v)
   280  			}
   281  		}
   282  		switch samples[i].Name {
   283  		case "/cpu/classes/gc/mark/assist:cpu-seconds":
   284  			cpu.gcAssist = samples[i].Value.Float64()
   285  		case "/cpu/classes/gc/mark/dedicated:cpu-seconds":
   286  			cpu.gcDedicated = samples[i].Value.Float64()
   287  		case "/cpu/classes/gc/mark/idle:cpu-seconds":
   288  			cpu.gcIdle = samples[i].Value.Float64()
   289  		case "/cpu/classes/gc/pause:cpu-seconds":
   290  			cpu.gcPause = samples[i].Value.Float64()
   291  		case "/cpu/classes/gc/total:cpu-seconds":
   292  			cpu.gcTotal = samples[i].Value.Float64()
   293  		case "/cpu/classes/idle:cpu-seconds":
   294  			cpu.idle = samples[i].Value.Float64()
   295  		case "/cpu/classes/scavenge/assist:cpu-seconds":
   296  			cpu.scavengeAssist = samples[i].Value.Float64()
   297  		case "/cpu/classes/scavenge/background:cpu-seconds":
   298  			cpu.scavengeBg = samples[i].Value.Float64()
   299  		case "/cpu/classes/scavenge/total:cpu-seconds":
   300  			cpu.scavengeTotal = samples[i].Value.Float64()
   301  		case "/cpu/classes/total:cpu-seconds":
   302  			cpu.total = samples[i].Value.Float64()
   303  		case "/cpu/classes/user:cpu-seconds":
   304  			cpu.user = samples[i].Value.Float64()
   305  		case "/memory/classes/total:bytes":
   306  			totalVirtual.got = samples[i].Value.Uint64()
   307  		case "/memory/classes/heap/objects:bytes":
   308  			objects.totalBytes = samples[i].Value.Uint64()
   309  		case "/gc/heap/objects:objects":
   310  			objects.total = samples[i].Value.Uint64()
   311  		case "/gc/heap/allocs:bytes":
   312  			objects.allocdBytes = samples[i].Value.Uint64()
   313  		case "/gc/heap/allocs:objects":
   314  			objects.allocs = samples[i].Value.Uint64()
   315  		case "/gc/heap/allocs-by-size:bytes":
   316  			objects.alloc = samples[i].Value.Float64Histogram()
   317  		case "/gc/heap/frees:bytes":
   318  			objects.freedBytes = samples[i].Value.Uint64()
   319  		case "/gc/heap/frees:objects":
   320  			objects.frees = samples[i].Value.Uint64()
   321  		case "/gc/heap/frees-by-size:bytes":
   322  			objects.free = samples[i].Value.Float64Histogram()
   323  		case "/gc/cycles:gc-cycles":
   324  			gc.numGC = samples[i].Value.Uint64()
   325  		case "/gc/pauses:seconds":
   326  			h := samples[i].Value.Float64Histogram()
   327  			gc.pauses = 0
   328  			for i := range h.Counts {
   329  				gc.pauses += h.Counts[i]
   330  			}
   331  		case "/gc/scan/heap:bytes":
   332  			totalScan.want += samples[i].Value.Uint64()
   333  		case "/gc/scan/globals:bytes":
   334  			totalScan.want += samples[i].Value.Uint64()
   335  		case "/gc/scan/stack:bytes":
   336  			totalScan.want += samples[i].Value.Uint64()
   337  		case "/gc/scan/total:bytes":
   338  			totalScan.got = samples[i].Value.Uint64()
   339  		case "/sched/gomaxprocs:threads":
   340  			if got, want := samples[i].Value.Uint64(), uint64(runtime.GOMAXPROCS(-1)); got != want {
   341  				t.Errorf("gomaxprocs doesn't match runtime.GOMAXPROCS: got %d, want %d", got, want)
   342  			}
   343  		case "/sched/goroutines:goroutines":
   344  			if samples[i].Value.Uint64() < 1 {
   345  				t.Error("number of goroutines is less than one")
   346  			}
   347  		}
   348  	}
   349  	// Only check this on Linux where we can be reasonably sure we have a high-resolution timer.
   350  	if runtime.GOOS == "linux" {
   351  		if cpu.gcDedicated <= 0 && cpu.gcAssist <= 0 && cpu.gcIdle <= 0 {
   352  			t.Errorf("found no time spent on GC work: %#v", cpu)
   353  		}
   354  		if cpu.gcPause <= 0 {
   355  			t.Errorf("found no GC pauses: %f", cpu.gcPause)
   356  		}
   357  		if cpu.idle <= 0 {
   358  			t.Errorf("found no idle time: %f", cpu.idle)
   359  		}
   360  		if total := cpu.gcDedicated + cpu.gcAssist + cpu.gcIdle + cpu.gcPause; !withinEpsilon(cpu.gcTotal, total, 0.001) {
   361  			t.Errorf("calculated total GC CPU time not within %%0.1 of total: %f vs. %f", total, cpu.gcTotal)
   362  		}
   363  		if total := cpu.scavengeAssist + cpu.scavengeBg; !withinEpsilon(cpu.scavengeTotal, total, 0.001) {
   364  			t.Errorf("calculated total scavenge CPU not within %%0.1 of total: %f vs. %f", total, cpu.scavengeTotal)
   365  		}
   366  		if cpu.total <= 0 {
   367  			t.Errorf("found no total CPU time passed")
   368  		}
   369  		if cpu.user <= 0 {
   370  			t.Errorf("found no user time passed")
   371  		}
   372  		if total := cpu.gcTotal + cpu.scavengeTotal + cpu.user + cpu.idle; !withinEpsilon(cpu.total, total, 0.001) {
   373  			t.Errorf("calculated total CPU not within %%0.1 of total: %f vs. %f", total, cpu.total)
   374  		}
   375  	}
   376  	if totalVirtual.got != totalVirtual.want {
   377  		t.Errorf(`"/memory/classes/total:bytes" does not match sum of /memory/classes/**: got %d, want %d`, totalVirtual.got, totalVirtual.want)
   378  	}
   379  	if got, want := objects.allocs-objects.frees, objects.total; got != want {
   380  		t.Errorf("mismatch between object alloc/free tallies and total: got %d, want %d", got, want)
   381  	}
   382  	if got, want := objects.allocdBytes-objects.freedBytes, objects.totalBytes; got != want {
   383  		t.Errorf("mismatch between object alloc/free tallies and total: got %d, want %d", got, want)
   384  	}
   385  	if b, c := len(objects.alloc.Buckets), len(objects.alloc.Counts); b != c+1 {
   386  		t.Errorf("allocs-by-size has wrong bucket or counts length: %d buckets, %d counts", b, c)
   387  	}
   388  	if b, c := len(objects.free.Buckets), len(objects.free.Counts); b != c+1 {
   389  		t.Errorf("frees-by-size has wrong bucket or counts length: %d buckets, %d counts", b, c)
   390  	}
   391  	if len(objects.alloc.Buckets) != len(objects.free.Buckets) {
   392  		t.Error("allocs-by-size and frees-by-size buckets don't match in length")
   393  	} else if len(objects.alloc.Counts) != len(objects.free.Counts) {
   394  		t.Error("allocs-by-size and frees-by-size counts don't match in length")
   395  	} else {
   396  		for i := range objects.alloc.Buckets {
   397  			ba := objects.alloc.Buckets[i]
   398  			bf := objects.free.Buckets[i]
   399  			if ba != bf {
   400  				t.Errorf("bucket %d is different for alloc and free hists: %f != %f", i, ba, bf)
   401  			}
   402  		}
   403  		if !t.Failed() {
   404  			var gotAlloc, gotFree uint64
   405  			want := objects.total
   406  			for i := range objects.alloc.Counts {
   407  				if objects.alloc.Counts[i] < objects.free.Counts[i] {
   408  					t.Errorf("found more allocs than frees in object dist bucket %d", i)
   409  					continue
   410  				}
   411  				gotAlloc += objects.alloc.Counts[i]
   412  				gotFree += objects.free.Counts[i]
   413  			}
   414  			if got := gotAlloc - gotFree; got != want {
   415  				t.Errorf("object distribution counts don't match count of live objects: got %d, want %d", got, want)
   416  			}
   417  			if gotAlloc != objects.allocs {
   418  				t.Errorf("object distribution counts don't match total allocs: got %d, want %d", gotAlloc, objects.allocs)
   419  			}
   420  			if gotFree != objects.frees {
   421  				t.Errorf("object distribution counts don't match total allocs: got %d, want %d", gotFree, objects.frees)
   422  			}
   423  		}
   424  	}
   425  	// The current GC has at least 2 pauses per GC.
   426  	// Check to see if that value makes sense.
   427  	if gc.pauses < gc.numGC*2 {
   428  		t.Errorf("fewer pauses than expected: got %d, want at least %d", gc.pauses, gc.numGC*2)
   429  	}
   430  	if totalScan.got <= 0 {
   431  		t.Errorf("scannable GC space is empty: %d", totalScan.got)
   432  	}
   433  	if totalScan.got != totalScan.want {
   434  		t.Errorf("/gc/scan/total:bytes doesn't line up with sum of /gc/scan*: total %d vs. sum %d", totalScan.got, totalScan.want)
   435  	}
   436  }
   437  
   438  func BenchmarkReadMetricsLatency(b *testing.B) {
   439  	stop := applyGCLoad(b)
   440  
   441  	// Spend this much time measuring latencies.
   442  	latencies := make([]time.Duration, 0, 1024)
   443  	_, samples := prepareAllMetricsSamples()
   444  
   445  	// Hit metrics.Read continuously and measure.
   446  	b.ResetTimer()
   447  	for i := 0; i < b.N; i++ {
   448  		start := time.Now()
   449  		metrics.Read(samples)
   450  		latencies = append(latencies, time.Since(start))
   451  	}
   452  	// Make sure to stop the timer before we wait! The load created above
   453  	// is very heavy-weight and not easy to stop, so we could end up
   454  	// confusing the benchmarking framework for small b.N.
   455  	b.StopTimer()
   456  	stop()
   457  
   458  	// Disable the default */op metrics.
   459  	// ns/op doesn't mean anything because it's an average, but we
   460  	// have a sleep in our b.N loop above which skews this significantly.
   461  	b.ReportMetric(0, "ns/op")
   462  	b.ReportMetric(0, "B/op")
   463  	b.ReportMetric(0, "allocs/op")
   464  
   465  	// Sort latencies then report percentiles.
   466  	sort.Slice(latencies, func(i, j int) bool {
   467  		return latencies[i] < latencies[j]
   468  	})
   469  	b.ReportMetric(float64(latencies[len(latencies)*50/100]), "p50-ns")
   470  	b.ReportMetric(float64(latencies[len(latencies)*90/100]), "p90-ns")
   471  	b.ReportMetric(float64(latencies[len(latencies)*99/100]), "p99-ns")
   472  }
   473  
   474  var readMetricsSink [1024]any
   475  
   476  func TestReadMetricsCumulative(t *testing.T) {
   477  	// Set up the set of metrics marked cumulative.
   478  	descs := metrics.All()
   479  	var samples [2][]metrics.Sample
   480  	samples[0] = make([]metrics.Sample, len(descs))
   481  	samples[1] = make([]metrics.Sample, len(descs))
   482  	total := 0
   483  	for i := range samples[0] {
   484  		if !descs[i].Cumulative {
   485  			continue
   486  		}
   487  		samples[0][total].Name = descs[i].Name
   488  		total++
   489  	}
   490  	samples[0] = samples[0][:total]
   491  	samples[1] = samples[1][:total]
   492  	copy(samples[1], samples[0])
   493  
   494  	// Start some noise in the background.
   495  	var wg sync.WaitGroup
   496  	wg.Add(1)
   497  	done := make(chan struct{})
   498  	go func() {
   499  		defer wg.Done()
   500  		for {
   501  			// Add more things here that could influence metrics.
   502  			for i := 0; i < 10; i++ {
   503  				runtime.AddCleanup(new(*int), func(_ struct{}) {}, struct{}{})
   504  				runtime.SetFinalizer(new(*int), func(_ **int) {})
   505  			}
   506  			for i := 0; i < len(readMetricsSink); i++ {
   507  				readMetricsSink[i] = make([]byte, 1024)
   508  				select {
   509  				case <-done:
   510  					return
   511  				default:
   512  				}
   513  			}
   514  			runtime.GC()
   515  		}
   516  	}()
   517  
   518  	sum := func(us []uint64) uint64 {
   519  		total := uint64(0)
   520  		for _, u := range us {
   521  			total += u
   522  		}
   523  		return total
   524  	}
   525  
   526  	// Populate the first generation.
   527  	metrics.Read(samples[0])
   528  
   529  	// Check to make sure that these metrics only grow monotonically.
   530  	for gen := 1; gen < 10; gen++ {
   531  		metrics.Read(samples[gen%2])
   532  		for i := range samples[gen%2] {
   533  			name := samples[gen%2][i].Name
   534  			vNew, vOld := samples[gen%2][i].Value, samples[1-(gen%2)][i].Value
   535  
   536  			switch vNew.Kind() {
   537  			case metrics.KindUint64:
   538  				new := vNew.Uint64()
   539  				old := vOld.Uint64()
   540  				if new < old {
   541  					t.Errorf("%s decreased: %d < %d", name, new, old)
   542  				}
   543  			case metrics.KindFloat64:
   544  				new := vNew.Float64()
   545  				old := vOld.Float64()
   546  				if new < old {
   547  					t.Errorf("%s decreased: %f < %f", name, new, old)
   548  				}
   549  			case metrics.KindFloat64Histogram:
   550  				new := sum(vNew.Float64Histogram().Counts)
   551  				old := sum(vOld.Float64Histogram().Counts)
   552  				if new < old {
   553  					t.Errorf("%s counts decreased: %d < %d", name, new, old)
   554  				}
   555  			}
   556  		}
   557  	}
   558  	close(done)
   559  
   560  	wg.Wait()
   561  }
   562  
   563  func withinEpsilon(v1, v2, e float64) bool {
   564  	return v2-v2*e <= v1 && v1 <= v2+v2*e
   565  }
   566  
   567  func TestMutexWaitTimeMetric(t *testing.T) {
   568  	var sample [1]metrics.Sample
   569  	sample[0].Name = "/sync/mutex/wait/total:seconds"
   570  
   571  	locks := []locker2{
   572  		new(mutex),
   573  		new(rwmutexWrite),
   574  		new(rwmutexReadWrite),
   575  		new(rwmutexWriteRead),
   576  	}
   577  	for _, lock := range locks {
   578  		t.Run(reflect.TypeOf(lock).Elem().Name(), func(t *testing.T) {
   579  			metrics.Read(sample[:])
   580  			before := time.Duration(sample[0].Value.Float64() * 1e9)
   581  
   582  			minMutexWaitTime := generateMutexWaitTime(lock)
   583  
   584  			metrics.Read(sample[:])
   585  			after := time.Duration(sample[0].Value.Float64() * 1e9)
   586  
   587  			if wt := after - before; wt < minMutexWaitTime {
   588  				t.Errorf("too little mutex wait time: got %s, want %s", wt, minMutexWaitTime)
   589  			}
   590  		})
   591  	}
   592  }
   593  
   594  // locker2 represents an API surface of two concurrent goroutines
   595  // locking the same resource, but through different APIs. It's intended
   596  // to abstract over the relationship of two Lock calls or an RLock
   597  // and a Lock call.
   598  type locker2 interface {
   599  	Lock1()
   600  	Unlock1()
   601  	Lock2()
   602  	Unlock2()
   603  }
   604  
   605  type mutex struct {
   606  	mu sync.Mutex
   607  }
   608  
   609  func (m *mutex) Lock1()   { m.mu.Lock() }
   610  func (m *mutex) Unlock1() { m.mu.Unlock() }
   611  func (m *mutex) Lock2()   { m.mu.Lock() }
   612  func (m *mutex) Unlock2() { m.mu.Unlock() }
   613  
   614  type rwmutexWrite struct {
   615  	mu sync.RWMutex
   616  }
   617  
   618  func (m *rwmutexWrite) Lock1()   { m.mu.Lock() }
   619  func (m *rwmutexWrite) Unlock1() { m.mu.Unlock() }
   620  func (m *rwmutexWrite) Lock2()   { m.mu.Lock() }
   621  func (m *rwmutexWrite) Unlock2() { m.mu.Unlock() }
   622  
   623  type rwmutexReadWrite struct {
   624  	mu sync.RWMutex
   625  }
   626  
   627  func (m *rwmutexReadWrite) Lock1()   { m.mu.RLock() }
   628  func (m *rwmutexReadWrite) Unlock1() { m.mu.RUnlock() }
   629  func (m *rwmutexReadWrite) Lock2()   { m.mu.Lock() }
   630  func (m *rwmutexReadWrite) Unlock2() { m.mu.Unlock() }
   631  
   632  type rwmutexWriteRead struct {
   633  	mu sync.RWMutex
   634  }
   635  
   636  func (m *rwmutexWriteRead) Lock1()   { m.mu.Lock() }
   637  func (m *rwmutexWriteRead) Unlock1() { m.mu.Unlock() }
   638  func (m *rwmutexWriteRead) Lock2()   { m.mu.RLock() }
   639  func (m *rwmutexWriteRead) Unlock2() { m.mu.RUnlock() }
   640  
   641  // generateMutexWaitTime causes a couple of goroutines
   642  // to block a whole bunch of times on a sync.Mutex, returning
   643  // the minimum amount of time that should be visible in the
   644  // /sync/mutex-wait:seconds metric.
   645  func generateMutexWaitTime(mu locker2) time.Duration {
   646  	// Set up the runtime to always track casgstatus transitions for metrics.
   647  	*runtime.CasGStatusAlwaysTrack = true
   648  
   649  	mu.Lock1()
   650  
   651  	// Start up a goroutine to wait on the lock.
   652  	gc := make(chan *runtime.G)
   653  	done := make(chan bool)
   654  	go func() {
   655  		gc <- runtime.Getg()
   656  
   657  		for {
   658  			mu.Lock2()
   659  			mu.Unlock2()
   660  			if <-done {
   661  				return
   662  			}
   663  		}
   664  	}()
   665  	gp := <-gc
   666  
   667  	// Set the block time high enough so that it will always show up, even
   668  	// on systems with coarse timer granularity.
   669  	const blockTime = 100 * time.Millisecond
   670  
   671  	// Make sure the goroutine spawned above actually blocks on the lock.
   672  	for {
   673  		if runtime.GIsWaitingOnMutex(gp) {
   674  			break
   675  		}
   676  		runtime.Gosched()
   677  	}
   678  
   679  	// Let some amount of time pass.
   680  	time.Sleep(blockTime)
   681  
   682  	// Let the other goroutine acquire the lock.
   683  	mu.Unlock1()
   684  	done <- true
   685  
   686  	// Reset flag.
   687  	*runtime.CasGStatusAlwaysTrack = false
   688  	return blockTime
   689  }
   690  
   691  // See issue #60276.
   692  func TestCPUMetricsSleep(t *testing.T) {
   693  	if runtime.GOOS == "wasip1" {
   694  		// Since wasip1 busy-waits in the scheduler, there's no meaningful idle
   695  		// time. This is accurately reflected in the metrics, but it means this
   696  		// test is basically meaningless on this platform.
   697  		t.Skip("wasip1 currently busy-waits in idle time; test not applicable")
   698  	}
   699  
   700  	names := []string{
   701  		"/cpu/classes/idle:cpu-seconds",
   702  
   703  		"/cpu/classes/gc/mark/assist:cpu-seconds",
   704  		"/cpu/classes/gc/mark/dedicated:cpu-seconds",
   705  		"/cpu/classes/gc/mark/idle:cpu-seconds",
   706  		"/cpu/classes/gc/pause:cpu-seconds",
   707  		"/cpu/classes/gc/total:cpu-seconds",
   708  		"/cpu/classes/scavenge/assist:cpu-seconds",
   709  		"/cpu/classes/scavenge/background:cpu-seconds",
   710  		"/cpu/classes/scavenge/total:cpu-seconds",
   711  		"/cpu/classes/total:cpu-seconds",
   712  		"/cpu/classes/user:cpu-seconds",
   713  	}
   714  	prep := func() []metrics.Sample {
   715  		mm := make([]metrics.Sample, len(names))
   716  		for i := range names {
   717  			mm[i].Name = names[i]
   718  		}
   719  		return mm
   720  	}
   721  	m1, m2 := prep(), prep()
   722  
   723  	const (
   724  		// Expected time spent idle.
   725  		dur = 100 * time.Millisecond
   726  
   727  		// maxFailures is the number of consecutive failures requires to cause the test to fail.
   728  		maxFailures = 10
   729  	)
   730  
   731  	failureIdleTimes := make([]float64, 0, maxFailures)
   732  
   733  	// If the bug we expect is happening, then the Sleep CPU time will be accounted for
   734  	// as user time rather than idle time. In an ideal world we'd expect the whole application
   735  	// to go instantly idle the moment this goroutine goes to sleep, and stay asleep for that
   736  	// duration. However, the Go runtime can easily eat into idle time while this goroutine is
   737  	// blocked in a sleep. For example, slow platforms might spend more time expected in the
   738  	// scheduler. Another example is that a Go runtime background goroutine could run while
   739  	// everything else is idle. Lastly, if a running goroutine is descheduled by the OS, enough
   740  	// time may pass such that the goroutine is ready to wake, even though the runtime couldn't
   741  	// observe itself as idle with nanotime.
   742  	//
   743  	// To deal with all this, we give a half-proc's worth of leniency.
   744  	//
   745  	// We also retry multiple times to deal with the fact that the OS might deschedule us before
   746  	// we yield and go idle. That has a rare enough chance that retries should resolve it.
   747  	// If the issue we expect is happening, it should be persistent.
   748  	minIdleCPUSeconds := dur.Seconds() * (float64(runtime.GOMAXPROCS(-1)) - 0.5)
   749  
   750  	// Let's make sure there's no background scavenge work to do.
   751  	//
   752  	// The runtime.GC calls below ensure the background sweeper
   753  	// will not run during the idle period.
   754  	debug.FreeOSMemory()
   755  
   756  	for retries := 0; retries < maxFailures; retries++ {
   757  		// Read 1.
   758  		runtime.GC() // Update /cpu/classes metrics.
   759  		metrics.Read(m1)
   760  
   761  		// Sleep.
   762  		time.Sleep(dur)
   763  
   764  		// Read 2.
   765  		runtime.GC() // Update /cpu/classes metrics.
   766  		metrics.Read(m2)
   767  
   768  		dt := m2[0].Value.Float64() - m1[0].Value.Float64()
   769  		if dt >= minIdleCPUSeconds {
   770  			// All is well. Test passed.
   771  			return
   772  		}
   773  		failureIdleTimes = append(failureIdleTimes, dt)
   774  		// Try again.
   775  	}
   776  
   777  	// We couldn't observe the expected idle time even once.
   778  	for i, dt := range failureIdleTimes {
   779  		t.Logf("try %2d: idle time = %.5fs\n", i+1, dt)
   780  	}
   781  	t.Logf("try %d breakdown:\n", len(failureIdleTimes))
   782  	for i := range names {
   783  		if m1[i].Value.Kind() == metrics.KindBad {
   784  			continue
   785  		}
   786  		t.Logf("\t%s %0.3f\n", names[i], m2[i].Value.Float64()-m1[i].Value.Float64())
   787  	}
   788  	t.Errorf(`time.Sleep did not contribute enough to "idle" class: minimum idle time = %.5fs`, minIdleCPUSeconds)
   789  }
   790  
   791  // Call f() and verify that the correct STW metrics increment. If isGC is true,
   792  // fn triggers a GC STW. If isOther is true, fn triggers an other STW. If both
   793  // are false, fn does not trigger any STW.
   794  func testSchedPauseMetrics(t *testing.T, fn func(t *testing.T), isGC, isOther bool) {
   795  	m := []metrics.Sample{
   796  		{Name: "/sched/pauses/stopping/gc:seconds"},
   797  		{Name: "/sched/pauses/stopping/other:seconds"},
   798  		{Name: "/sched/pauses/total/gc:seconds"},
   799  		{Name: "/sched/pauses/total/other:seconds"},
   800  	}
   801  
   802  	stoppingGC := &m[0]
   803  	stoppingOther := &m[1]
   804  	totalGC := &m[2]
   805  	totalOther := &m[3]
   806  
   807  	sampleCount := func(s *metrics.Sample) uint64 {
   808  		h := s.Value.Float64Histogram()
   809  
   810  		var n uint64
   811  		for _, c := range h.Counts {
   812  			n += c
   813  		}
   814  		return n
   815  	}
   816  
   817  	// Read baseline.
   818  	metrics.Read(m)
   819  
   820  	baselineStartGC := sampleCount(stoppingGC)
   821  	baselineStartOther := sampleCount(stoppingOther)
   822  	baselineTotalGC := sampleCount(totalGC)
   823  	baselineTotalOther := sampleCount(totalOther)
   824  
   825  	fn(t)
   826  
   827  	metrics.Read(m)
   828  
   829  	if isGC {
   830  		if got := sampleCount(stoppingGC); got <= baselineStartGC {
   831  			t.Errorf("/sched/pauses/stopping/gc:seconds sample count %d did not increase from baseline of %d", got, baselineStartGC)
   832  		}
   833  		if got := sampleCount(totalGC); got <= baselineTotalGC {
   834  			t.Errorf("/sched/pauses/total/gc:seconds sample count %d did not increase from baseline of %d", got, baselineTotalGC)
   835  		}
   836  	} else {
   837  		if got := sampleCount(stoppingGC); got != baselineStartGC {
   838  			t.Errorf("/sched/pauses/stopping/gc:seconds sample count %d changed from baseline of %d", got, baselineStartGC)
   839  		}
   840  		if got := sampleCount(totalGC); got != baselineTotalGC {
   841  			t.Errorf("/sched/pauses/total/gc:seconds sample count %d changed from baseline of %d", got, baselineTotalGC)
   842  		}
   843  	}
   844  
   845  	if isOther {
   846  		if got := sampleCount(stoppingOther); got <= baselineStartOther {
   847  			t.Errorf("/sched/pauses/stopping/other:seconds sample count %d did not increase from baseline of %d", got, baselineStartOther)
   848  		}
   849  		if got := sampleCount(totalOther); got <= baselineTotalOther {
   850  			t.Errorf("/sched/pauses/total/other:seconds sample count %d did not increase from baseline of %d", got, baselineTotalOther)
   851  		}
   852  	} else {
   853  		if got := sampleCount(stoppingOther); got != baselineStartOther {
   854  			t.Errorf("/sched/pauses/stopping/other:seconds sample count %d changed from baseline of %d", got, baselineStartOther)
   855  		}
   856  		if got := sampleCount(totalOther); got != baselineTotalOther {
   857  			t.Errorf("/sched/pauses/total/other:seconds sample count %d changed from baseline of %d", got, baselineTotalOther)
   858  		}
   859  	}
   860  }
   861  
   862  func TestSchedPauseMetrics(t *testing.T) {
   863  	tests := []struct {
   864  		name   string
   865  		isGC   bool
   866  		isNone bool // no STW at all
   867  		fn     func(t *testing.T)
   868  	}{
   869  		{
   870  			name:   "runtime/metrics.Read",
   871  			isNone: true,
   872  			fn: func(t *testing.T) {
   873  				descs := metrics.All()
   874  				allSamples := make([]metrics.Sample, len(descs))
   875  				for i := range allSamples {
   876  					allSamples[i].Name = descs[i].Name
   877  				}
   878  				metrics.Read(allSamples)
   879  			},
   880  		},
   881  		{
   882  			name: "runtime.GC",
   883  			isGC: true,
   884  			fn: func(t *testing.T) {
   885  				runtime.GC()
   886  			},
   887  		},
   888  		{
   889  			name: "runtime.GOMAXPROCS",
   890  			fn: func(t *testing.T) {
   891  				if runtime.GOARCH == "wasm" {
   892  					t.Skip("GOMAXPROCS >1 not supported on wasm")
   893  				}
   894  
   895  				n := runtime.GOMAXPROCS(0)
   896  				defer runtime.GOMAXPROCS(n)
   897  
   898  				runtime.GOMAXPROCS(n + 1)
   899  			},
   900  		},
   901  		{
   902  			name: "runtime.GoroutineProfile",
   903  			fn: func(t *testing.T) {
   904  				var s [1]runtime.StackRecord
   905  				runtime.GoroutineProfile(s[:])
   906  			},
   907  		},
   908  		{
   909  			name: "runtime.ReadMemStats",
   910  			fn: func(t *testing.T) {
   911  				var mstats runtime.MemStats
   912  				runtime.ReadMemStats(&mstats)
   913  			},
   914  		},
   915  		{
   916  			name: "runtime.Stack",
   917  			fn: func(t *testing.T) {
   918  				var b [64]byte
   919  				runtime.Stack(b[:], true)
   920  			},
   921  		},
   922  		{
   923  			name: "runtime/debug.WriteHeapDump",
   924  			fn: func(t *testing.T) {
   925  				if runtime.GOOS == "js" {
   926  					t.Skip("WriteHeapDump not supported on js")
   927  				}
   928  
   929  				f, err := os.CreateTemp(t.TempDir(), "heapdumptest")
   930  				if err != nil {
   931  					t.Fatalf("os.CreateTemp failed: %v", err)
   932  				}
   933  				defer os.Remove(f.Name())
   934  				defer f.Close()
   935  				debug.WriteHeapDump(f.Fd())
   936  			},
   937  		},
   938  		{
   939  			name: "runtime/trace.Start",
   940  			fn: func(t *testing.T) {
   941  				if trace.IsEnabled() {
   942  					t.Skip("tracing already enabled")
   943  				}
   944  
   945  				var buf bytes.Buffer
   946  				if err := trace.Start(&buf); err != nil {
   947  					t.Errorf("trace.Start err got %v want nil", err)
   948  				}
   949  				trace.Stop()
   950  			},
   951  		},
   952  	}
   953  
   954  	// These tests count STW pauses, classified based on whether they're related
   955  	// to the GC or not. Disable automatic GC cycles during the test so we don't
   956  	// have an incidental GC pause when we're trying to observe only
   957  	// non-GC-related pauses. This is especially important for the
   958  	// runtime/trace.Start test, since (as of this writing) that will block
   959  	// until any active GC mark phase completes.
   960  	defer debug.SetGCPercent(debug.SetGCPercent(-1))
   961  	runtime.GC()
   962  
   963  	for _, tc := range tests {
   964  		t.Run(tc.name, func(t *testing.T) {
   965  			isOther := !tc.isGC && !tc.isNone
   966  			testSchedPauseMetrics(t, tc.fn, tc.isGC, isOther)
   967  		})
   968  	}
   969  }
   970  
   971  func TestRuntimeLockMetricsAndProfile(t *testing.T) {
   972  	old := runtime.SetMutexProfileFraction(0) // enabled during sub-tests
   973  	defer runtime.SetMutexProfileFraction(old)
   974  	if old != 0 {
   975  		t.Fatalf("need MutexProfileRate 0, got %d", old)
   976  	}
   977  
   978  	t.Logf("NumCPU %d", runtime.NumCPU())
   979  	t.Logf("GOMAXPROCS %d", runtime.GOMAXPROCS(0))
   980  	if minCPU := 2; runtime.NumCPU() < minCPU {
   981  		t.Skipf("creating and observing contention on runtime-internal locks requires NumCPU >= %d", minCPU)
   982  	}
   983  
   984  	loadProfile := func(t *testing.T) *profile.Profile {
   985  		var w bytes.Buffer
   986  		pprof.Lookup("mutex").WriteTo(&w, 0)
   987  		p, err := profile.Parse(&w)
   988  		if err != nil {
   989  			t.Fatalf("failed to parse profile: %v", err)
   990  		}
   991  		if err := p.CheckValid(); err != nil {
   992  			t.Fatalf("invalid profile: %v", err)
   993  		}
   994  		return p
   995  	}
   996  
   997  	measureDelta := func(t *testing.T, fn func()) (metricGrowth, profileGrowth float64, p *profile.Profile) {
   998  		beforeProfile := loadProfile(t)
   999  		beforeMetrics := []metrics.Sample{{Name: "/sync/mutex/wait/total:seconds"}}
  1000  		metrics.Read(beforeMetrics)
  1001  
  1002  		fn()
  1003  
  1004  		afterProfile := loadProfile(t)
  1005  		afterMetrics := []metrics.Sample{{Name: "/sync/mutex/wait/total:seconds"}}
  1006  		metrics.Read(afterMetrics)
  1007  
  1008  		sumSamples := func(p *profile.Profile, i int) int64 {
  1009  			var sum int64
  1010  			for _, s := range p.Sample {
  1011  				sum += s.Value[i]
  1012  			}
  1013  			return sum
  1014  		}
  1015  
  1016  		metricGrowth = afterMetrics[0].Value.Float64() - beforeMetrics[0].Value.Float64()
  1017  		profileGrowth = float64(sumSamples(afterProfile, 1)-sumSamples(beforeProfile, 1)) * time.Nanosecond.Seconds()
  1018  
  1019  		// The internal/profile package does not support compaction; this delta
  1020  		// profile will include separate positive and negative entries.
  1021  		p = afterProfile.Copy()
  1022  		if len(beforeProfile.Sample) > 0 {
  1023  			err := p.Merge(beforeProfile, -1)
  1024  			if err != nil {
  1025  				t.Fatalf("Merge profiles: %v", err)
  1026  			}
  1027  		}
  1028  
  1029  		return metricGrowth, profileGrowth, p
  1030  	}
  1031  
  1032  	testcase := func(strictTiming bool, acceptStacks [][]string, workers int, fn func() bool) func(t *testing.T) (metricGrowth float64, profileGrowth []int64, n, value int64, explain func()) {
  1033  		return func(t *testing.T) (metricGrowth float64, profileGrowth []int64, n, value int64, explain func()) {
  1034  			metricGrowth, totalProfileGrowth, p := measureDelta(t, func() {
  1035  				var started, stopped sync.WaitGroup
  1036  				started.Add(workers)
  1037  				stopped.Add(workers)
  1038  				for i := 0; i < workers; i++ {
  1039  					w := &contentionWorker{
  1040  						before: func() {
  1041  							started.Done()
  1042  							started.Wait()
  1043  						},
  1044  						after: func() {
  1045  							stopped.Done()
  1046  						},
  1047  						fn: fn,
  1048  					}
  1049  					go w.run()
  1050  				}
  1051  				stopped.Wait()
  1052  			})
  1053  
  1054  			if totalProfileGrowth == 0 {
  1055  				t.Errorf("no increase in mutex profile")
  1056  			}
  1057  			if metricGrowth == 0 && strictTiming {
  1058  				// If the critical section is very short, systems with low timer
  1059  				// resolution may be unable to measure it via nanotime.
  1060  				//
  1061  				// This is sampled at 1 per gTrackingPeriod, but the explicit
  1062  				// runtime.mutex tests create 200 contention events. Observing
  1063  				// zero of those has a probability of (7/8)^200 = 2.5e-12 which
  1064  				// is acceptably low (though the calculation has a tenuous
  1065  				// dependency on cheaprandn being a good-enough source of
  1066  				// entropy).
  1067  				t.Errorf("no increase in /sync/mutex/wait/total:seconds metric")
  1068  			}
  1069  			// This comparison is possible because the time measurements in support of
  1070  			// runtime/pprof and runtime/metrics for runtime-internal locks are so close
  1071  			// together. It doesn't work as well for user-space contention, where the
  1072  			// involved goroutines are not _Grunnable the whole time and so need to pass
  1073  			// through the scheduler.
  1074  			t.Logf("lock contention growth in runtime/pprof's view  (%fs)", totalProfileGrowth)
  1075  			t.Logf("lock contention growth in runtime/metrics' view (%fs)", metricGrowth)
  1076  
  1077  			acceptStacks = append([][]string(nil), acceptStacks...)
  1078  			for i, stk := range acceptStacks {
  1079  				if goexperiment.StaticLockRanking {
  1080  					if !slices.ContainsFunc(stk, func(s string) bool {
  1081  						return s == "runtime.systemstack" || s == "runtime.mcall" || s == "runtime.mstart"
  1082  					}) {
  1083  						// stk is a call stack that is still on the user stack when
  1084  						// it calls runtime.unlock. Add the extra function that
  1085  						// we'll see, when the static lock ranking implementation of
  1086  						// runtime.unlockWithRank switches to the system stack.
  1087  						stk = append([]string{"runtime.unlockWithRank"}, stk...)
  1088  					}
  1089  				}
  1090  				acceptStacks[i] = stk
  1091  			}
  1092  
  1093  			var stks [][]string
  1094  			values := make([][2]int64, len(acceptStacks)+1)
  1095  			for _, s := range p.Sample {
  1096  				var have []string
  1097  				for _, loc := range s.Location {
  1098  					for _, line := range loc.Line {
  1099  						have = append(have, line.Function.Name)
  1100  					}
  1101  				}
  1102  				stks = append(stks, have)
  1103  				found := false
  1104  				for i, stk := range acceptStacks {
  1105  					if slices.Equal(have, stk) {
  1106  						values[i][0] += s.Value[0]
  1107  						values[i][1] += s.Value[1]
  1108  						found = true
  1109  						break
  1110  					}
  1111  				}
  1112  				if !found {
  1113  					values[len(values)-1][0] += s.Value[0]
  1114  					values[len(values)-1][1] += s.Value[1]
  1115  				}
  1116  			}
  1117  			profileGrowth = make([]int64, len(acceptStacks)+1)
  1118  			profileGrowth[len(profileGrowth)-1] = values[len(values)-1][1]
  1119  			for i, stk := range acceptStacks {
  1120  				n += values[i][0]
  1121  				value += values[i][1]
  1122  				profileGrowth[i] = values[i][1]
  1123  				t.Logf("stack %v has samples totaling n=%d value=%d", stk, values[i][0], values[i][1])
  1124  			}
  1125  			if n == 0 && value == 0 {
  1126  				t.Logf("profile:\n%s", p)
  1127  				for _, have := range stks {
  1128  					t.Logf("have stack %v", have)
  1129  				}
  1130  				for _, stk := range acceptStacks {
  1131  					t.Errorf("want stack %v", stk)
  1132  				}
  1133  			}
  1134  
  1135  			return metricGrowth, profileGrowth, n, value, func() {
  1136  				t.Logf("profile:\n%s", p)
  1137  			}
  1138  		}
  1139  	}
  1140  
  1141  	name := t.Name()
  1142  
  1143  	t.Run("runtime.lock", func(t *testing.T) {
  1144  		// The goroutine that acquires the lock will only proceed when it
  1145  		// detects that its partner is contended for the lock. That will lead to
  1146  		// live-lock if anything (such as a STW) prevents the partner goroutine
  1147  		// from running. Allowing the contention workers to pause and restart
  1148  		// (to allow a STW to proceed) makes it harder to confirm that we're
  1149  		// counting the correct number of contention events, since some locks
  1150  		// will end up contended twice. Instead, disable the GC.
  1151  		defer debug.SetGCPercent(debug.SetGCPercent(-1))
  1152  
  1153  		mus := make([]runtime.Mutex, 200)
  1154  		var needContention atomic.Int64
  1155  
  1156  		baseDelay := 100 * time.Microsecond // large relative to system noise, for comparison between clocks
  1157  		fastDelayMicros := baseDelay.Microseconds()
  1158  		slowDelayMicros := baseDelay.Microseconds() * 4
  1159  
  1160  		const (
  1161  			fastRole = iota
  1162  			slowRole
  1163  			workerCount
  1164  		)
  1165  		if runtime.GOMAXPROCS(0) < workerCount {
  1166  			t.Skipf("contention on runtime-internal locks requires GOMAXPROCS >= %d", workerCount)
  1167  		}
  1168  
  1169  		minTicks := make([][]int64, workerCount) // lower bound, known-contended time, measured by cputicks
  1170  		maxTicks := make([][]int64, workerCount) // upper bound, total lock() duration, measured by cputicks
  1171  		for i := range minTicks {
  1172  			minTicks[i] = make([]int64, len(mus))
  1173  			maxTicks[i] = make([]int64, len(mus))
  1174  		}
  1175  		var id atomic.Int32
  1176  		fn := func() bool {
  1177  			n := int(needContention.Load())
  1178  			if n < 0 {
  1179  				return false
  1180  			}
  1181  			mu := &mus[n]
  1182  
  1183  			// Each worker has a role: to have a fast or slow critical section.
  1184  			// Rotate the role assignments as we step through the mutex slice so
  1185  			// we don't end up with one M always claiming the same kind of work.
  1186  			id := int(id.Add(1))
  1187  			role := (id + n) % workerCount
  1188  
  1189  			marker, delayMicros := fastMarkerFrame, fastDelayMicros
  1190  			if role == slowRole {
  1191  				marker, delayMicros = slowMarkerFrame, slowDelayMicros
  1192  			}
  1193  
  1194  			// Each lock is used by two different critical sections, one fast
  1195  			// and one slow, identified in profiles by their different "marker"
  1196  			// functions. We expect the profile to blame each for the amount of
  1197  			// delay it inflicts on other users of the lock. We run one worker
  1198  			// of each kind, so any contention in one would be due to the other.
  1199  			//
  1200  			// We measure how long our runtime.lock call takes, which sets an
  1201  			// upper bound on how much blame to expect for the other worker type
  1202  			// in the profile. And if we acquire the lock first, we wait for the
  1203  			// other worker to announce its contention. We measure the
  1204  			// known-contended time, to use as a lower bound on how much blame
  1205  			// we expect of ourselves in the profile. Then we stall for a little
  1206  			// while (different amounts for "fast" versus "slow") before
  1207  			// unlocking the mutex.
  1208  
  1209  			marker(func() {
  1210  				t0 := runtime.Cputicks()
  1211  				runtime.Lock(mu)
  1212  				maxTicks[role][n] = runtime.Cputicks() - t0
  1213  				minTicks[role][n] = 0
  1214  				for int(needContention.Load()) == n {
  1215  					if runtime.MutexContended(mu) {
  1216  						t1 := runtime.Cputicks()
  1217  						// make them wait a little while
  1218  						for start := runtime.Nanotime(); (runtime.Nanotime()-start)/1000 < delayMicros; {
  1219  							runtime.Usleep(uint32(1 + delayMicros/8))
  1220  						}
  1221  						minTicks[role][n] = runtime.Cputicks() - t1
  1222  						break
  1223  					}
  1224  					runtime.Usleep(uint32(1 + delayMicros/8))
  1225  				}
  1226  				runtime.Unlock(mu)
  1227  				needContention.Store(int64(n - 1))
  1228  			})
  1229  
  1230  			return true
  1231  		}
  1232  
  1233  		stks := make([][]string, 2)
  1234  		for i := range stks {
  1235  			marker := "runtime_test.fastMarkerFrame"
  1236  			if i == slowRole {
  1237  				marker = "runtime_test.slowMarkerFrame"
  1238  			}
  1239  
  1240  			stks[i] = []string{
  1241  				"runtime.unlock",
  1242  				"runtime_test." + name + ".func4.1.1",
  1243  				marker,
  1244  				"runtime_test." + name + ".func4.1",
  1245  				"runtime_test.(*contentionWorker).run",
  1246  			}
  1247  		}
  1248  
  1249  		t.Run("sample-1", func(t *testing.T) {
  1250  			old := runtime.SetMutexProfileFraction(1)
  1251  			defer runtime.SetMutexProfileFraction(old)
  1252  
  1253  			needContention.Store(int64(len(mus) - 1))
  1254  			metricGrowth, profileGrowth, n, _, explain := testcase(true, stks, workerCount, fn)(t)
  1255  			defer func() {
  1256  				if t.Failed() {
  1257  					explain()
  1258  				}
  1259  			}()
  1260  
  1261  			t.Run("metric", func(t *testing.T) {
  1262  				// The runtime/metrics view may be sampled at 1 per
  1263  				// gTrackingPeriod, so we don't have a hard lower bound here.
  1264  				testenv.SkipFlaky(t, 64253)
  1265  
  1266  				if have, want := metricGrowth, baseDelay.Seconds()*float64(len(mus)); have < want {
  1267  					// The test imposes a delay with usleep, verified with calls to
  1268  					// nanotime. Compare against the runtime/metrics package's view
  1269  					// (based on nanotime) rather than runtime/pprof's view (based
  1270  					// on cputicks).
  1271  					t.Errorf("runtime/metrics reported less than the known minimum contention duration (%fs < %fs)", have, want)
  1272  				}
  1273  			})
  1274  			if have, want := n, int64(len(mus)); have != want {
  1275  				t.Errorf("mutex profile reported contention count different from the known true count (%d != %d)", have, want)
  1276  			}
  1277  
  1278  			var slowMinTicks, fastMinTicks int64
  1279  			for role, ticks := range minTicks {
  1280  				for _, delta := range ticks {
  1281  					if role == slowRole {
  1282  						slowMinTicks += delta
  1283  					} else {
  1284  						fastMinTicks += delta
  1285  					}
  1286  				}
  1287  			}
  1288  			var slowMaxTicks, fastMaxTicks int64
  1289  			for role, ticks := range maxTicks {
  1290  				for _, delta := range ticks {
  1291  					if role == slowRole {
  1292  						slowMaxTicks += delta
  1293  					} else {
  1294  						fastMaxTicks += delta
  1295  					}
  1296  				}
  1297  			}
  1298  
  1299  			cpuGHz := float64(runtime.CyclesPerSecond()) / 1e9
  1300  			for _, set := range []struct {
  1301  				name     string
  1302  				profTime int64
  1303  				minTime  int64
  1304  				maxTime  int64
  1305  			}{
  1306  				{
  1307  					name:     "slow",
  1308  					profTime: profileGrowth[slowRole],
  1309  					minTime:  int64(float64(slowMinTicks) / cpuGHz),
  1310  					maxTime:  int64(float64(fastMaxTicks) / cpuGHz),
  1311  				},
  1312  				{
  1313  					name:     "fast",
  1314  					profTime: profileGrowth[fastRole],
  1315  					minTime:  int64(float64(fastMinTicks) / cpuGHz),
  1316  					maxTime:  int64(float64(slowMaxTicks) / cpuGHz),
  1317  				},
  1318  			} {
  1319  				t.Logf("profile's view of delays due to %q critical section:                 %dns", set.name, set.profTime)
  1320  				t.Logf("test's view of known-contended time within %q critical section:      %dns", set.name, set.minTime)
  1321  				t.Logf("test's view of lock duration before critical sections other than %q: %dns", set.name, set.maxTime)
  1322  
  1323  				if set.profTime < set.minTime {
  1324  					t.Errorf("profile undercounted %q critical section", set.name)
  1325  				}
  1326  				if set.profTime > set.maxTime {
  1327  					t.Errorf("profile overcounted %q critical section", set.name)
  1328  				}
  1329  			}
  1330  
  1331  			var totalProfileGrowth float64
  1332  			for _, growth := range profileGrowth {
  1333  				totalProfileGrowth += float64(growth) * time.Nanosecond.Seconds()
  1334  			}
  1335  
  1336  			const slop = 1.5 // account for nanotime vs cputicks
  1337  			t.Run("compare timers", func(t *testing.T) {
  1338  				testenv.SkipFlaky(t, 64253)
  1339  				if totalProfileGrowth > slop*metricGrowth || metricGrowth > slop*totalProfileGrowth {
  1340  					t.Errorf("views differ by more than %fx", slop)
  1341  				}
  1342  			})
  1343  		})
  1344  
  1345  		t.Run("sample-2", func(t *testing.T) {
  1346  			testenv.SkipFlaky(t, 64253)
  1347  
  1348  			old := runtime.SetMutexProfileFraction(2)
  1349  			defer runtime.SetMutexProfileFraction(old)
  1350  
  1351  			needContention.Store(int64(len(mus) - 1))
  1352  			metricGrowth, profileGrowth, n, _, explain := testcase(true, stks, workerCount, fn)(t)
  1353  			defer func() {
  1354  				if t.Failed() {
  1355  					explain()
  1356  				}
  1357  			}()
  1358  
  1359  			// With 100 trials and profile fraction of 2, we expect to capture
  1360  			// 50 samples. Allow the test to pass if we get at least 20 samples;
  1361  			// the CDF of the binomial distribution says there's less than a
  1362  			// 1e-9 chance of that, which is an acceptably low flakiness rate.
  1363  			const samplingSlop = 2.5
  1364  
  1365  			if have, want := metricGrowth, baseDelay.Seconds()*float64(len(mus)); samplingSlop*have < want {
  1366  				// The test imposes a delay with usleep, verified with calls to
  1367  				// nanotime. Compare against the runtime/metrics package's view
  1368  				// (based on nanotime) rather than runtime/pprof's view (based
  1369  				// on cputicks).
  1370  				t.Errorf("runtime/metrics reported less than the known minimum contention duration (%f * %fs < %fs)", samplingSlop, have, want)
  1371  			}
  1372  			if have, want := n, int64(len(mus)); float64(have) > float64(want)*samplingSlop || float64(want) > float64(have)*samplingSlop {
  1373  				t.Errorf("mutex profile reported contention count too different from the expected count (%d far from %d)", have, want)
  1374  			}
  1375  
  1376  			var totalProfileGrowth float64
  1377  			for _, growth := range profileGrowth {
  1378  				totalProfileGrowth += float64(growth) * time.Nanosecond.Seconds()
  1379  			}
  1380  
  1381  			const timerSlop = 1.5 * samplingSlop // account for nanotime vs cputicks, plus the two views' independent sampling
  1382  			if totalProfileGrowth > timerSlop*metricGrowth || metricGrowth > timerSlop*totalProfileGrowth {
  1383  				t.Errorf("views differ by more than %fx", timerSlop)
  1384  			}
  1385  		})
  1386  	})
  1387  
  1388  	t.Run("runtime.semrelease", func(t *testing.T) {
  1389  		testenv.SkipFlaky(t, 64253)
  1390  
  1391  		old := runtime.SetMutexProfileFraction(1)
  1392  		defer runtime.SetMutexProfileFraction(old)
  1393  
  1394  		const workers = 3
  1395  		if runtime.GOMAXPROCS(0) < workers {
  1396  			t.Skipf("creating and observing contention on runtime-internal semaphores requires GOMAXPROCS >= %d", workers)
  1397  		}
  1398  
  1399  		var sem uint32 = 1
  1400  		var tries atomic.Int32
  1401  		tries.Store(10_000_000) // prefer controlled failure to timeout
  1402  		var sawContention atomic.Int32
  1403  		var need int32 = 1
  1404  		fn := func() bool {
  1405  			if sawContention.Load() >= need {
  1406  				return false
  1407  			}
  1408  			if tries.Add(-1) < 0 {
  1409  				return false
  1410  			}
  1411  
  1412  			runtime.Semacquire(&sem)
  1413  			runtime.Semrelease1(&sem, false, 0)
  1414  			if runtime.MutexContended(runtime.SemRootLock(&sem)) {
  1415  				sawContention.Add(1)
  1416  			}
  1417  			return true
  1418  		}
  1419  
  1420  		stks := [][]string{
  1421  			{
  1422  				"runtime.unlock",
  1423  				"runtime.semrelease1",
  1424  				"runtime_test.TestRuntimeLockMetricsAndProfile.func5.1",
  1425  				"runtime_test.(*contentionWorker).run",
  1426  			},
  1427  			{
  1428  				"runtime.unlock",
  1429  				"runtime.semacquire1",
  1430  				"runtime.semacquire",
  1431  				"runtime_test.TestRuntimeLockMetricsAndProfile.func5.1",
  1432  				"runtime_test.(*contentionWorker).run",
  1433  			},
  1434  		}
  1435  
  1436  		// Verify that we get call stack we expect, with anything more than zero
  1437  		// cycles / zero samples. The duration of each contention event is too
  1438  		// small relative to the expected overhead for us to verify its value
  1439  		// more directly. Leave that to the explicit lock/unlock test.
  1440  
  1441  		testcase(false, stks, workers, fn)(t)
  1442  
  1443  		if remaining := tries.Load(); remaining >= 0 {
  1444  			t.Logf("finished test early (%d tries remaining)", remaining)
  1445  		}
  1446  	})
  1447  }
  1448  
  1449  func slowMarkerFrame(fn func()) { fn() }
  1450  func fastMarkerFrame(fn func()) { fn() }
  1451  
  1452  // contentionWorker provides cleaner call stacks for lock contention profile tests
  1453  type contentionWorker struct {
  1454  	before func()
  1455  	fn     func() bool
  1456  	after  func()
  1457  }
  1458  
  1459  func (w *contentionWorker) run() {
  1460  	defer w.after()
  1461  	w.before()
  1462  
  1463  	for w.fn() {
  1464  	}
  1465  }
  1466  
  1467  func TestCPUStats(t *testing.T) {
  1468  	// Run a few GC cycles to get some of the stats to be non-zero.
  1469  	runtime.GC()
  1470  	runtime.GC()
  1471  	runtime.GC()
  1472  
  1473  	// Set GOMAXPROCS high then sleep briefly to ensure we generate
  1474  	// some idle time.
  1475  	oldmaxprocs := runtime.GOMAXPROCS(10)
  1476  	time.Sleep(time.Millisecond)
  1477  	runtime.GOMAXPROCS(oldmaxprocs)
  1478  
  1479  	stats := runtime.ReadCPUStats()
  1480  	gcTotal := stats.GCAssistTime + stats.GCDedicatedTime + stats.GCIdleTime + stats.GCPauseTime
  1481  	if gcTotal != stats.GCTotalTime {
  1482  		t.Errorf("manually computed total does not match GCTotalTime: %d cpu-ns vs. %d cpu-ns", gcTotal, stats.GCTotalTime)
  1483  	}
  1484  	scavTotal := stats.ScavengeAssistTime + stats.ScavengeBgTime
  1485  	if scavTotal != stats.ScavengeTotalTime {
  1486  		t.Errorf("manually computed total does not match ScavengeTotalTime: %d cpu-ns vs. %d cpu-ns", scavTotal, stats.ScavengeTotalTime)
  1487  	}
  1488  	total := gcTotal + scavTotal + stats.IdleTime + stats.UserTime
  1489  	if total != stats.TotalTime {
  1490  		t.Errorf("manually computed overall total does not match TotalTime: %d cpu-ns vs. %d cpu-ns", total, stats.TotalTime)
  1491  	}
  1492  	if total == 0 {
  1493  		t.Error("total time is zero")
  1494  	}
  1495  	if gcTotal == 0 {
  1496  		t.Error("GC total time is zero")
  1497  	}
  1498  	if stats.IdleTime == 0 {
  1499  		t.Error("idle time is zero")
  1500  	}
  1501  }
  1502  
  1503  func TestMetricHeapUnusedLargeObjectOverflow(t *testing.T) {
  1504  	// This test makes sure /memory/classes/heap/unused:bytes
  1505  	// doesn't overflow when allocating and deallocating large
  1506  	// objects. It is a regression test for #67019.
  1507  	done := make(chan struct{})
  1508  	var wg sync.WaitGroup
  1509  	wg.Add(1)
  1510  	go func() {
  1511  		defer wg.Done()
  1512  		for {
  1513  			for range 10 {
  1514  				abi.Escape(make([]byte, 1<<20))
  1515  			}
  1516  			runtime.GC()
  1517  			select {
  1518  			case <-done:
  1519  				return
  1520  			default:
  1521  			}
  1522  		}
  1523  	}()
  1524  	s := []metrics.Sample{
  1525  		{Name: "/memory/classes/heap/unused:bytes"},
  1526  	}
  1527  	for range 1000 {
  1528  		metrics.Read(s)
  1529  		if s[0].Value.Uint64() > 1<<40 {
  1530  			t.Errorf("overflow")
  1531  			break
  1532  		}
  1533  	}
  1534  	done <- struct{}{}
  1535  	wg.Wait()
  1536  }
  1537  
  1538  func TestReadMetricsCleanups(t *testing.T) {
  1539  	runtime.GC()                                                // End any in-progress GC.
  1540  	runtime.BlockUntilEmptyCleanupQueue(int64(1 * time.Second)) // Flush any queued cleanups.
  1541  
  1542  	var before [2]metrics.Sample
  1543  	before[0].Name = "/gc/cleanups/queued:cleanups"
  1544  	before[1].Name = "/gc/cleanups/executed:cleanups"
  1545  	after := before
  1546  
  1547  	metrics.Read(before[:])
  1548  
  1549  	const N = 10
  1550  	for i := 0; i < N; i++ {
  1551  		runtime.AddCleanup(new(*int), func(_ struct{}) {}, struct{}{})
  1552  	}
  1553  
  1554  	runtime.GC()
  1555  	runtime.BlockUntilEmptyCleanupQueue(int64(1 * time.Second))
  1556  
  1557  	metrics.Read(after[:])
  1558  
  1559  	if v0, v1 := before[0].Value.Uint64(), after[0].Value.Uint64(); v0+N != v1 {
  1560  		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[0].Name, N, v0, v1)
  1561  	}
  1562  	if v0, v1 := before[1].Value.Uint64(), after[1].Value.Uint64(); v0+N != v1 {
  1563  		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[1].Name, N, v0, v1)
  1564  	}
  1565  }
  1566  
  1567  func TestReadMetricsFinalizers(t *testing.T) {
  1568  	runtime.GC()                                                  // End any in-progress GC.
  1569  	runtime.BlockUntilEmptyFinalizerQueue(int64(1 * time.Second)) // Flush any queued finalizers.
  1570  
  1571  	var before [2]metrics.Sample
  1572  	before[0].Name = "/gc/finalizers/queued:finalizers"
  1573  	before[1].Name = "/gc/finalizers/executed:finalizers"
  1574  	after := before
  1575  
  1576  	metrics.Read(before[:])
  1577  
  1578  	const N = 10
  1579  	for i := 0; i < N; i++ {
  1580  		runtime.SetFinalizer(new(*int), func(_ **int) {})
  1581  	}
  1582  
  1583  	runtime.GC()
  1584  	runtime.GC()
  1585  	runtime.BlockUntilEmptyFinalizerQueue(int64(1 * time.Second))
  1586  
  1587  	metrics.Read(after[:])
  1588  
  1589  	if v0, v1 := before[0].Value.Uint64(), after[0].Value.Uint64(); v0+N != v1 {
  1590  		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[0].Name, N, v0, v1)
  1591  	}
  1592  	if v0, v1 := before[1].Value.Uint64(), after[1].Value.Uint64(); v0+N != v1 {
  1593  		t.Errorf("expected %s difference to be exactly %d, got %d -> %d", before[1].Name, N, v0, v1)
  1594  	}
  1595  }
  1596  
  1597  func TestReadMetricsSched(t *testing.T) {
  1598  	// This test is run in a subprocess to prevent other tests from polluting the metrics.
  1599  	output := runTestProg(t, "testprog", "SchedMetrics")
  1600  	want := "OK\n"
  1601  	if output != want {
  1602  		t.Fatalf("output:\n%s\n\nwanted:\n%s", output, want)
  1603  	}
  1604  }
  1605  

View as plain text