]> Cypherpunks repositories - gostls13.git/commitdiff
runtime/metrics: add CPU stats
authorMichael Anthony Knyszek <mknyszek@google.com>
Fri, 6 May 2022 20:11:28 +0000 (20:11 +0000)
committerGopher Robot <gobot@golang.org>
Fri, 16 Sep 2022 16:32:20 +0000 (16:32 +0000)
This changes adds a breakdown for estimated CPU usage by time. These
estimates are not based on real on-CPU counters, so each metric has a
disclaimer explaining so. They can, however, be more reasonably
compared to a total CPU time metric that this change also adds.

Fixes #47216.

Change-Id: I125006526be9f8e0d609200e193da5a78d9935be
Reviewed-on: https://go-review.googlesource.com/c/go/+/404307
Reviewed-by: Michael Pratt <mpratt@google.com>
Reviewed-by: Josh MacDonald <jmacd@lightstep.com>
Auto-Submit: Michael Knyszek <mknyszek@google.com>
Reviewed-by: David Chase <drchase@google.com>
Run-TryBot: Michael Knyszek <mknyszek@google.com>
TryBot-Result: Gopher Robot <gobot@golang.org>

src/runtime/metrics.go
src/runtime/metrics/description.go
src/runtime/metrics/doc.go
src/runtime/metrics_test.go
src/runtime/mgc.go
src/runtime/mgclimit.go
src/runtime/mgcscavenge.go
src/runtime/mheap.go
src/runtime/mpagealloc.go
src/runtime/mstats.go
src/runtime/runtime2.go

index 2271d8084dd2ab484bce6984b04719294aea62d2..44fb4878ac8b0c5c8eec458ab758d7a91dd0e539 100644 (file)
@@ -90,6 +90,83 @@ func initMetrics() {
                                out.scalar = uint64(NumCgoCall())
                        },
                },
+               "/cpu/classes/gc/mark/assist:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.gcAssistTime))
+                       },
+               },
+               "/cpu/classes/gc/mark/dedicated:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.gcDedicatedTime))
+                       },
+               },
+               "/cpu/classes/gc/mark/idle:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.gcIdleTime))
+                       },
+               },
+               "/cpu/classes/gc/pause:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.gcPauseTime))
+                       },
+               },
+               "/cpu/classes/gc/total:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.gcTotalTime))
+                       },
+               },
+               "/cpu/classes/idle:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.idleTime))
+                       },
+               },
+               "/cpu/classes/scavenge/assist:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.scavengeAssistTime))
+                       },
+               },
+               "/cpu/classes/scavenge/background:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.scavengeBgTime))
+                       },
+               },
+               "/cpu/classes/scavenge/total:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.scavengeTotalTime))
+                       },
+               },
+               "/cpu/classes/total:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.totalTime))
+                       },
+               },
+               "/cpu/classes/user:cpu-seconds": {
+                       deps: makeStatDepSet(cpuStatsDep),
+                       compute: func(in *statAggregate, out *metricValue) {
+                               out.kind = metricKindFloat64
+                               out.scalar = float64bits(nsToSec(in.cpuStats.userTime))
+                       },
+               },
                "/gc/cycles/automatic:gc-cycles": {
                        deps: makeStatDepSet(sysStatsDep),
                        compute: func(in *statAggregate, out *metricValue) {
@@ -345,6 +422,7 @@ type statDep uint
 const (
        heapStatsDep statDep = iota // corresponds to heapStatsAggregate
        sysStatsDep                 // corresponds to sysStatsAggregate
+       cpuStatsDep                 // corresponds to cpuStatsAggregate
        numStatsDeps
 )
 
@@ -490,6 +568,23 @@ func (a *sysStatsAggregate) compute() {
        })
 }
 
