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

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