Skip to content

Commit d100768

Browse files
committed
scheduler_perf: track and visualize progress over time
This is useful to see whether pod scheduling happens in bursts and how it behaves over time, which is relevant in particular for dynamic resource allocation where it may become harder at the end to find the node which still has resources available. Besides "pods scheduled" it's also useful to know how many attempts were needed, so schedule_attempts_total also gets sampled and stored. To visualize the result of one or more test runs, use: gnuplot.sh *.dat
1 parent ded9604 commit d100768

File tree

6 files changed

+293
-7
lines changed

6 files changed

+293
-7
lines changed

staging/src/k8s.io/component-base/metrics/testutil/metrics.go

Lines changed: 46 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -258,12 +258,8 @@ func GetHistogramVecFromGatherer(gatherer metrics.Gatherer, metricName string, l
258258
if err != nil {
259259
return nil, err
260260
}
261-
for _, mFamily := range m {
262-
if mFamily.GetName() == metricName {
263-
metricFamily = mFamily
264-
break
265-
}
266-
}
261+
262+
metricFamily = findMetricFamily(m, metricName)
267263

268264
if metricFamily == nil {
269265
return nil, fmt.Errorf("metric %q not found", metricName)
@@ -433,3 +429,47 @@ func LabelsMatch(metric *dto.Metric, labelFilter map[string]string) bool {
433429

434430
return true
435431
}
432+
433+
// GetCounterVecFromGatherer collects a counter that matches the given name
434+
// from a gatherer implementing k8s.io/component-base/metrics.Gatherer interface.
435+
// It returns all counter values that had a label with a certain name in a map
436+
// that uses the label value as keys.
437+
//
438+
// Used only for testing purposes where we need to gather metrics directly from a running binary (without metrics endpoint).
439+
func GetCounterValuesFromGatherer(gatherer metrics.Gatherer, metricName string, lvMap map[string]string, labelName string) (map[string]float64, error) {
440+
m, err := gatherer.Gather()
441+
if err != nil {
442+
return nil, err
443+
}
444+
445+
metricFamily := findMetricFamily(m, metricName)
446+
if metricFamily == nil {
447+
return nil, fmt.Errorf("metric %q not found", metricName)
448+
}
449+
if len(metricFamily.GetMetric()) == 0 {
450+
return nil, fmt.Errorf("metric %q is empty", metricName)
451+
}
452+
453+
values := make(map[string]float64)
454+
for _, metric := range metricFamily.GetMetric() {
455+
if LabelsMatch(metric, lvMap) {
456+
if counter := metric.GetCounter(); counter != nil {
457+
for _, labelPair := range metric.Label {
458+
if labelPair.GetName() == labelName {
459+
values[labelPair.GetValue()] = counter.GetValue()
460+
}
461+
}
462+
}
463+
}
464+
}
465+
return values, nil
466+
}
467+
468+
func findMetricFamily(metricFamilies []*dto.MetricFamily, metricName string) *dto.MetricFamily {
469+
for _, mFamily := range metricFamilies {
470+
if mFamily.GetName() == metricName {
471+
return mFamily
472+
}
473+
}
474+
return nil
475+
}

staging/src/k8s.io/component-base/metrics/testutil/metrics_test.go

Lines changed: 102 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -20,6 +20,7 @@ import (
2020
"fmt"
2121
"math"
2222
"reflect"
23+
"strings"
2324
"testing"
2425

2526
"github.com/google/go-cmp/cmp"
@@ -591,3 +592,104 @@ func TestGetHistogramVecFromGatherer(t *testing.T) {
591592
})
592593
}
593594
}
595+
596+
func TestGetCounterValuesFromGatherer(t *testing.T) {
597+
namespace := "namespace"
598+
subsystem := "subsystem"
599+
name := "metric_test_name"
600+
metricName := fmt.Sprintf("%s_%s_%s", namespace, subsystem, name)
601+
602+
tests := map[string]struct {
603+
metricName string // Empty is replaced with valid name.
604+
lvMap map[string]string
605+
labelName string
606+
607+
wantCounterValues map[string]float64
608+
wantErr string
609+
}{
610+
"wrong-metric": {
611+
metricName: "no-such-metric",
612+
wantErr: `metric "no-such-metric" not found`,
613+
},
614+
615+
"none": {
616+
metricName: metricName,
617+
lvMap: map[string]string{"no-such-label": "a"},
618+
619+
wantCounterValues: map[string]float64{},
620+
},
621+
622+
"value1-0": {
623+
metricName: metricName,
624+
lvMap: map[string]string{"label1": "value1-0"},
625+
labelName: "label2",
626+
627+
wantCounterValues: map[string]float64{"value2-0": 1.5, "value2-1": 2.5},
628+
},
629+
630+
"value1-1": {
631+
metricName: metricName,
632+
lvMap: map[string]string{"label1": "value1-1"},
633+
labelName: "label2",
634+
635+
wantCounterValues: map[string]float64{"value2-0": 3.5, "value2-1": 4.5},
636+
},
637+
638+
"value1-1-value2-0-none": {
639+
metricName: metricName,
640+
lvMap: map[string]string{"label1": "value1-1", "label2": "value2-0"},
641+
labelName: "none",
642+
643+
wantCounterValues: map[string]float64{},
644+
},
645+
646+
"value1-0-value2-0-one": {
647+
metricName: metricName,
648+
lvMap: map[string]string{"label1": "value1-0", "label2": "value2-0"},
649+
labelName: "label2",
650+
651+
wantCounterValues: map[string]float64{"value2-0": 1.5},
652+
},
653+
}
654+
for name, tt := range tests {
655+
t.Run(name, func(t *testing.T) {
656+
// CounterVec has two labels defined.
657+
labels := []string{"label1", "label2"}
658+
counterOpts := &metrics.CounterOpts{
659+
Namespace: "namespace",
660+
Name: "metric_test_name",
661+
Subsystem: "subsystem",
662+
Help: "counter help message",
663+
}
664+
vec := metrics.NewCounterVec(counterOpts, labels)
665+
// Use local registry
666+
var registry = metrics.NewKubeRegistry()
667+
var gather metrics.Gatherer = registry
668+
registry.MustRegister(vec)
669+
// Observe two metrics with same value for label1 but different value of label2.
670+
vec.WithLabelValues("value1-0", "value2-0").Add(1.5)
671+
vec.WithLabelValues("value1-0", "value2-1").Add(2.5)
672+
vec.WithLabelValues("value1-1", "value2-0").Add(3.5)
673+
vec.WithLabelValues("value1-1", "value2-1").Add(4.5)
674+
675+
// The check for empty metric apparently cannot be tested: registering
676+
// a NewCounterVec with no values has the affect that it doesn't get
677+
// returned, leading to "not found".
678+
679+
counterValues, err := GetCounterValuesFromGatherer(gather, tt.metricName, tt.lvMap, tt.labelName)
680+
if err != nil {
681+
if tt.wantErr != "" && !strings.Contains(err.Error(), tt.wantErr) {
682+
t.Errorf("expected error %q, got instead: %v", tt.wantErr, err)
683+
}
684+
return
685+
}
686+
if tt.wantErr != "" {
687+
t.Fatalf("expected error %q, got none", tt.wantErr)
688+
}
689+
690+
if diff := cmp.Diff(tt.wantCounterValues, counterValues); diff != "" {
691+
t.Errorf("Got unexpected HistogramVec (-want +got):\n%s", diff)
692+
}
693+
})
694+
}
695+
}