+// cpuStatsAggregate represents CPU stats obtained from the runtime
+// acquired together to avoid skew and inconsistencies.
+type cpuStatsAggregate struct {
+       cpuStats
+}
+
+// compute populates the cpuStatsAggregate with values from the runtime.
+func (a *cpuStatsAggregate) compute() {
+       a.cpuStats = work.cpuStats
+}
+
+// nsToSec takes a duration in nanoseconds and converts it to seconds as
+// a float64.
+func nsToSec(ns int64) float64 {
+       return float64(ns) / 1e9
+}
+
 // statAggregate is the main driver of the metrics implementation.
 //
 // It contains multiple aggregates of runtime statistics, as well
@@ -499,6 +594,7 @@ type statAggregate struct {
        ensured   statDepSet
        heapStats heapStatsAggregate
        sysStats  sysStatsAggregate
+       cpuStats  cpuStatsAggregate
 }
 
 // ensure populates statistics aggregates determined by deps if they
@@ -517,6 +613,8 @@ func (a *statAggregate) ensure(deps *statDepSet) {
                        a.heapStats.compute()
                case sysStatsDep:
                        a.sysStats.compute()
+               case cpuStatsDep:
+                       a.cpuStats.compute()
                }
        }
        a.ensured = a.ensured.union(missing)
index ee99d3938df607c87b69fe7e44c9c61a486be7cd..abcdddd16c189b945875437870a7ddf45fcb1dba 100644 (file)
@@ -57,6 +57,122 @@ var allDesc = []Description{
                Kind:        KindUint64,
                Cumulative:  true,
        },
