feat/metrics : add new metrics for measuring skipper latency (#3506)

This change involves adding a new metric to measure the overall skipper
latency of a request. i.e., the time taken by a request in skipper
itself, so this does not include time taken for serving for the response
to client and the time taken for the backend round trip.

skipper latency = serve duration - response duration - backend duration

---------

Signed-off-by: speruri <surya.srikar.peruri@zalando.de>
Co-authored-by: speruri <surya.srikar.peruri@zalando.de>

Author: ayruslore

config/config.go

@@ -93,6 +93,8 @@ type Config struct {
 	ServeMethodMetric                   bool      `yaml:"serve-method-metric"`
 	ServeStatusCodeMetric               bool      `yaml:"serve-status-code-metric"`
 	BackendHostMetrics                  bool      `yaml:"backend-host-metrics"`
+	ProxyRequestMetrics                 bool      `yaml:"proxy-request-metrics"`
+	ProxyResponseMetrics                bool      `yaml:"proxy-response-metrics"`
 	AllFiltersMetrics                   bool      `yaml:"all-filters-metrics"`
 	CombinedResponseMetrics             bool      `yaml:"combined-response-metrics"`
 	RouteResponseMetrics                bool      `yaml:"route-response-metrics"`
@@ -409,6 +411,8 @@ func NewConfig() *Config {
 	flag.BoolVar(&cfg.ServeMethodMetric, "serve-method-metric", true, "enables the HTTP method as a domain of the total serve time metric. It affects both route and host split metrics")
 	flag.BoolVar(&cfg.ServeStatusCodeMetric, "serve-status-code-metric", true, "enables the HTTP response status code as a domain of the total serve time metric. It affects both route and host split metrics")
 	flag.BoolVar(&cfg.BackendHostMetrics, "backend-host-metrics", false, "enables reporting total serve time metrics for each backend")
+	flag.BoolVar(&cfg.ProxyRequestMetrics, "proxy-request-metrics", false, "enables reporting latency / time spent in handling the request part of the proxy operation i.e., the duration from entry till before the backend round trip")
+	flag.BoolVar(&cfg.ProxyResponseMetrics, "proxy-response-metrics", false, "enables reporting latency / time spent in handling the reponse part of the proxy operation i.e., the duration from after the backend round trip till the response is served")
 	flag.BoolVar(&cfg.AllFiltersMetrics, "all-filters-metrics", false, "enables reporting combined filter metrics for each route")
 	flag.BoolVar(&cfg.CombinedResponseMetrics, "combined-response-metrics", false, "enables reporting combined response time metrics")
 	flag.BoolVar(&cfg.RouteResponseMetrics, "route-response-metrics", false, "enables reporting response time metrics for each route")
@@ -822,6 +826,8 @@ func (c *Config) ToOptions() skipper.Options {
 		EnableServeHostCounter:              c.ServeHostCounter,
 		EnableServeMethodMetric:             c.ServeMethodMetric,
 		EnableServeStatusCodeMetric:         c.ServeStatusCodeMetric,
+		EnableProxyRequestMetrics:           c.ProxyRequestMetrics,
+		EnableProxyResponseMetrics:          c.ProxyResponseMetrics,
 		EnableBackendHostMetrics:            c.BackendHostMetrics,
 		EnableAllFiltersMetrics:             c.AllFiltersMetrics,
 		EnableCombinedResponseMetrics:       c.CombinedResponseMetrics,

docs/operation/operation.md

@@ -210,6 +210,7 @@ common metrics endpoint :9911/metrics.
 
 To monitor skipper we recommend the following queries:
 
+- P99 Proxy latency: `histogram_quantile(0.99, sum(rate(skipper_proxy_total_duration_seconds_bucket{}[1m])) by (le))`
 - P99 backend latency: `histogram_quantile(0.99, sum(rate(skipper_serve_host_duration_seconds_bucket{}[1m])) by (le))`
 - HTTP 2xx rate: `histogram_quantile(0.99, sum(rate(skipper_serve_host_duration_seconds_bucket{code =~ "2.*"}[1m])) by (le) )`
 - HTTP 4xx rate: `histogram_quantile(0.99, sum(rate(skipper_serve_host_duration_seconds_bucket{code =~ "4.*"}[1m])) by (le) )`
@@ -225,6 +226,85 @@ To monitor skipper we recommend the following queries:
 
 You may add static metrics labels like `version` using Prometheus [relabeling feature](https://prometheus.io/docs/prometheus/latest/configuration/configuration/#relabel_config).
 
+### Proxy Metrics
+
+Skipper Proxy Metrics provides information about the time spent by skipper in processing a request i.e., the time spent by a request inside skipper (this excludes the response application of filters to a req/res, the backend roundtrip and serving the response). The total proxy metrics are enabled by default and these metrics can be used to build KPIs / SLOs, so as to understand and monitor the performance of skipper.
+
+The Proxy Metrics exludes the filter processing as this is dependent on which filters the user decides to use for a particular route. The backend round trip time depends on the backend application and the operation being performed. And the serve response depends on the client. These are operations are not in control of skipper and are hence excluded to solely monitor the performance of Skipper.
+
+These metrics are exposed in /metrics, the example json structure looks like this:
+
+```json
+{
+  "timers" : {
+    "skipper.proxy.total": {
+      "15m.rate": 0.2,
+      "1m.rate": 0.2,
+      "5m.rate": 0.2,
+      "75%": 288375,
+      "95%": 288375,
+      "99%": 288375,
+      "99.9%": 288375,
+      "count": 1,
+      "max": 288375,
+      "mean": 288375,
+      "mean.rate": 0.7268368234069077,
+      "median": 288375,
+      "min": 288375,
+      "stddev": 0
+    },
+  }
+}
+```
+
+The proxy metrics can also be fetched in more detail, i.e., splits the proxy total metrics to get the proxy request metrics and proxy response metrics. The Proxy Request Metrics provides the duration / time taken from the start of ServeHTTP till the backend round trip. The Proxy Response Metrics provides the duration / time taken from after the backend round trip till the response is served.
+
+    -proxy-request-metrics
+        enbales the collection proxy request metrics
+    -proxy-response-metrics
+        enables the collection proxy response metrics
+
+If enabled these metrics are also exposed in /metrics, and the example json structure would like the following:
+
+```json
+{
+  "timers": {
+    "skipper.proxy.request": {
+      "15m.rate": 0.2,
+      "1m.rate": 0.2,
+      "5m.rate": 0.2,
+      "75%": 0,
+      "95%": 0,
+      "99%": 0,
+      "99.9%": 0,
+      "count": 1,
+      "max": 0,
+      "mean": 0,
+      "mean.rate": 0.7268396413261223,
+      "median": 0,
+      "min": 0,
+      "stddev": 0
+    },
+    "skipper.proxy.response": {
+      "15m.rate": 0.2,
+      "1m.rate": 0.2,
+      "5m.rate": 0.2,
+      "75%": 288375,
+      "95%": 288375,
+      "99%": 288375,
+      "99.9%": 288375,
+      "count": 1,
+      "max": 288375,
+      "mean": 288375,
+      "mean.rate": 0.7268397290232465,
+      "median": 288375,
+      "min": 288375,
+      "stddev": 0
+    },
+  }
+}
+```
+
 ### Connection metrics
 
 This option will enable known loadbalancer connections metrics, like

metrics/all_kind.go

@@ -89,6 +89,11 @@ func (a *All) MeasureResponse(code int, method string, routeId string, start tim
 	a.codaHale.MeasureResponse(code, method, routeId, start)
 }
 
+func (a *All) MeasureProxy(requestDuration, responseDuration time.Duration) {
+	a.prometheus.MeasureProxy(requestDuration, responseDuration)
+	a.codaHale.MeasureProxy(requestDuration, responseDuration)
+}
+
 func (a *All) MeasureServe(routeId, host, method string, code int, start time.Time) {
 	a.prometheus.MeasureServe(routeId, host, method, code, start)
 	a.codaHale.MeasureServe(routeId, host, method, code, start)

metrics/codahale.go

@@ -27,6 +27,9 @@ const (
 	KeyResponse                   = "response.%d.%s.skipper.%s"
 	KeyResponseCombined           = "all.response.%d.%s.skipper"
 	Key5xxsBackend                = "all.backend.5xx"
+	KeyProxyTotal                 = "proxy.total"
+	KeyProxyRequest               = "proxy.request"
+	KeyProxyResponse              = "proxy.response"
 
 	KeyErrorsBackend   = "errors.backend.%s"
 	KeyErrorsStreaming = "errors.streaming.%s"
@@ -182,6 +185,17 @@ func (c *CodaHale) MeasureResponse(code int, method string, routeId string, star
 	}
 }
 
+func (c *CodaHale) MeasureProxy(requestDuration, responseDuration time.Duration) {
+	skipperDuration := requestDuration + responseDuration
+	c.updateTimer(KeyProxyTotal, skipperDuration)
+	if c.options.EnableProxyRequestMetrics {
+		c.updateTimer(KeyProxyRequest, requestDuration)
+	}
+	if c.options.EnableProxyResponseMetrics {
+		c.updateTimer(KeyProxyResponse, responseDuration)
+	}
+}
+
 func (c *CodaHale) MeasureServe(routeId, host, method string, code int, start time.Time) {
 	if !(c.options.EnableServeRouteMetrics || c.options.EnableServeHostMetrics) {
 		return

metrics/codahale_test.go

@@ -525,3 +525,100 @@ func TestCodaHaleServeMetrics(t *testing.T) {
 		})
 	}
 }
+
+type latencyMetricsTestItem struct {
+	msg              string
+	requestDuration  time.Duration
+	responseDuration time.Duration
+	enabledRequest   bool
+	enabledResponse  bool
+}
+
+func TestCodaHaleProxyLatencyMetrics(t *testing.T) {
+	if testing.Short() {
+		t.Skip()
+	}
+
+	for _, ti := range []latencyMetricsTestItem{
+		{
+			msg:              "request and response disabled",
+			requestDuration:  100 * time.Millisecond,
+			responseDuration: 200 * time.Millisecond,
+			enabledRequest:   false,
+			enabledResponse:  false,
+		},
+		{
+			msg:              "request enabled, response disabled",
+			requestDuration:  10 * time.Millisecond,
+			responseDuration: 20 * time.Millisecond,
+			enabledRequest:   true,
+			enabledResponse:  false,
+		},
+		{
+			msg:              "request disabled, response enabled",
+			requestDuration:  300 * time.Millisecond,
+			responseDuration: 100 * time.Millisecond,
+			enabledRequest:   false,
+			enabledResponse:  true,
+		},
+		{
+			msg:              "request and response enabled",
+			requestDuration:  150 * time.Millisecond,
+			responseDuration: 200 * time.Millisecond,
+			enabledRequest:   true,
+			enabledResponse:  true,
+		},
+	} {
+		t.Run(ti.msg, func(t *testing.T) {
+			checkMetrics := func(m *CodaHale, key string, enabled bool, count int64, duration time.Duration) (bool, string) {
+				v := m.reg.Get(key)
+
+				switch {
+				case enabled && v == nil:
+					return false, "metric not found in the registry"
+				case !enabled && v != nil:
+					return false, "unexpected metrics"
+				case !enabled && v == nil:
+					return true, ""
+				}
+
+				tr, ok := v.(metrics.Timer)
+				if !ok {
+					return false, "invalid metric type"
+				}
+
+				trs := tr.Snapshot()
+
+				if trs.Count() != count {
+					return false, fmt.Sprintf("failed to get the right count: %d instead of %d", trs.Count(), count)
+				}
+
+				if trs.Max() > int64(duration) || trs.Min() < int64(duration) {
+					return false, "failed to get the right duration"
+				}
+
+				return true, ""
+			}
+
+			o := Options{
+				EnableProxyRequestMetrics:  ti.enabledRequest,
+				EnableProxyResponseMetrics: ti.enabledResponse,
+			}
+			c := NewCodaHale(o)
+			defer c.Close()
+
+			c.MeasureProxy(ti.requestDuration, ti.responseDuration)
+			time.Sleep(10 * time.Millisecond)
+
+			if ok, reason := checkMetrics(c, KeyProxyTotal, true, 1, ti.requestDuration+ti.responseDuration); !ok {
+				t.Errorf("error processing metric '%s': %s", KeyProxyTotal, reason)
+			}
+			if ok, reason := checkMetrics(c, KeyProxyRequest, ti.enabledRequest, 1, ti.requestDuration); !ok {
+				t.Errorf("error processing metric '%s': %s", KeyProxyRequest, reason)
+			}
+			if ok, reason := checkMetrics(c, KeyProxyResponse, ti.enabledResponse, 1, ti.responseDuration); !ok {
+				t.Errorf("error processing metric '%s': %s", KeyProxyResponse, reason)
+			}
+		})
+	}
+}

metrics/metrics.go

@@ -70,6 +70,7 @@ type Metrics interface {
 	MeasureFilterResponse(filterName string, start time.Time)
 	MeasureAllFiltersResponse(routeId string, start time.Time)
 	MeasureResponse(code int, method string, routeId string, start time.Time)
+	MeasureProxy(requestDuration, responseDuration time.Duration)
 	MeasureServe(routeId, host, method string, code int, start time.Time)
 	IncRoutingFailures()
 	IncErrorsBackend(routeId string)
@@ -130,6 +131,18 @@ type Options struct {
 	// both route and host split metrics.
 	EnableServeStatusCodeMetric bool
 
+	// If set, the total request handling time taken by skipper will be
+	// collected. It measures the duration taken by skipper to process
+	// the request, from the start excluding the filters processing and
+	// until the backend round trip is started.
+	EnableProxyRequestMetrics bool
+
+	// If set, the total response handling time take by skipper will be
+	// collected. It measures the duration taken by skipper to process the
+	// response, from after the backend round trip is finished, excluding
+	// the filters processing and until the before the response is served.
+	EnableProxyResponseMetrics bool
+
 	// If set, detailed response time metrics will be collected
 	// for each backend host
 	EnableBackendHostMetrics bool

metrics/metricstest/metricsmock.go

@@ -148,6 +148,22 @@ func (m *MockMetrics) MeasureResponse(code int, method string, routeId string, s
 	// implement me
 }
 
+func (m *MockMetrics) MeasureProxy(requestDuration, responseDuration time.Duration) {
+	totalDuration := requestDuration + responseDuration
+	totalDurationKey := fmt.Sprintf("%sproxy.total.duration", m.Prefix)
+	m.WithMeasures(func(measures map[string][]time.Duration) {
+		measures[totalDurationKey] = append(measures[totalDurationKey], totalDuration)
+	})
+	requestDurationKey := fmt.Sprintf("%sproxy.request.duration", m.Prefix)
+	m.WithMeasures(func(measures map[string][]time.Duration) {
+		measures[requestDurationKey] = append(measures[requestDurationKey], requestDuration)
+	})
+	responseDurationKey := fmt.Sprintf("%sproxy.response.duration", m.Prefix)
+	m.WithMeasures(func(measures map[string][]time.Duration) {
+		measures[responseDurationKey] = append(measures[responseDurationKey], responseDuration)
+	})
+}
+
 func (m *MockMetrics) MeasureServe(routeId, host, method string, code int, start time.Time) {
 	// implement me
 }