test/integration/scheduler_perf/README.md

Lines changed: 19 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -175,3 +175,22 @@ the ci-benchmark-scheduler-perf periodic job will fail with an error log such as
175175
This allows to analyze which workload failed. Make sure that the failure is not an outlier
176176
by checking multiple runs of the job. If the failures are not related to any regression,
177177
but to an incorrect threshold setting, it is reasonable to decrease it.
178+
179+
### Visualization
180+
181+
Some support for visualizing progress over time is built into the
182+
benchmarks. The measurement operation which creates pods writes .dat files like
183+
this:
184+
185+
test/integration/scheduler_perf/SchedulingBasic_5000Nodes_2023-03-17T14:52:09Z.dat
186+
187+
This file is in a text format that [gnuplot](http://www.gnuplot.info/) can
188+
read. A wrapper script selects some suitable parameters:
189+
190+
test/integration/scheduler_perf/gnuplot.sh test/integration/scheduler_perf/*.dat
191+
192+
It plots in an interactive window by default. To write into a file, use
193+
194+
test/integration/scheduler_perf/gnuplot.sh \
195+
-e 'set term png; set output "<output>.png"' \
196+
test/integration/scheduler_perf/*.dat
Lines changed: 54 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,54 @@
1+
#!/usr/bin/env bash
2+
3+
# Copyright 2024 The Kubernetes Authors.
4+
#
5+
# Licensed under the Apache License, Version 2.0 (the "License");
6+
# you may not use this file except in compliance with the License.
7+
# You may obtain a copy of the License at
8+
#
9+
# http://www.apache.org/licenses/LICENSE-2.0
10+
#
11+
# Unless required by applicable law or agreed to in writing, software
12+
# distributed under the License is distributed on an "AS IS" BASIS,
13+
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14+
# See the License for the specific language governing permissions and
15+
# limitations under the License.
16+
17+
# Invoke this script with a list of *.dat and it'll plot them with gnuplot.
18+
# Any non-file parameter is passed through to gnuplot. By default,
19+
# an X11 window is used to display the result. To write into a file,
20+
# use
21+
# -e "set term png; set output <output>.png"
22+
23+
files=()
24+
args=( -e "set term x11 persist" )
25+
26+
for i in "$@"; do
27+
if [ -f "$i" ]; then
28+
files+=("$i")
29+
else
30+
args+=("$i")
31+
fi
32+
done
33+
34+
(
35+
cat <<EOF
36+
set ytics autofreq nomirror tc lt 1
37+
set xlabel 'measurement runtime [seconds]'
38+
set ylabel 'scheduling rate [pods/second]' tc lt 1
39+
set y2tics autofreq nomirror tc lt 2
40+
set y2label 'scheduling attempts per pod' tc lt 2
41+
42+
# Derivative from https://stackoverflow.com/questions/15751226/how-can-i-plot-the-derivative-of-a-graph-in-gnuplot.
43+
d2(x,y) = (\$0 == 0) ? (x1 = x, y1 = y, 1/0) : (x2 = x1, x1 = x, y2 = y1, y1 = y, (y1-y2)/(x1-x2))
44+
dx = 0.25
45+
46+
EOF
47+
echo -n "plot "
48+
for file in "${files[@]}"; do
49+
echo -n "'${file}' using (\$1 - dx):(d2(\$1, \$2)) with linespoints title '$(basename "$file" .dat | sed -e 's/_/ /g') metric rate' axis x1y1, "
50+
echo -n "'${file}' using (\$1 - dx):(d2(\$1, \$4)) with linespoints title '$(basename "$file" .dat | sed -e 's/_/ /g') observed rate' axis x1y1, "
51+
echo -n "'${file}' using 1:(\$3/\$2) with linespoints title '$(basename "$file" .dat | sed -e 's/_/ /g') attempts' axis x1y2, "
52+
done
53+
echo
54+
) | tee /dev/stderr | gnuplot "${args[@]}" -

test/integration/scheduler_perf/scheduler_perf.go

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1095,6 +1095,30 @@ func RunBenchmarkPerfScheduling(b *testing.B, outOfTreePluginRegistry frameworkr
10951095
// Reset metrics to prevent metrics generated in current workload gets
10961096
// carried over to the next workload.
10971097
legacyregistry.Reset()
1098+
1099+
// Exactly one result is expected to contain the progress information.
1100+
for _, item := range results {
1101+
if len(item.progress) == 0 {
1102+
continue
1103+
}
1104+
1105+
destFile, err := dataFilename(strings.ReplaceAll(fmt.Sprintf("%s_%s_%s.dat", tc.Name, w.Name, runID), "/", "_"))
1106+
if err != nil {
1107+
b.Fatalf("prepare data file: %v", err)
1108+
}
1109+
f, err := os.Create(destFile)
1110+
if err != nil {
1111+
b.Fatalf("create data file: %v", err)
1112+
}
1113+
1114+
// Print progress over time.
1115+
for _, sample := range item.progress {
1116+
fmt.Fprintf(f, "%.1fs %d %d %d %f\n", sample.ts.Sub(item.start).Seconds(), sample.completed, sample.attempts, sample.observedTotal, sample.observedRate)
1117+
}
1118+
if err := f.Close(); err != nil {
1119+
b.Fatalf("closing data file: %v", err)
1120+
}
1121+
}
10981122
})
10991123
}
11001124
})

test/integration/scheduler_perf/util.go

Lines changed: 48 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,6 +63,8 @@ const (
6363

6464
var dataItemsDir = flag.String("data-items-dir", "", "destination directory for storing generated data items for perf dashboard")
6565

66+
var runID = time.Now().Format(dateFormat)
67+
6668
func newDefaultComponentConfig() (*config.KubeSchedulerConfiguration, error) {
6769
gvk := kubeschedulerconfigv1.SchemeGroupVersion.WithKind("KubeSchedulerConfiguration")
6870
cfg := config.KubeSchedulerConfiguration{}
@@ -180,6 +182,10 @@ type DataItem struct {
180182
Unit string `json:"unit"`
181183
// Labels is the labels of the data item.
182184
Labels map[string]string `json:"labels,omitempty"`
185+
186+
// progress contains number of scheduled pods over time.
187+
progress []podScheduling
188+
start time.Time
183189
}
184190

185191
// DataItems is the data point set. It is the struct that perf dashboard expects.
@@ -188,6 +194,14 @@ type DataItems struct {
188194
DataItems []DataItem `json:"dataItems"`
189195
}
190196

197+
type podScheduling struct {
198+
ts time.Time
199+
attempts int
200+
completed int
201+
observedTotal int
202+
observedRate float64
203+
}
204+
191205
// makeBasePod creates a Pod object to be used as a template.
192206
func makeBasePod() *v1.Pod {
193207
basePod := &v1.Pod{
@@ -241,6 +255,17 @@ func dataItems2JSONFile(dataItems DataItems, namePrefix string) error {
241255
return os.WriteFile(destFile, formatted.Bytes(), 0644)
242256
}
243257

258+
func dataFilename(destFile string) (string, error) {
259+
if *dataItemsDir != "" {
260+
// Ensure the "dataItemsDir" path is valid.
261+
if err := os.MkdirAll(*dataItemsDir, 0750); err != nil {
262+
return "", fmt.Errorf("dataItemsDir path %v does not exist and cannot be created: %w", *dataItemsDir, err)
263+
}
264+
destFile = path.Join(*dataItemsDir, destFile)
265+
}
266+
return destFile, nil
267+
}
268+
244269
type labelValues struct {
245270
label string
246271
values []string
@@ -383,6 +408,9 @@ type throughputCollector struct {
383408
labels map[string]string
384409
namespaces sets.Set[string]
385410
errorMargin float64
411+
412+
progress []podScheduling
413+
start time.Time
386414
}
387415

388416
func newThroughputCollector(podInformer coreinformers.PodInformer, labels map[string]string, namespaces []string, errorMargin float64) *throughputCollector {
@@ -492,6 +520,7 @@ func (tc *throughputCollector) run(tCtx ktesting.TContext) {
492520
// sampling and creating pods get started independently.
493521
lastScheduledCount = scheduled
494522
lastSampleTime = now
523+
tc.start = now
495524
continue
496525
}
497526

@@ -524,6 +553,20 @@ func (tc *throughputCollector) run(tCtx ktesting.TContext) {
524553
for i := 0; i <= skipped; i++ {
525554
tc.schedulingThroughputs = append(tc.schedulingThroughputs, throughput)
526555
}
556+
557+
// Record the metric sample.
558+
counters, err := testutil.GetCounterValuesFromGatherer(legacyregistry.DefaultGatherer, "scheduler_schedule_attempts_total", map[string]string{"profile": "default-scheduler"}, "result")
559+
if err != nil {
560+
klog.Error(err)
561+
}
562+
tc.progress = append(tc.progress, podScheduling{
563+
ts: now,
564+
attempts: int(counters["unschedulable"] + counters["error"] + counters["scheduled"]),
565+
completed: int(counters["scheduled"]),
566+
observedTotal: scheduled,
567+
observedRate: throughput,
568+
})
569+
527570
lastScheduledCount = scheduled
528571
klog.Infof("%d pods have been scheduled successfully", lastScheduledCount)
529572
skipped = 0
@@ -533,7 +576,11 @@ func (tc *throughputCollector) run(tCtx ktesting.TContext) {
533576
}
534577

535578
func (tc *throughputCollector) collect() []DataItem {
536-
throughputSummary := DataItem{Labels: tc.labels}
579+
throughputSummary := DataItem{
580+
Labels: tc.labels,
581+
progress: tc.progress,
582+
start: tc.start,
583+
}
537584
if length := len(tc.schedulingThroughputs); length > 0 {
538585
sort.Float64s(tc.schedulingThroughputs)
539586
sum := 0.0

0 commit comments

Comments
 (0)