admission,goschedstats: add metrics for non work-conserving CPU behavior

We have encountered scenarios with a large number of goroutines, which often
causes an increase in the runnable goroutines, while the mean CPU utilization
stays low (sometimes as low as 25%). Since there are non-zero runnable
goroutines, at very short time scales of a few millis, CPU utilization must
be 100% at those time scales. Since admission control (AC) samples the
runnable goroutine count every 1ms, in order to react to such short time
scales, we do see some drop in the slot count in some of these scenarios, and
see queueing in the AC queues. The concern that comes up when seeing such
queueing is whether AC is making the situation worse in its attempt to shift
some queueing from the goroutine scheduler into the AC queue. Note that since
admission.kv_slot_adjuster.overload_threshold is set to 32, AC does allow for
significant queuing in the goroutine scheduler too, in an attempt to be work
conserving. But it is still possible that the slot adjustment logic is being
too slow to react and not allowing enough concurrency to keep the CPUs busy.

This PR adds two metrics to measure this behavior. These are still subject
to sampling errors, but they are tied to the 1ms sampling of CPULoad.
The admission.granter.cpu_non_work_conserving_duration.kv is incremented
by the sampling duration * number of idle Ps if there are requests waiting
in the AC KV (CPU) queue. Since we have observed idle P's even when there are
runnable goroutines (which is not the fault of AC), there is another metric
admission.granter.cpu_non_work_conserving_due_to_admission_duration.kv
which discounts the number of idle Ps by the number of runnable goroutines.

These metrics give a sense of how much CPU capacity we are wasting per
second. For example, if the first metric has a value 0.5s/s and we have
10 CPUs, so 10s/s of capacity, we are wasting 5% of the CPU. If the second
metric is 0.3s/s then 3% of that CPU wastage can be attributed to AC
queueing not behaving well. That is, one may expect CPU utilization to
increase by 3% if AC is switched off. These metrics don't tell us the real
latency impact of turning off AC, but the expectation is that if the
reduction in CPU utilization due to AC divided by the observed CPU
utilization (with AC on) is very small, the latency benefit of turning off
AC will be small.

Epic: none
Fixes: cockroachdb#96495

pkg/testutils/lint/lint_test.go

