From 0e833bfc83f8356b7bfe257393583732572d34d7 Mon Sep 17 00:00:00 2001 From: Krzysztof Siedlecki Date: Fri, 25 May 2018 15:58:43 +0200 Subject: [PATCH] Fixing scheduling latency metrics --- cmd/kube-scheduler/app/BUILD | 1 + cmd/kube-scheduler/app/server.go | 21 ++++++-- pkg/scheduler/metrics/metrics.go | 83 ++++++++++++++++-------------- pkg/scheduler/scheduler.go | 6 +-- test/e2e/framework/BUILD | 1 + test/e2e/framework/metrics_util.go | 60 +++++++++++++++------ test/e2e/scalability/density.go | 3 +- 7 files changed, 111 insertions(+), 64 deletions(-) diff --git a/cmd/kube-scheduler/app/BUILD b/cmd/kube-scheduler/app/BUILD index d6de2aaef8..a98dc30914 100644 --- a/cmd/kube-scheduler/app/BUILD +++ b/cmd/kube-scheduler/app/BUILD @@ -21,6 +21,7 @@ go_library( "//pkg/scheduler/api:go_default_library", "//pkg/scheduler/api/latest:go_default_library", "//pkg/scheduler/factory:go_default_library", + "//pkg/scheduler/metrics:go_default_library", "//pkg/util/configz:go_default_library", "//pkg/util/flag:go_default_library", "//pkg/version:go_default_library", diff --git a/cmd/kube-scheduler/app/server.go b/cmd/kube-scheduler/app/server.go index 11ace1a983..ee776c89b6 100644 --- a/cmd/kube-scheduler/app/server.go +++ b/cmd/kube-scheduler/app/server.go @@ -19,6 +19,7 @@ package app import ( "fmt" + "io" "io/ioutil" "net/http" "os" @@ -51,6 +52,7 @@ import ( schedulerapi "k8s.io/kubernetes/pkg/scheduler/api" latestschedulerapi "k8s.io/kubernetes/pkg/scheduler/api/latest" "k8s.io/kubernetes/pkg/scheduler/factory" + "k8s.io/kubernetes/pkg/scheduler/metrics" "k8s.io/kubernetes/pkg/util/configz" utilflag "k8s.io/kubernetes/pkg/util/flag" "k8s.io/kubernetes/pkg/version" @@ -221,11 +223,23 @@ func buildHandlerChain(handler http.Handler, authn authenticator.Request, authz return handler } +func installMetricHandler(pathRecorderMux *mux.PathRecorderMux) { + configz.InstallHandler(pathRecorderMux) + defaultMetricsHandler := prometheus.Handler().ServeHTTP + pathRecorderMux.HandleFunc("/metrics", func(w http.ResponseWriter, req *http.Request) { + if req.Method == "DELETE" { + metrics.Reset() + io.WriteString(w, "metrics reset\n") + return + } + defaultMetricsHandler(w, req) + }) +} + // newMetricsHandler builds a metrics server from the config. func newMetricsHandler(config *componentconfig.KubeSchedulerConfiguration) http.Handler { pathRecorderMux := mux.NewPathRecorderMux("kube-scheduler") - configz.InstallHandler(pathRecorderMux) - pathRecorderMux.Handle("/metrics", prometheus.Handler()) + installMetricHandler(pathRecorderMux) if config.EnableProfiling { routes.Profiling{}.Install(pathRecorderMux) if config.EnableContentionProfiling { @@ -242,8 +256,7 @@ func newHealthzHandler(config *componentconfig.KubeSchedulerConfiguration, separ pathRecorderMux := mux.NewPathRecorderMux("kube-scheduler") healthz.InstallHandler(pathRecorderMux) if !separateMetrics { - configz.InstallHandler(pathRecorderMux) - pathRecorderMux.Handle("/metrics", prometheus.Handler()) + installMetricHandler(pathRecorderMux) } if config.EnableProfiling { routes.Profiling{}.Install(pathRecorderMux) diff --git a/pkg/scheduler/metrics/metrics.go b/pkg/scheduler/metrics/metrics.go index 4836ac4b93..0250ddb76d 100644 --- a/pkg/scheduler/metrics/metrics.go +++ b/pkg/scheduler/metrics/metrics.go @@ -23,29 +23,38 @@ import ( "github.com/prometheus/client_golang/prometheus" ) -const schedulerSubsystem = "scheduler" +const ( + // SchedulerSubsystem - subsystem name used by scheduler + SchedulerSubsystem = "scheduler" + // SchedulingLatencyName - scheduler latency metric name + SchedulingLatencyName = "scheduling_latencies_summary" + + // OperationLabel - operation label name + OperationLabel = "operation" + // Binding - binding operation label value + Binding = "binding" + // SchedulingAlgorithm - scheduling algorithm operation label value + SchedulingAlgorithm = "scheduling_algorithm" + // E2eScheduling - e2e scheduling operation label value + E2eScheduling = "e2e_scheduling" +) // All the histogram based metrics have 1ms as size for the smallest bucket. var ( - E2eSchedulingLatency = prometheus.NewHistogram( - prometheus.HistogramOpts{ - Subsystem: schedulerSubsystem, - Name: "e2e_scheduling_latency_microseconds", - Help: "E2e scheduling latency (scheduling algorithm + binding)", - Buckets: prometheus.ExponentialBuckets(1000, 2, 15), - }, - ) - SchedulingAlgorithmLatency = prometheus.NewHistogram( - prometheus.HistogramOpts{ - Subsystem: schedulerSubsystem, - Name: "scheduling_algorithm_latency_microseconds", - Help: "Scheduling algorithm latency", - Buckets: prometheus.ExponentialBuckets(1000, 2, 15), + SchedulingLatency = prometheus.NewSummaryVec( + prometheus.SummaryOpts{ + Subsystem: SchedulerSubsystem, + Name: SchedulingLatencyName, + Help: "Scheduling latency in microseconds split by sub-parts of the scheduling operation", + // Make the sliding window of 5h. + // TODO: The value for this should be based on some SLI definition (long term). + MaxAge: 5 * time.Hour, }, + []string{OperationLabel}, ) SchedulingAlgorithmPredicateEvaluationDuration = prometheus.NewHistogram( prometheus.HistogramOpts{ - Subsystem: schedulerSubsystem, + Subsystem: SchedulerSubsystem, Name: "scheduling_algorithm_predicate_evaluation", Help: "Scheduling algorithm predicate evaluation duration", Buckets: prometheus.ExponentialBuckets(1000, 2, 15), @@ -53,7 +62,7 @@ var ( ) SchedulingAlgorithmPriorityEvaluationDuration = prometheus.NewHistogram( prometheus.HistogramOpts{ - Subsystem: schedulerSubsystem, + Subsystem: SchedulerSubsystem, Name: "scheduling_algorithm_priority_evaluation", Help: "Scheduling algorithm priority evaluation duration", Buckets: prometheus.ExponentialBuckets(1000, 2, 15), @@ -61,52 +70,50 @@ var ( ) SchedulingAlgorithmPremptionEvaluationDuration = prometheus.NewHistogram( prometheus.HistogramOpts{ - Subsystem: schedulerSubsystem, + Subsystem: SchedulerSubsystem, Name: "scheduling_algorithm_preemption_evaluation", Help: "Scheduling algorithm preemption evaluation duration", Buckets: prometheus.ExponentialBuckets(1000, 2, 15), }, ) - BindingLatency = prometheus.NewHistogram( - prometheus.HistogramOpts{ - Subsystem: schedulerSubsystem, - Name: "binding_latency_microseconds", - Help: "Binding latency", - Buckets: prometheus.ExponentialBuckets(1000, 2, 15), - }, - ) PreemptionVictims = prometheus.NewGauge( prometheus.GaugeOpts{ - Subsystem: schedulerSubsystem, + Subsystem: SchedulerSubsystem, Name: "pod_preemption_victims", Help: "Number of selected preemption victims", }) PreemptionAttempts = prometheus.NewCounter( prometheus.CounterOpts{ - Subsystem: schedulerSubsystem, + Subsystem: SchedulerSubsystem, Name: "total_preemption_attempts", Help: "Total preemption attempts in the cluster till now", }) + metricsList = []prometheus.Collector{ + SchedulingLatency, + SchedulingAlgorithmPredicateEvaluationDuration, + SchedulingAlgorithmPriorityEvaluationDuration, + SchedulingAlgorithmPremptionEvaluationDuration, + PreemptionVictims, + PreemptionAttempts, + } ) var registerMetrics sync.Once // Register all metrics. func Register() { - // Register the metrics. registerMetrics.Do(func() { - prometheus.MustRegister(E2eSchedulingLatency) - prometheus.MustRegister(SchedulingAlgorithmLatency) - prometheus.MustRegister(BindingLatency) - - prometheus.MustRegister(SchedulingAlgorithmPredicateEvaluationDuration) - prometheus.MustRegister(SchedulingAlgorithmPriorityEvaluationDuration) - prometheus.MustRegister(SchedulingAlgorithmPremptionEvaluationDuration) - prometheus.MustRegister(PreemptionVictims) - prometheus.MustRegister(PreemptionAttempts) + for _, metric := range metricsList { + prometheus.MustRegister(metric) + } }) } +// Reset resets metrics +func Reset() { + SchedulingLatency.Reset() +} + // SinceInMicroseconds gets the time since the specified start in microseconds. func SinceInMicroseconds(start time.Time) float64 { return float64(time.Since(start).Nanoseconds() / time.Microsecond.Nanoseconds()) diff --git a/pkg/scheduler/scheduler.go b/pkg/scheduler/scheduler.go index 98beabe5c5..e6783b70db 100644 --- a/pkg/scheduler/scheduler.go +++ b/pkg/scheduler/scheduler.go @@ -429,7 +429,7 @@ func (sched *Scheduler) bind(assumed *v1.Pod, b *v1.Binding) error { return err } - metrics.BindingLatency.Observe(metrics.SinceInMicroseconds(bindingStart)) + metrics.SchedulingLatency.WithLabelValues(metrics.Binding).Observe(metrics.SinceInMicroseconds(bindingStart)) sched.config.Recorder.Eventf(assumed, v1.EventTypeNormal, "Scheduled", "Successfully assigned %v/%v to %v", assumed.Namespace, assumed.Name, b.Target.Name) return nil } @@ -461,7 +461,7 @@ func (sched *Scheduler) scheduleOne() { } return } - metrics.SchedulingAlgorithmLatency.Observe(metrics.SinceInMicroseconds(start)) + metrics.SchedulingLatency.WithLabelValues(metrics.SchedulingAlgorithm).Observe(metrics.SinceInMicroseconds(start)) // Tell the cache to assume that a pod now is running on a given node, even though it hasn't been bound yet. // This allows us to keep scheduling without waiting on binding to occur. assumedPod := pod.DeepCopy() @@ -496,7 +496,7 @@ func (sched *Scheduler) scheduleOne() { Name: suggestedHost, }, }) - metrics.E2eSchedulingLatency.Observe(metrics.SinceInMicroseconds(start)) + metrics.SchedulingLatency.WithLabelValues(metrics.E2eScheduling).Observe(metrics.SinceInMicroseconds(start)) if err != nil { glog.Errorf("Internal error binding pod: (%v)", err) } diff --git a/test/e2e/framework/BUILD b/test/e2e/framework/BUILD index 4997016456..892ef421f5 100644 --- a/test/e2e/framework/BUILD +++ b/test/e2e/framework/BUILD @@ -72,6 +72,7 @@ go_library( "//pkg/kubemark:go_default_library", "//pkg/master/ports:go_default_library", "//pkg/scheduler/algorithm/predicates:go_default_library", + "//pkg/scheduler/metrics:go_default_library", "//pkg/scheduler/schedulercache:go_default_library", "//pkg/security/podsecuritypolicy/seccomp:go_default_library", "//pkg/ssh:go_default_library", diff --git a/test/e2e/framework/metrics_util.go b/test/e2e/framework/metrics_util.go index f9c5370646..edd31c06ce 100644 --- a/test/e2e/framework/metrics_util.go +++ b/test/e2e/framework/metrics_util.go @@ -32,6 +32,7 @@ import ( "k8s.io/apimachinery/pkg/util/sets" clientset "k8s.io/client-go/kubernetes" "k8s.io/kubernetes/pkg/master/ports" + schedulermetric "k8s.io/kubernetes/pkg/scheduler/metrics" "k8s.io/kubernetes/pkg/util/system" "k8s.io/kubernetes/test/e2e/framework/metrics" @@ -130,6 +131,8 @@ func (m *MetricsForE2E) SummaryKind() string { return "MetricsForE2E" } +var SchedulingLatencyMetricName = model.LabelValue(schedulermetric.SchedulerSubsystem + "_" + schedulermetric.SchedulingLatencyName) + var InterestingApiServerMetrics = []string{ "apiserver_request_count", "apiserver_request_latencies_summary", @@ -439,27 +442,29 @@ func getMetrics(c clientset.Interface) (string, error) { return string(body), nil } -// Retrieves scheduler latency metrics. -func getSchedulingLatency(c clientset.Interface) (*SchedulingMetrics, error) { - result := SchedulingMetrics{} +// Sends REST request to kube scheduler metrics +func sendRestRequestToScheduler(c clientset.Interface, op string) (string, error) { + opUpper := strings.ToUpper(op) + if opUpper != "GET" && opUpper != "DELETE" { + return "", fmt.Errorf("Unknown REST request") + } - // Check if master Node is registered nodes, err := c.CoreV1().Nodes().List(metav1.ListOptions{}) ExpectNoError(err) - var data string var masterRegistered = false for _, node := range nodes.Items { if system.IsMasterNode(node.Name) { masterRegistered = true } } + + var responseText string if masterRegistered { ctx, cancel := context.WithTimeout(context.Background(), SingleCallTimeout) defer cancel() - var rawData []byte - rawData, err = c.CoreV1().RESTClient().Get(). + body, err := c.CoreV1().RESTClient().Verb(opUpper). Context(ctx). Namespace(metav1.NamespaceSystem). Resource("pods"). @@ -469,33 +474,46 @@ func getSchedulingLatency(c clientset.Interface) (*SchedulingMetrics, error) { Do().Raw() ExpectNoError(err) - data = string(rawData) + responseText = string(body) } else { // If master is not registered fall back to old method of using SSH. if TestContext.Provider == "gke" { Logf("Not grabbing scheduler metrics through master SSH: unsupported for gke") - return nil, nil + return "", nil } - cmd := "curl http://localhost:10251/metrics" + + cmd := "curl -X " + opUpper + " http://localhost:10251/metrics" sshResult, err := SSH(cmd, GetMasterHost()+":22", TestContext.Provider) if err != nil || sshResult.Code != 0 { - return &result, fmt.Errorf("unexpected error (code: %d) in ssh connection to master: %#v", sshResult.Code, err) + return "", fmt.Errorf("unexpected error (code: %d) in ssh connection to master: %#v", sshResult.Code, err) } - data = sshResult.Stdout + responseText = sshResult.Stdout } + return responseText, nil +} + +// Retrieves scheduler latency metrics. +func getSchedulingLatency(c clientset.Interface) (*SchedulingMetrics, error) { + result := SchedulingMetrics{} + data, err := sendRestRequestToScheduler(c, "GET") + samples, err := extractMetricSamples(data) if err != nil { return nil, err } for _, sample := range samples { + if sample.Metric[model.MetricNameLabel] != SchedulingLatencyMetricName { + continue + } + var metric *LatencyMetric = nil - switch sample.Metric[model.MetricNameLabel] { - case "scheduler_scheduling_algorithm_latency_microseconds": + switch sample.Metric[schedulermetric.OperationLabel] { + case schedulermetric.SchedulingAlgorithm: metric = &result.SchedulingLatency - case "scheduler_binding_latency_microseconds": + case schedulermetric.Binding: metric = &result.BindingLatency - case "scheduler_e2e_scheduling_latency_microseconds": + case schedulermetric.E2eScheduling: metric = &result.E2ELatency } if metric == nil { @@ -507,7 +525,7 @@ func getSchedulingLatency(c clientset.Interface) (*SchedulingMetrics, error) { if err != nil { return nil, err } - setQuantile(metric, quantile, time.Duration(int64(latency))*time.Microsecond) + setQuantile(metric, quantile, time.Duration(int64(latency))) } return &result, nil } @@ -521,6 +539,14 @@ func VerifySchedulerLatency(c clientset.Interface) (*SchedulingMetrics, error) { return latency, nil } +func ResetSchedulerMetrics(c clientset.Interface) error { + responseText, err := sendRestRequestToScheduler(c, "DELETE") + if err != nil || responseText != "metrics reset\n" { + return fmt.Errorf("Unexpected response: %q", responseText) + } + return nil +} + func PrettyPrintJSON(metrics interface{}) string { output := &bytes.Buffer{} if err := json.NewEncoder(output).Encode(metrics); err != nil { diff --git a/test/e2e/scalability/density.go b/test/e2e/scalability/density.go index 1ef125d874..706f63068d 100644 --- a/test/e2e/scalability/density.go +++ b/test/e2e/scalability/density.go @@ -395,8 +395,6 @@ var _ = SIGDescribe("Density", func() { } // Verify scheduler metrics. - // TODO: Reset metrics at the beginning of the test. - // We should do something similar to how we do it for APIserver. latency, err := framework.VerifySchedulerLatency(c) framework.ExpectNoError(err) if err == nil { @@ -442,6 +440,7 @@ var _ = SIGDescribe("Density", func() { uuid = string(utiluuid.NewUUID()) + framework.ExpectNoError(framework.ResetSchedulerMetrics(c)) framework.ExpectNoError(framework.ResetMetrics(c)) framework.ExpectNoError(os.Mkdir(fmt.Sprintf(framework.TestContext.OutputDir+"/%s", uuid), 0777))