From 177a434cab882ad5b855d29061452b502e18cb84 Mon Sep 17 00:00:00 2001 From: irfan sharif Date: Sun, 20 Feb 2022 02:23:19 -0500 Subject: [PATCH] runtime,runtime/metrics: track on-cpu time per goroutine Fixes #41554. This commit introduces a /sched/goroutine/running:nanoseconds metric, defined as the total time spent by a goroutine in the running state. This measurement is useful for systems that would benefit from fine-grained CPU attribution. An alternative to scheduler-backed CPU attribution would be the use of profiler labels. Given it's common to spawn multiple goroutines for the same task, goroutine-backed statistics can easily become misleading. Profiler labels instead let you measure CPU performance across a set of cooperating goroutines. That said, it comes with overhead that makes it unfeasible to always enable. For high-performance systems that care about fine-grained CPU attribution (databases for e.g. that want to measure total CPU time spent processing each request), profiler labels are too cost-prohibitive, especially given the Go runtime has a much cheaper view of the data needed. It's worth noting that we already export /sched/latencies:seconds to track scheduling latencies, i.e. time spent by a goroutine in the runnable state (go-review.googlesource.com/c/go/+/308933). This commit does effectively the same except for the running state. Users are free to use this metric to power histograms or tracking on-CPU time across a set of goroutines. Change-Id: Ie78336a3ddeca0521ae29cce57bc7a5ea67da297 --- src/runtime/metrics.go | 6 ++++++ src/runtime/metrics/description.go | 5 +++++ src/runtime/metrics/doc.go | 3 +++ src/runtime/metrics_test.go | 4 ++++ src/runtime/proc.go | 22 +++++++++++++++++++++- src/runtime/runtime2.go | 2 ++ src/runtime/sizeof_test.go | 2 +- 7 files changed, 42 insertions(+), 2 deletions(-) diff --git a/src/runtime/metrics.go b/src/runtime/metrics.go index ba0a920a5d16bc..c741f9a8fd6129 100644 --- a/src/runtime/metrics.go +++ b/src/runtime/metrics.go @@ -274,6 +274,12 @@ func initMetrics() { in.sysStats.gcMiscSys + in.sysStats.otherSys }, }, + "/sched/goroutine/running:nanoseconds": { + compute: func(_ *statAggregate, out *metricValue) { + out.kind = metricKindUint64 + out.scalar = uint64(grunningnanos()) + }, + }, "/sched/goroutines:goroutines": { compute: func(_ *statAggregate, out *metricValue) { out.kind = metricKindUint64 diff --git a/src/runtime/metrics/description.go b/src/runtime/metrics/description.go index c147cada8944a2..cce0eac9400f58 100644 --- a/src/runtime/metrics/description.go +++ b/src/runtime/metrics/description.go @@ -214,6 +214,11 @@ var allDesc = []Description{ Description: "All memory mapped by the Go runtime into the current process as read-write. Note that this does not include memory mapped by code called via cgo or via the syscall package. Sum of all metrics in /memory/classes.", Kind: KindUint64, }, + { + Name: "/sched/goroutine/running:nanoseconds", + Description: "Time spent by the current goroutine in the running state.", + Kind: KindUint64, + }, { Name: "/sched/goroutines:goroutines", Description: "Count of live goroutines.", diff --git a/src/runtime/metrics/doc.go b/src/runtime/metrics/doc.go index 91ef03072de49b..c839528f24ca00 100644 --- a/src/runtime/metrics/doc.go +++ b/src/runtime/metrics/doc.go @@ -164,6 +164,9 @@ Below is the full list of supported metrics, ordered lexicographically. by code called via cgo or via the syscall package. Sum of all metrics in /memory/classes. + /sched/goroutine/running:nanoseconds + Wall time spent by the current goroutine in the running state. + /sched/goroutines:goroutines Count of live goroutines. diff --git a/src/runtime/metrics_test.go b/src/runtime/metrics_test.go index 5d32ef469caaa9..d93eaf84337f24 100644 --- a/src/runtime/metrics_test.go +++ b/src/runtime/metrics_test.go @@ -222,6 +222,10 @@ func TestReadMetricsConsistency(t *testing.T) { for i := range h.Counts { gc.pauses += h.Counts[i] } + case "/sched/goroutine/running:nanoseconds": + if samples[i].Value.Uint64() < 1 { + t.Error("goroutine running nanoseconds is less than one") + } case "/sched/goroutines:goroutines": if samples[i].Value.Uint64() < 1 { t.Error("number of goroutines is less than one") diff --git a/src/runtime/proc.go b/src/runtime/proc.go index b997a467bab447..4bf7ff7579a438 100644 --- a/src/runtime/proc.go +++ b/src/runtime/proc.go @@ -990,8 +990,18 @@ func casgstatus(gp *g, oldval, newval uint32) { } } - // Handle tracking for scheduling latencies. + // Handle tracking for scheduling and running latencies. + now := nanotime() + if newval == _Grunning { + // We're transitioning into the running state, record the timestamp for + // subsequent use. + gp.lastsched = now + } if oldval == _Grunning { + // We're transitioning out of running, record how long we were in the + // state. + gp.runningnanos += now - gp.lastsched + // Track every 8th time a goroutine transitions out of running. if gp.trackingSeq%gTrackingPeriod == 0 { gp.tracking = true @@ -3240,6 +3250,14 @@ func dropg() { setGNoWB(&_g_.m.curg, nil) } +// grunningnanos returns the wall time spent by current g in the running state. +// A goroutine may be running on an OS thread that's descheduled by the OS +// scheduler, this time still counts towards the metric. +func grunningnanos() int64 { + gp := getg() + return gp.runningnanos + nanotime() - gp.lastsched +} + // checkTimers runs any timers for the P that are ready. // If now is not 0 it is the current time. // It returns the passed time or the current time if now was passed as 0. @@ -3472,6 +3490,8 @@ func goexit0(gp *g) { gp.param = nil gp.labels = nil gp.timer = nil + gp.lastsched = 0 + gp.runningnanos = 0 if gcBlackenEnabled != 0 && gp.gcAssistBytes > 0 { // Flush assist credit to the global pool. This gives diff --git a/src/runtime/runtime2.go b/src/runtime/runtime2.go index 3d01ac517137c2..9574ed9b5cb587 100644 --- a/src/runtime/runtime2.go +++ b/src/runtime/runtime2.go @@ -486,6 +486,8 @@ type g struct { labels unsafe.Pointer // profiler labels timer *timer // cached timer for time.Sleep selectDone uint32 // are we participating in a select and did someone win the race? + lastsched int64 // timestamp when the G last started running + runningnanos int64 // wall time spent in the running state // Per-G GC state diff --git a/src/runtime/sizeof_test.go b/src/runtime/sizeof_test.go index ebf544ad3b96cf..2ae536d3e9794a 100644 --- a/src/runtime/sizeof_test.go +++ b/src/runtime/sizeof_test.go @@ -21,7 +21,7 @@ func TestSizeof(t *testing.T) { _32bit uintptr // size on 32bit platforms _64bit uintptr // size on 64bit platforms }{ - {runtime.G{}, 236, 392}, // g, but exported for testing + {runtime.G{}, 236, 408}, // g, but exported for testing {runtime.Sudog{}, 56, 88}, // sudog, but exported for testing }