@@ -2237,6 +2237,10 @@ func TestLint(t *testing.T) {
 			// This exception is for hash.go, which re-implements runtime.noescape
 			// for efficient hashing.
 			stream.GrepNot(`pkg/sql/colexec/colexechash/hash.go:[0-9:]+: possible misuse of unsafe.Pointer`),
+			// This exception is for interpreting the uintptr in the schedt and p
+			// structs inside the goroutine scheduler.
+			stream.GrepNot(`pkg/util/goschedstats/runtime_go1.19.go:[0-9:]+: possible misuse of unsafe.Pointer.*`),
+			stream.GrepNot(`pkg/util/goschedstats/runtime_go1.19.go.*`),
 			stream.GrepNot(`^#`), // comment line
 			// Roachpb's own error package takes ownership of error unwraps
 			// (by enforcing that errors can never been wrapped under a

pkg/ts/catalog/chart_catalog.go

@@ -3819,6 +3819,8 @@ var charts = []sectionDescription{
 					"admission.granter.slots_exhausted_duration.kv",
 					"admission.granter.cpu_load_short_period_duration.kv",
 					"admission.granter.cpu_load_long_period_duration.kv",
+					"admission.granter.cpu_non_work_conserving_duration.kv",
+					"admission.granter.cpu_non_work_conserving_due_to_admission_duration.kv",
 				},
 			},
 			{

pkg/util/admission/admission.go

@@ -315,7 +315,7 @@ type cpuOverloadIndicator interface {
 // underloaded. If the samplePeriod is > 1ms, admission control enforcement
 // for CPU is disabled.
 type CPULoadListener interface {
-	CPULoad(runnable int, procs int, samplePeriod time.Duration)
+	CPULoad(runnable int, procs int, idleProcs int, samplePeriod time.Duration)
 }
 
 // storeRequester is used to abstract *StoreWorkQueue for testing.

pkg/util/admission/grant_coordinator.go

@@ -427,14 +427,16 @@ func makeRegularGrantCoordinator(
 	}
 
 	kvSlotAdjuster := &kvSlotAdjuster{
-		settings:                         st,
-		minCPUSlots:                      opts.MinCPUSlots,
-		maxCPUSlots:                      opts.MaxCPUSlots,
-		totalSlotsMetric:                 metrics.KVTotalSlots,
-		cpuLoadShortPeriodDurationMetric: metrics.KVCPULoadShortPeriodDuration,
-		cpuLoadLongPeriodDurationMetric:  metrics.KVCPULoadLongPeriodDuration,
-		slotAdjusterIncrementsMetric:     metrics.KVSlotAdjusterIncrements,
-		slotAdjusterDecrementsMetric:     metrics.KVSlotAdjusterDecrements,
+		settings:                            st,
+		minCPUSlots:                         opts.MinCPUSlots,
+		maxCPUSlots:                         opts.MaxCPUSlots,
+		totalSlotsMetric:                    metrics.KVTotalSlots,
+		cpuLoadShortPeriodDurationMetric:    metrics.KVCPULoadShortPeriodDuration,
+		cpuLoadLongPeriodDurationMetric:     metrics.KVCPULoadLongPeriodDuration,
+		cpuNonWorkConservingDuration:        metrics.KVCPUNonWorkConservingDuration,
+		cpuNonWorkConservingDueToACDuration: metrics.KVCPUNonWorkConservingDueToACDuration,
+		slotAdjusterIncrementsMetric:        metrics.KVSlotAdjusterIncrements,
+		slotAdjusterDecrementsMetric:        metrics.KVSlotAdjusterDecrements,
 	}
 	coord := &GrantCoordinator{
 		ambientCtx:                    ambientCtx,
@@ -651,7 +653,9 @@ func (coord *GrantCoordinator) GetWorkQueue(workKind WorkKind) *WorkQueue {
 // burst tokens since synchronizing the two means that the refilled burst can
 // take into account the latest schedulers stats (indirectly, via the
 // implementation of cpuOverloadIndicator).
-func (coord *GrantCoordinator) CPULoad(runnable int, procs int, samplePeriod time.Duration) {
+func (coord *GrantCoordinator) CPULoad(
+	runnable int, procs int, idleProcs int, samplePeriod time.Duration,
+) {
 	ctx := coord.ambientCtx.AnnotateCtx(context.Background())
 
 	if log.V(1) {
@@ -665,7 +669,7 @@ func (coord *GrantCoordinator) CPULoad(runnable int, procs int, samplePeriod tim
 	coord.mu.Lock()
 	defer coord.mu.Unlock()
 	coord.numProcs = procs
-	coord.cpuLoadListener.CPULoad(runnable, procs, samplePeriod)
+	coord.cpuLoadListener.CPULoad(runnable, procs, idleProcs, samplePeriod)
 
 	// Slot adjustment and token refilling requires 1ms periods to work well. If
 	// the CPULoad ticks are less frequent, there is no guarantee that the
@@ -936,33 +940,37 @@ func (coord *GrantCoordinator) SafeFormat(s redact.SafePrinter, verb rune) {
 
 // GrantCoordinatorMetrics are metrics associated with a GrantCoordinator.
 type GrantCoordinatorMetrics struct {
-	KVTotalSlots                 *metric.Gauge
-	KVUsedSlots                  *metric.Gauge
-	KVSlotsExhaustedDuration     *metric.Counter
-	KVCPULoadShortPeriodDuration *metric.Counter
-	KVCPULoadLongPeriodDuration  *metric.Counter
-	KVSlotAdjusterIncrements     *metric.Counter
-	KVSlotAdjusterDecrements     *metric.Counter
-	KVIOTokensExhaustedDuration  *metric.Counter
-	SQLLeafStartUsedSlots        *metric.Gauge
-	SQLRootStartUsedSlots        *metric.Gauge
+	KVTotalSlots                          *metric.Gauge
+	KVUsedSlots                           *metric.Gauge
+	KVSlotsExhaustedDuration              *metric.Counter
+	KVCPULoadShortPeriodDuration          *metric.Counter
+	KVCPULoadLongPeriodDuration           *metric.Counter
+	KVCPUNonWorkConservingDuration        *metric.Counter
+	KVCPUNonWorkConservingDueToACDuration *metric.Counter
+	KVSlotAdjusterIncrements              *metric.Counter
+	KVSlotAdjusterDecrements              *metric.Counter
+	KVIOTokensExhaustedDuration           *metric.Counter
+	SQLLeafStartUsedSlots                 *metric.Gauge
+	SQLRootStartUsedSlots                 *metric.Gauge
 }
 
 // MetricStruct implements the metric.Struct interface.
 func (GrantCoordinatorMetrics) MetricStruct() {}
 
 func makeGrantCoordinatorMetrics() GrantCoordinatorMetrics {
 	m := GrantCoordinatorMetrics{
-		KVTotalSlots:                 metric.NewGauge(totalSlots),
-		KVUsedSlots:                  metric.NewGauge(addName(workKindString(KVWork), usedSlots)),
-		KVSlotsExhaustedDuration:     metric.NewCounter(kvSlotsExhaustedDuration),
-		KVCPULoadShortPeriodDuration: metric.NewCounter(kvCPULoadShortPeriodDuration),
-		KVCPULoadLongPeriodDuration:  metric.NewCounter(kvCPULoadLongPeriodDuration),
-		KVSlotAdjusterIncrements:     metric.NewCounter(kvSlotAdjusterIncrements),
-		KVSlotAdjusterDecrements:     metric.NewCounter(kvSlotAdjusterDecrements),
-		KVIOTokensExhaustedDuration:  metric.NewCounter(kvIOTokensExhaustedDuration),
-		SQLLeafStartUsedSlots:        metric.NewGauge(addName(workKindString(SQLStatementLeafStartWork), usedSlots)),
-		SQLRootStartUsedSlots:        metric.NewGauge(addName(workKindString(SQLStatementRootStartWork), usedSlots)),
+		KVTotalSlots:                          metric.NewGauge(totalSlots),
+		KVUsedSlots:                           metric.NewGauge(addName(workKindString(KVWork), usedSlots)),
+		KVSlotsExhaustedDuration:              metric.NewCounter(kvSlotsExhaustedDuration),
+		KVCPULoadShortPeriodDuration:          metric.NewCounter(kvCPULoadShortPeriodDuration),
+		KVCPULoadLongPeriodDuration:           metric.NewCounter(kvCPULoadLongPeriodDuration),
+		KVCPUNonWorkConservingDuration:        metric.NewCounter(kvCPUNonWorkConservingDuration),
+		KVCPUNonWorkConservingDueToACDuration: metric.NewCounter(kvCPUNonWorkConservingDueToACDuration),
+		KVSlotAdjusterIncrements:              metric.NewCounter(kvSlotAdjusterIncrements),
+		KVSlotAdjusterDecrements:              metric.NewCounter(kvSlotAdjusterDecrements),
+		KVIOTokensExhaustedDuration:           metric.NewCounter(kvIOTokensExhaustedDuration),
+		SQLLeafStartUsedSlots:                 metric.NewGauge(addName(workKindString(SQLStatementLeafStartWork), usedSlots)),
+		SQLRootStartUsedSlots:                 metric.NewGauge(addName(workKindString(SQLStatementRootStartWork), usedSlots)),
 	}
 	return m
 }

pkg/util/admission/granter.go

@@ -648,6 +648,23 @@ var (
 		Measurement: "Microseconds",
 		Unit:        metric.Unit_COUNT,
 	}
+	// NB: Both the following metrics do not look at the SQL queues, since if
+	// the KV queue is empty the only throttling on the SQL queues is via grant
+	// chaining, which should only cause delays if there is no CPU available.
+	kvCPUNonWorkConservingDuration = metric.Metadata{
+		Name:        "admission.granter.cpu_non_work_conserving_duration.kv",
+		Help:        "Total CPU duration with idle CPU and requests waiting for admission in CPU queue",
+		Measurement: "Microseconds",
+		Unit:        metric.Unit_COUNT,
+	}
+	kvCPUNonWorkConservingDueToACDuration = metric.Metadata{
+		Name: "admission.granter.cpu_non_work_conserving_due_to_admission_duration.kv",
+		Help: "Total CPU duration with idle CPU caused by admission control, i.e., the CPU is" +
+			" idle even after excluding runnable goroutines, and there are requests waiting for" +
+			" admission in CPU queue",
+		Measurement: "Microseconds",
+		Unit:        metric.Unit_COUNT,
+	}
 	kvSlotAdjusterIncrements = metric.Metadata{
 		Name:        "admission.granter.slot_adjuster_increments.kv",
 		Help:        "Number of increments of the total KV slots",

pkg/util/admission/granter_test.go

@@ -196,6 +196,10 @@ func TestGranterBasic(t *testing.T) {
 			var runnable, procs int
 			d.ScanArgs(t, "runnable", &runnable)
 			d.ScanArgs(t, "procs", &procs)
+			idleProcs := 0
+			if d.HasArg("idle-procs") {
+				d.ScanArgs(t, "idle-procs", &idleProcs)
+			}
 			infrequent := false
 			if d.HasArg("infrequent") {
 				d.ScanArgs(t, "infrequent", &infrequent)
@@ -205,17 +209,20 @@ func TestGranterBasic(t *testing.T) {
 			if infrequent {
 				samplePeriod = 250 * time.Millisecond
 			}
-			coord.CPULoad(runnable, procs, samplePeriod)
+			coord.CPULoad(runnable, procs, idleProcs, samplePeriod)
 			str := flushAndReset()
 			kvsa := coord.cpuLoadListener.(*kvSlotAdjuster)
 			microsToMillis := func(micros int64) int64 {
 				return micros * int64(time.Microsecond) / int64(time.Millisecond)
 			}
-			return fmt.Sprintf("%sSlotAdjuster metrics: slots: %d, duration (short, long) millis: (%d, %d), inc: %d, dec: %d\n",
+			return fmt.Sprintf("%sSlotAdjuster metrics: slots: %d, duration (short, long) millis: (%d, %d),"+
+				"inc: %d, dec: %d, non-wc millis (adjusted): %d (%d)\n",
 				str, kvsa.totalSlotsMetric.Value(),
 				microsToMillis(kvsa.cpuLoadShortPeriodDurationMetric.Count()),
 				microsToMillis(kvsa.cpuLoadLongPeriodDurationMetric.Count()),
 				kvsa.slotAdjusterIncrementsMetric.Count(), kvsa.slotAdjusterDecrementsMetric.Count(),
+				microsToMillis(kvsa.cpuNonWorkConservingDuration.Count()),
+				microsToMillis(kvsa.cpuNonWorkConservingDueToACDuration.Count()),
 			)
 
 		case "set-io-tokens":

pkg/util/admission/kv_slot_adjuster.go

@@ -43,17 +43,21 @@ type kvSlotAdjuster struct {
 	minCPUSlots int
 	maxCPUSlots int
 
-	totalSlotsMetric                 *metric.Gauge
-	cpuLoadShortPeriodDurationMetric *metric.Counter
-	cpuLoadLongPeriodDurationMetric  *metric.Counter
-	slotAdjusterIncrementsMetric     *metric.Counter
-	slotAdjusterDecrementsMetric     *metric.Counter
+	totalSlotsMetric                    *metric.Gauge
+	cpuLoadShortPeriodDurationMetric    *metric.Counter
+	cpuLoadLongPeriodDurationMetric     *metric.Counter
+	cpuNonWorkConservingDuration        *metric.Counter
+	cpuNonWorkConservingDueToACDuration *metric.Counter
+	slotAdjusterIncrementsMetric        *metric.Counter
+	slotAdjusterDecrementsMetric        *metric.Counter
 }
 
 var _ cpuOverloadIndicator = &kvSlotAdjuster{}
 var _ CPULoadListener = &kvSlotAdjuster{}
 
-func (kvsa *kvSlotAdjuster) CPULoad(runnable int, procs int, samplePeriod time.Duration) {
+func (kvsa *kvSlotAdjuster) CPULoad(
+	runnable int, procs int, idleProcs int, samplePeriod time.Duration,
+) {
 	threshold := int(KVSlotAdjusterOverloadThreshold.Get(&kvsa.settings.SV))
 
 	periodDurationMicros := samplePeriod.Microseconds()
@@ -62,6 +66,26 @@ func (kvsa *kvSlotAdjuster) CPULoad(runnable int, procs int, samplePeriod time.D
 	} else {
 		kvsa.cpuLoadShortPeriodDurationMetric.Inc(periodDurationMicros)
 	}
+	if idleProcs > 0 && samplePeriod <= time.Millisecond {
+		// Compute whether AC queueing is causing the system to be non
+		// work-conserving, i.e., idle CPU with waiting requests. We don't do this
+		// computation if the samplePeriod is long to avoid polluting this metric,
+		// and because there is no AC slot enforcement when samplePeriod is long.
+
+		// We have seen situations with P's being idle when there are runnable
+		// goroutines. Adjust for that since those idle P's are not the fault of
+		// AC queueing.
+		adjustedIdleProcs := idleProcs - runnable
+		if adjustedIdleProcs < 0 {
+			adjustedIdleProcs = 0
+		}
+		if kvsa.granter.requesterHasWaitingRequests() {
+			kvsa.cpuNonWorkConservingDuration.Inc(periodDurationMicros * int64(idleProcs))
+			if adjustedIdleProcs > 0 {
+				kvsa.cpuNonWorkConservingDueToACDuration.Inc(periodDurationMicros * int64(adjustedIdleProcs))
+			}
+		}
+	}
 
 	// Simple heuristic, which worked ok in experiments. More sophisticated ones
 	// could be devised.

pkg/util/admission/sql_cpu_overload_indicator.go

@@ -29,7 +29,7 @@ var _ cpuOverloadIndicator = &sqlNodeCPUOverloadIndicator{}
 var _ CPULoadListener = &sqlNodeCPUOverloadIndicator{}
 
 func (sn *sqlNodeCPUOverloadIndicator) CPULoad(
-	runnable int, procs int, samplePeriod time.Duration,
+	runnable int, procs int, idleProcs int, samplePeriod time.Duration,
 ) {
 }
 

pkg/util/admission/testdata/granter

@@ -215,30 +215,30 @@ GrantCoordinator:
 sql-sql-response: avail: 1 sql-leaf-start: used: 1, total: 2 sql-root-start: used: 1, total: 1
 
 # Refill the tokens and increase the kv slots to 2.
-cpu-load runnable=0 procs=1
+cpu-load runnable=0 procs=1 idle-procs=1
 ----
 GrantCoordinator:
 (chain: id: 4 active: false index: 1) kv: used: 2, total: 2 sql-kv-response: avail: 2
 sql-sql-response: avail: 1 sql-leaf-start: used: 1, total: 2 sql-root-start: used: 1, total: 1
-SlotAdjuster metrics: slots: 2, duration (short, long) millis: (1, 0), inc: 1, dec: 0
+SlotAdjuster metrics: slots: 2, duration (short, long) millis: (1, 0),inc: 1, dec: 0, non-wc millis (adjusted): 0 (0)
 
 # Tokens don't get overfull. And kv slots increased to 3. This causes a grant
 # to sql-kv-response and the grant chain is again active.
-cpu-load runnable=0 procs=1
+cpu-load runnable=0 procs=1 idle-procs=1
 ----
 sql-kv-response: granted in chain 4, and returning 1
 GrantCoordinator:
 (chain: id: 4 active: true index: 1) kv: used: 2, total: 3 sql-kv-response: avail: 1
 sql-sql-response: avail: 1 sql-leaf-start: used: 1, total: 2 sql-root-start: used: 1, total: 1
-SlotAdjuster metrics: slots: 3, duration (short, long) millis: (2, 0), inc: 2, dec: 0
+SlotAdjuster metrics: slots: 3, duration (short, long) millis: (2, 0),inc: 2, dec: 0, non-wc millis (adjusted): 0 (0)
 
 # Overload and kv slots decreased. Forces termination of grant chain 4.
 cpu-load runnable=2 procs=1
 ----
 GrantCoordinator:
 (chain: id: 5 active: false index: 1) kv: used: 2, total: 2 sql-kv-response: avail: 2
 sql-sql-response: avail: 1 sql-leaf-start: used: 1, total: 2 sql-root-start: used: 1, total: 1
-SlotAdjuster metrics: slots: 2, duration (short, long) millis: (3, 0), inc: 2, dec: 1
+SlotAdjuster metrics: slots: 2, duration (short, long) millis: (3, 0),inc: 2, dec: 1, non-wc millis (adjusted): 0 (0)
 
 # Grant chain 4 terminates.
 continue-grant-chain work=sql-kv-response
@@ -260,7 +260,7 @@ sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: use
 # Underload and kv slots increased. The number of procs=4, so can grant 4 at
 # the same time. The first 3 get a chain-id=0, i.e., they are not really
 # relevant to continuing the grant chain.
-cpu-load runnable=2 procs=4
+cpu-load runnable=2 procs=4 idle-procs=1
 ----
 sql-kv-response: granted in chain 0, and returning 1
 sql-kv-response: granted in chain 0, and returning 1
@@ -269,7 +269,7 @@ sql-leaf-start: granted in chain 5, and returning 1
 GrantCoordinator:
 (chain: id: 5 active: true index: 3) kv: used: 2, total: 3 sql-kv-response: avail: 0
 sql-sql-response: avail: 1 sql-leaf-start: used: 2, total: 2 sql-root-start: used: 1, total: 1
-SlotAdjuster metrics: slots: 3, duration (short, long) millis: (4, 0), inc: 3, dec: 1
+SlotAdjuster metrics: slots: 3, duration (short, long) millis: (4, 0),inc: 3, dec: 1, non-wc millis (adjusted): 0 (0)
 
 # There is now a free sql-root-start slot, which the grant chain will get to.
 return-grant work=sql-root-start
@@ -336,7 +336,7 @@ cpu-load runnable=20 procs=1 infrequent=true
 GrantCoordinator:
 (chain: id: 1 active: false index: 5) kv: used: 1, total: 1 sql-kv-response: avail: 1
 sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 2
-SlotAdjuster metrics: slots: 1, duration (short, long) millis: (0, 250), inc: 0, dec: 0
+SlotAdjuster metrics: slots: 1, duration (short, long) millis: (0, 250),inc: 0, dec: 0, non-wc millis (adjusted): 0 (0)
 
 # sql-kv-response can get a token.
 try-get work=sql-kv-response
@@ -378,6 +378,76 @@ GrantCoordinator:
 (chain: id: 1 active: false index: 5) kv: used: 2, total: 1 sql-kv-response: avail: -1
 sql-sql-response: avail: -1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 2
 
+#####################################################################
+# Test non-work-conserving metrics.
+init-grant-coordinator min-cpu=1 max-cpu=4 sql-kv-tokens=2 sql-sql-tokens=1 sql-leaf=2 sql-root=1
+----
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 0, total: 1 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+
+set-has-waiting-requests work=kv v=true
+----
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 0, total: 1 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+
+# Since waiting request, and there is 1 idle proc, non-wc millis is increased
+# by 1. The adjusted metric
+# (admission.granter.cpu_non_work_conserving_due_to_admission_duration.kv) is
+# not increased since idle-procs-runnable <= 0.
+cpu-load runnable=2 procs=4 idle-procs=1
+----
+kv: granted in chain 0, and returning 1
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 1, total: 1 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+SlotAdjuster metrics: slots: 1, duration (short, long) millis: (1, 0),inc: 0, dec: 0, non-wc millis (adjusted): 1 (0)
+
+# Non-wc millis increases by 2 since 2 idle procs. The adjusted metric does
+# not increase.
+cpu-load runnable=2 procs=4 idle-procs=2
+----
+kv: granted in chain 0, and returning 1
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 2, total: 2 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+SlotAdjuster metrics: slots: 2, duration (short, long) millis: (2, 0),inc: 1, dec: 0, non-wc millis (adjusted): 3 (0)
+
+# Non-wc millis increases by 3 and the adjusted metric by
+# idle-procs-runnable=1.
+cpu-load runnable=2 procs=4 idle-procs=3
+----
+kv: granted in chain 0, and returning 1
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 3, total: 3 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+SlotAdjuster metrics: slots: 3, duration (short, long) millis: (3, 0),inc: 2, dec: 0, non-wc millis (adjusted): 6 (1)
+
+# Non-wc millis increases by 4 and the adjusted metric by
+# idle-procs-runnable=2.
+cpu-load runnable=2 procs=4 idle-procs=4
+----
+kv: granted in chain 0, and returning 1
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 4, total: 4 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+SlotAdjuster metrics: slots: 4, duration (short, long) millis: (4, 0),inc: 3, dec: 0, non-wc millis (adjusted): 10 (3)
+
+set-has-waiting-requests work=kv v=false
+----
+GrantCoordinator:
+(chain: id: 1 active: false index: 0) kv: used: 4, total: 4 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+
+# No increase since there are no waiting requests.
+cpu-load runnable=2 procs=4 idle-procs=4
+----
+GrantCoordinator:
+(chain: id: 1 active: false index: 5) kv: used: 4, total: 4 sql-kv-response: avail: 2
+sql-sql-response: avail: 1 sql-leaf-start: used: 0, total: 2 sql-root-start: used: 0, total: 1
+SlotAdjuster metrics: slots: 4, duration (short, long) millis: (5, 0),inc: 3, dec: 0, non-wc millis (adjusted): 10 (3)
+
 #####################################################################
 # Test store grant coordinator.
 init-store-grant-coordinator