+       {
+               Name: "/cpu/classes/gc/mark/assist:cpu-seconds",
+               Description: "Estimated total CPU time goroutines spent performing GC tasks " +
+                       "to assist the GC and prevent it from falling behind the application. " +
+                       "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,
+       },
+       {
+               Name: "/cpu/classes/gc/mark/dedicated:cpu-seconds",
+               Description: "Estimated total CPU time spent performing GC tasks on " +
+                       "processors (as defined by GOMAXPROCS) dedicated to those tasks. " +
+                       "This includes time spent with the world stopped due to the GC. " +
+                       "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,
+       },
+       {
+               Name: "/cpu/classes/gc/mark/idle:cpu-seconds",
+               Description: "Estimated total CPU time spent performing GC tasks on " +
+                       "spare CPU resources that the Go scheduler could not otherwise find " +
+                       "a use for. This should be subtracted from the total GC CPU time to " +
+                       "obtain a measure of compulsory GC CPU time. " +
+                       "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,
+       },
+       {
+               Name: "/cpu/classes/gc/pause:cpu-seconds",
+               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.",
+               Kind:       KindFloat64,
+               Cumulative: true,
+       },
+       {
+               Name: "/cpu/classes/gc/total:cpu-seconds",
+               Description: "Estimated total CPU time spent performing GC tasks. " +
+                       "This metric is an overestimate, and not directly comparable to " +
+                       "system CPU time measurements. Compare only with other /cpu/classes " +
+                       "metrics. Sum of all metrics in /cpu/classes/gc.",
+               Kind:       KindFloat64,
+               Cumulative: true,
+       },
+       {
+               Name: "/cpu/classes/idle:cpu-seconds",
+               Description: "Estimated total available CPU time not spent executing any Go or Go runtime code. " +
+                       "In other words, the part of /cpu/classes/total:cpu-seconds that was unused. " +
+                       "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,
+       },
+       {
+               Name: "/cpu/classes/scavenge/assist:cpu-seconds",
+               Description: "Estimated total CPU time spent returning unused memory to the " +
+                       "underlying platform in response eagerly in response to memory pressure. " +
+                       "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,
+       },
+       {
+               Name: "/cpu/classes/scavenge/background:cpu-seconds",
+               Description: "Estimated total CPU time spent performing background tasks " +
+                       "to return unused memory to the underlying platform. " +
+                       "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,
+       },
+       {
+               Name: "/cpu/classes/scavenge/total:cpu-seconds",
+               Description: "Estimated total CPU time spent performing tasks that return " +
+                       "unused memory to the underlying platform. " +
+                       "This metric is an overestimate, and not directly comparable to " +
+                       "system CPU time measurements. Compare only with other /cpu/classes " +
+                       "metrics. Sum of all metrics in /cpu/classes/scavenge.",
+               Kind:       KindFloat64,
+               Cumulative: true,
+       },
+       {
+               Name: "/cpu/classes/total:cpu-seconds",
+               Description: "Estimated total available CPU time for user Go code " +
+                       "or the Go runtime, as defined by GOMAXPROCS. In other words, GOMAXPROCS " +
+                       "integrated over the wall-clock duration this process has been executing for. " +
+                       "This metric is an overestimate, and not directly comparable to " +
+                       "system CPU time measurements. Compare only with other /cpu/classes " +
+                       "metrics. Sum of all metrics in /cpu/classes.",
+               Kind:       KindFloat64,
+               Cumulative: true,
+       },
+       {
+               Name: "/cpu/classes/user:cpu-seconds",
+               Description: "Estimated total CPU time spent running user Go code. This may " +
+                       "also include some small amount of time spent in the Go runtime. " +
+                       "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,
+       },
        {
                Name:        "/gc/cycles/automatic:gc-cycles",
                Description: "Count of completed GC cycles generated by the Go runtime.",
index 28c9f6abb5eb3ac71759bd679c75efb3ff3b0c35..bb7e96b3b5b379fdbc794ee4c18d852d141b386c 100644 (file)
@@ -54,6 +54,90 @@ Below is the full list of supported metrics, ordered lexicographically.
        /cgo/go-to-c-calls:calls
                Count of calls made from Go to C by the current process.
 
+       /cpu/classes/gc/mark/assist:cpu-seconds
+               Estimated total CPU time goroutines spent performing GC tasks
+               to assist the GC and prevent it from falling behind the application.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
+       /cpu/classes/gc/mark/dedicated:cpu-seconds
+               Estimated total CPU time spent performing GC tasks on
+               processors (as defined by GOMAXPROCS) dedicated to those tasks.
+               This includes time spent with the world stopped due to the GC.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
+       /cpu/classes/gc/mark/idle:cpu-seconds
+               Estimated total CPU time spent performing GC tasks on
+               spare CPU resources that the Go scheduler could not otherwise find
+               a use for. This should be subtracted from the total GC CPU time to
+               obtain a measure of compulsory GC CPU time.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
+       /cpu/classes/gc/pause:cpu-seconds
+               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.
+
+       /cpu/classes/gc/total:cpu-seconds
+               Estimated total CPU time spent performing GC tasks.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics. Sum of all metrics in /cpu/classes/gc.
+
+       /cpu/classes/idle:cpu-seconds
+               Estimated total available CPU time not spent executing any Go or Go
+               runtime code. In other words, the part of /cpu/classes/total:cpu-seconds
+               that was unused.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
+       /cpu/classes/scavenge/assist:cpu-seconds
+               Estimated total CPU time spent returning unused memory to the
+               underlying platform in response eagerly in response to memory pressure.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
+       /cpu/classes/scavenge/background:cpu-seconds
+               Estimated total CPU time spent performing background tasks
+               to return unused memory to the underlying platform.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
+       /cpu/classes/scavenge/total:cpu-seconds
+               Estimated total CPU time spent performing tasks that return
+               unused memory to the underlying platform.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics. Sum of all metrics in /cpu/classes/scavenge.
+
+       /cpu/classes/total:cpu-seconds
+               Estimated total available CPU time for user Go code or the Go runtime, as
+               defined by GOMAXPROCS. In other words, GOMAXPROCS integrated over the
+               wall-clock duration this process has been executing for.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics. Sum of all metrics in /cpu/classes.
+
+       /cpu/classes/user:cpu-seconds
+               Estimated total CPU time spent running user Go code. This may
+               also include some small amount of time spent in the Go runtime.
+               This metric is an overestimate, and not directly comparable to
+               system CPU time measurements. Compare only with other /cpu/classes
+               metrics.
+
        /gc/cycles/automatic:gc-cycles
                Count of completed GC cycles generated by the Go runtime.
 
index 8baf0209000731e36402c0407b64c8e7be6314d6..645d3a519b7e617dc95f84c2ee709d8107e394d2 100644 (file)
@@ -163,6 +163,12 @@ func TestReadMetricsConsistency(t *testing.T) {
        runtime.GC()
        runtime.GC()
 
+       // Set GOMAXPROCS high then sleep briefly to ensure we generate
+       // some idle time.
+       oldmaxprocs := runtime.GOMAXPROCS(10)
+       time.Sleep(time.Millisecond)
+       runtime.GOMAXPROCS(oldmaxprocs)
+
        // Read all the supported metrics through the metrics package.
        descs, samples := prepareAllMetricsSamples()
        metrics.Read(samples)
@@ -181,6 +187,22 @@ func TestReadMetricsConsistency(t *testing.T) {
                numGC  uint64
                pauses uint64
        }
+       var cpu struct {
+               gcAssist    float64
+               gcDedicated float64
+               gcIdle      float64
+               gcPause     float64
+               gcTotal     float64
+
+               idle float64
+               user float64
+
+               scavengeAssist float64
+               scavengeBg     float64
+               scavengeTotal  float64
+
+               total float64
+       }
        for i := range samples {
                kind := samples[i].Value.Kind()
                if want := descs[samples[i].Name].Kind; kind != want {
@@ -199,6 +221,28 @@ func TestReadMetricsConsistency(t *testing.T) {
                        }
                }
                switch samples[i].Name {
+               case "/cpu/classes/gc/mark/assist:cpu-seconds":
+                       cpu.gcAssist = samples[i].Value.Float64()
+               case "/cpu/classes/gc/mark/dedicated:cpu-seconds":
+                       cpu.gcDedicated = samples[i].Value.Float64()
+               case "/cpu/classes/gc/mark/idle:cpu-seconds":
+                       cpu.gcIdle = samples[i].Value.Float64()
+               case "/cpu/classes/gc/pause:cpu-seconds":
+                       cpu.gcPause = samples[i].Value.Float64()
+               case "/cpu/classes/gc/total:cpu-seconds":
+                       cpu.gcTotal = samples[i].Value.Float64()
+               case "/cpu/classes/idle:cpu-seconds":
+                       cpu.idle = samples[i].Value.Float64()
+               case "/cpu/classes/scavenge/assist:cpu-seconds":
+                       cpu.scavengeAssist = samples[i].Value.Float64()
+               case "/cpu/classes/scavenge/background:cpu-seconds":
+                       cpu.scavengeBg = samples[i].Value.Float64()
+               case "/cpu/classes/scavenge/total:cpu-seconds":
+                       cpu.scavengeTotal = samples[i].Value.Float64()
+               case "/cpu/classes/total:cpu-seconds":
+                       cpu.total = samples[i].Value.Float64()
+               case "/cpu/classes/user:cpu-seconds":
+                       cpu.user = samples[i].Value.Float64()
                case "/memory/classes/total:bytes":
                        totalVirtual.got = samples[i].Value.Uint64()
                case "/memory/classes/heap/objects:bytes":
@@ -235,6 +279,33 @@ func TestReadMetricsConsistency(t *testing.T) {
                        }
                }
        }
+       // Only check this on Linux where we can be reasonably sure we have a high-resolution timer.
+       if runtime.GOOS == "linux" {
+               if cpu.gcDedicated <= 0 && cpu.gcAssist <= 0 && cpu.gcIdle <= 0 {
+                       t.Errorf("found no time spent on GC work: %#v", cpu)
+               }
+               if cpu.gcPause <= 0 {
+                       t.Errorf("found no GC pauses: %f", cpu.gcPause)
+               }
+               if cpu.idle <= 0 {
+                       t.Errorf("found no idle time: %f", cpu.idle)
+               }
+               if total := cpu.gcDedicated + cpu.gcAssist + cpu.gcIdle + cpu.gcPause; !withinEpsilon(cpu.gcTotal, total, 0.01) {
+                       t.Errorf("calculated total GC CPU not within 1%% of sampled total: %f vs. %f", total, cpu.gcTotal)
+               }
+               if total := cpu.scavengeAssist + cpu.scavengeBg; !withinEpsilon(cpu.scavengeTotal, total, 0.01) {
+                       t.Errorf("calculated total scavenge CPU not within 1%% of sampled total: %f vs. %f", total, cpu.scavengeTotal)
+               }
+               if cpu.total <= 0 {
+                       t.Errorf("found no total CPU time passed")
+               }
+               if cpu.user <= 0 {
+                       t.Errorf("found no user time passed")
+               }
+               if total := cpu.gcTotal + cpu.scavengeTotal + cpu.user + cpu.idle; !withinEpsilon(cpu.total, total, 0.02) {
+                       t.Errorf("calculated total CPU not within 2%% of sampled total: %f vs. %f", total, cpu.total)
+               }
+       }
        if totalVirtual.got != totalVirtual.want {
                t.Errorf(`"/memory/classes/total:bytes" does not match sum of /memory/classes/**: got %d, want %d`, totalVirtual.got, totalVirtual.want)
        }
@@ -411,3 +482,7 @@ func TestReadMetricsCumulative(t *testing.T) {
 
        wg.Wait()
 }
+
+func withinEpsilon(v1, v2, e float64) bool {
+       return v2-v2*e <= v1 && v1 <= v2+v2*e
+}
index f7e54d3dd3305a4fb2262825dbc2872706c45e41..3b562181eab1d287fdb3a74b82141a4af5afd00b 100644 (file)
@@ -366,10 +366,6 @@ type workType struct {
        // explicit user call.
        userForced bool
 
-       // totaltime is the CPU nanoseconds spent in GC since the
-       // program started if debug.gctrace > 0.
-       totaltime int64
-
        // initialHeapLive is the value of gcController.heapLive at the
        // beginning of this GC cycle.
        initialHeapLive uint64
@@ -404,6 +400,9 @@ type workType struct {
 
        // debug.gctrace heap sizes for this cycle.
        heap0, heap1, heap2 uint64
+
+       // Cumulative estimated CPU usage.
+       cpuStats
 }
 
 // GC runs a garbage collection and blocks the caller until the
@@ -1006,24 +1005,57 @@ func gcMarkTermination() {
        memstats.pause_end[memstats.numgc%uint32(len(memstats.pause_end))] = uint64(unixNow)
        memstats.pause_total_ns += uint64(work.pauseNS)
 
-       // Update work.totaltime.
        sweepTermCpu := int64(work.stwprocs) * (work.tMark - work.tSweepTerm)
        // We report idle marking time below, but omit it from the
        // overall utilization here since it's "free".
-       markCpu := gcController.assistTime.Load() + gcController.dedicatedMarkTime.Load() + gcController.fractionalMarkTime.Load()
+       markAssistCpu := gcController.assistTime.Load()
+       markDedicatedCpu := gcController.dedicatedMarkTime.Load()
+       markFractionalCpu := gcController.fractionalMarkTime.Load()
+       markIdleCpu := gcController.idleMarkTime.Load()
        markTermCpu := int64(work.stwprocs) * (work.tEnd - work.tMarkTerm)
-       cycleCpu := sweepTermCpu + markCpu + markTermCpu
-       work.totaltime += cycleCpu
+       scavAssistCpu := scavenge.assistTime.Load()
+       scavBgCpu := scavenge.backgroundTime.Load()
+
+       // Update cumulative GC CPU stats.
+       work.cpuStats.gcAssistTime += markAssistCpu
+       work.cpuStats.gcDedicatedTime += markDedicatedCpu + markFractionalCpu
+       work.cpuStats.gcIdleTime += markIdleCpu
+       work.cpuStats.gcPauseTime += sweepTermCpu + markTermCpu
+       work.cpuStats.gcTotalTime += sweepTermCpu + markAssistCpu + markDedicatedCpu + markFractionalCpu + markIdleCpu + markTermCpu
+
+       // Update cumulative scavenge CPU stats.
+       work.cpuStats.scavengeAssistTime += scavAssistCpu
+       work.cpuStats.scavengeBgTime += scavBgCpu
+       work.cpuStats.scavengeTotalTime += scavAssistCpu + scavBgCpu
+
+       // Update total CPU.
+       work.cpuStats.totalTime = sched.totaltime + (now-sched.procresizetime)*int64(gomaxprocs)
+       work.cpuStats.idleTime += sched.idleTime.Load()
+
+       // Compute userTime. We compute this indirectly as everything that's not the above.
+       //
+       // Since time spent in _Pgcstop is covered by gcPauseTime, and time spent in _Pidle
+       // is covered by idleTime, what we're left with is time spent in _Prunning and _Psyscall,
+       // the latter of which is fine because the P will either go idle or get used for something
+       // else via sysmon. Meanwhile if we subtract GC time from whatever's left, we get non-GC
+       // _Prunning time. Note that this still leaves time spent in sweeping and in the scheduler,
+       // but that's fine. The overwhelming majority of this time will be actual user time.
+       work.cpuStats.userTime = work.cpuStats.totalTime - (work.cpuStats.gcTotalTime +
+               work.cpuStats.scavengeTotalTime + work.cpuStats.idleTime)
 
        // Compute overall GC CPU utilization.
-       totalCpu := sched.totaltime + (now-sched.procresizetime)*int64(gomaxprocs)
-       memstats.gc_cpu_fraction = float64(work.totaltime) / float64(totalCpu)
+       // Omit idle marking time from the overall utilization here since it's "free".
+       memstats.gc_cpu_fraction = float64(work.cpuStats.gcTotalTime-work.cpuStats.gcIdleTime) / float64(work.cpuStats.totalTime)
 
-       // Reset assist time stat.
+       // Reset assist time and background time stats.
        //
        // Do this now, instead of at the start of the next GC cycle, because
        // these two may keep accumulating even if the GC is not active.
-       mheap_.pages.scav.assistTime.Store(0)
+       scavenge.assistTime.Store(0)
+       scavenge.backgroundTime.Store(0)
+
+       // Reset idle time stat.
+       sched.idleTime.Store(0)
 
        // Reset sweep state.
        sweep.nbgsweep = 0
index b6fbcb14cf92df2bfc25c1ed07f0efdecfe4fbda..bcbe7f88a0567db54ceb5f24dd22ff8ba72525b1 100644 (file)
@@ -469,9 +469,10 @@ func (e *limiterEvent) stop(typ limiterEventType, now int64) {
        // Account for the event.
        switch typ {
        case limiterEventIdleMarkWork:
-               fallthrough
+               gcCPULimiter.addIdleTime(duration)
        case limiterEventIdle:
                gcCPULimiter.addIdleTime(duration)
+               sched.idleTime.Add(duration)
        case limiterEventMarkAssist:
                fallthrough
        case limiterEventScavengeAssist:
index c54ae3446249a5fdbd8138d98d08de999f473ccf..1b4fd66917b2f5eb637aa663bd8df7362834f852 100644 (file)
@@ -221,6 +221,16 @@ var scavenge struct {
        // gcController.memoryLimit by choosing to target the memory limit or
        // some lower target to keep the scavenger working.
        memoryLimitGoal atomic.Uint64
+
+       // assistTime is the time spent by the allocator scavenging in the last GC cycle.
+       //
+       // This is reset once a GC cycle ends.
+       assistTime atomic.Int64
+
+       // backgroundTime is the time spent by the background scavenger in the last GC cycle.
+       //
+       // This is reset once a GC cycle ends.
+       backgroundTime atomic.Int64
 }
 
 const (
@@ -361,6 +371,7 @@ func (s *scavengerState) init() {
                        if start >= end {
                                return r, 0
                        }
+                       scavenge.backgroundTime.Add(end - start)
                        return r, end - start
                }
        }
index cd4634448c32e0be3fd837cbda450f8ed5ecd09f..c8a6cd29362e99038b6256a0b368f130ee579ebc 100644 (file)
@@ -1327,7 +1327,7 @@ HaveSpan:
                if track {
                        pp.limiterEvent.stop(limiterEventScavengeAssist, now)
                }
-               h.pages.scav.assistTime.Add(now - start)
+               scavenge.assistTime.Add(now - start)
        }
 
        // Commit and account for any scavenged memory that the span now owns.
index 853d7fc9ca556217c48538735209b14841035d4a..a8bfc62a807c56fe7768b1faa6e993fec6395b7c 100644 (file)
@@ -48,7 +48,6 @@
 package runtime
 
 import (
-       "runtime/internal/atomic"
        "unsafe"
 )
 
@@ -273,15 +272,10 @@ type pageAlloc struct {
                // scavenge.
                index scavengeIndex
 
-               // released is the amount of memory released this generation.
+               // released is the amount of memory released this scavenge cycle.
                //
                // Updated atomically.
                released uintptr
-
-               // scavengeAssistTime is the time spent scavenging in the last GC cycle.
-               //
-               // This is reset once a GC cycle ends.
-               assistTime atomic.Int64
        }
 
        // mheap_.lock. This level of indirection makes it possible
index d4ef933611158b125d2c0b0bd544c625c0e50aa4..3a5273f3619cf61197c1221d058ace8f05e78056 100644 (file)
@@ -879,3 +879,25 @@ func (m *consistentHeapStats) read(out *heapStatsDelta) {
 
        releasem(mp)
 }
+
+type cpuStats struct {
+       // All fields are CPU time in nanoseconds computed by comparing
+       // calls of nanotime. This means they're all overestimates, because
+       // they don't accurately compute on-CPU time (so some of the time
+       // could be spent scheduled away by the OS).
+
+       gcAssistTime    int64 // GC assists
+       gcDedicatedTime int64 // GC dedicated mark workers + pauses
+       gcIdleTime      int64 // GC idle mark workers
+       gcPauseTime     int64 // GC pauses (all GOMAXPROCS, even if just 1 is running)
+       gcTotalTime     int64
+
+       scavengeAssistTime int64 // background scavenger
+       scavengeBgTime     int64 // scavenge assists
+       scavengeTotalTime  int64
+
+       idleTime int64 // Time Ps spent in _Pidle.
+       userTime int64 // Time Ps spent in _Prunning or _Psyscall that's not any of the above.
+
+       totalTime int64 // GOMAXPROCS * (monotonic wall clock time elapsed)
+}
index 1c620bbfbeeab84b395d86525f35596e75b3979c..5e0d61c058903410a85dde485c0844120bc3cf70 100644 (file)
@@ -838,6 +838,11 @@ type schedt struct {
        // as the sum of time a G spends in the _Grunnable state before
        // it transitions to _Grunning.
        timeToRun timeHistogram
+
+       // idleTime is the total CPU time Ps have "spent" idle.
+       //
+       // Reset on each GC cycle.
+       idleTime atomic.Int64
 }
 
 // Values for the flags field of a sigTabT.