Record metrics for invocations when they start

* This experimental patch records metrics as invocations start
so that the metrics can be used to make better scale to zero
decisions in faas-idler.

Tested with Kubernetes on a single-node cluster, metrics
reported as expected. Existing metrics still report.

Signed-off-by: Alex Ellis (OpenFaaS Ltd) <alexellis2@gmail.com>

gateway/Dockerfile

@@ -28,7 +28,7 @@ COPY queue          queue
 COPY plugin         plugin
 COPY version        version
 COPY scaling        scaling
-COPY server.go      .
+COPY main.go      .
 
 # Run a gofmt and exclude all vendored code.
 RUN license-check -path ./ --verbose=false "Alex Ellis" "OpenFaaS Authors" "OpenFaaS Author(s)" \

gateway/Dockerfile.arm64

@@ -25,7 +25,7 @@ COPY queue          queue
 COPY plugin         plugin
 COPY version        version
 COPY scaling        scaling
-COPY server.go      .
+COPY main.go      .
 
 # Run a gofmt and exclude all vendored code.
 RUN license-check -path ./ --verbose=false "Alex Ellis" "OpenFaaS Project" "OpenFaaS Authors" "OpenFaaS Author(s)" \

gateway/Dockerfile.armhf

@@ -25,7 +25,7 @@ COPY queue          queue
 COPY plugin         plugin
 COPY version        version
 COPY scaling        scaling
-COPY server.go      .
+COPY main.go      .
 
 # Run a gofmt and exclude all vendored code.
 RUN license-check -path ./ --verbose=false "Alex Ellis" "OpenFaaS Project" "OpenFaaS Authors" "OpenFaaS Author(s)" \

gateway/handlers/forwarding_proxy.go

@@ -53,9 +53,12 @@ func MakeForwardingProxyHandler(proxy *types.HTTPClientReverseProxy,
 	return func(w http.ResponseWriter, r *http.Request) {
 		baseURL := baseURLResolver.Resolve(r)
 		originalURL := r.URL.String()
-
 		requestURL := urlPathTransformer.Transform(r)
 
+		for _, notifier := range notifiers {
+			notifier.Notify(r.Method, requestURL, originalURL, http.StatusProcessing, "started", time.Second*0)
+		}
+
 		start := time.Now()
 
 		statusCode, err := forwardRequest(w, r, proxy.Client, baseURL, requestURL, proxy.Timeout, writeRequestURI, serviceAuthInjector)
@@ -66,7 +69,7 @@ func MakeForwardingProxyHandler(proxy *types.HTTPClientReverseProxy,
 		}
 
 		for _, notifier := range notifiers {
-			notifier.Notify(r.Method, requestURL, originalURL, statusCode, seconds)
+			notifier.Notify(r.Method, requestURL, originalURL, statusCode, "completed", seconds)
 		}
 	}
 }

gateway/handlers/notifier_handler.go

@@ -18,7 +18,7 @@ func MakeNotifierWrapper(next http.HandlerFunc, notifiers []HTTPNotifier) http.H
 
 		url := r.URL.String()
 		for _, notifier := range notifiers {
-			notifier.Notify(r.Method, url, url, writer.Status(), time.Since(then))
+			notifier.Notify(r.Method, url, url, writer.Status(), "completed", time.Since(then))
 		}
 	}
 }

gateway/handlers/notifier_wrapper_test.go

@@ -84,6 +84,6 @@ type testNotifier struct {
 }
 
 // Notify about service metrics
-func (tf *testNotifier) Notify(method string, URL string, originalURL string, statusCode int, duration time.Duration) {
+func (tf *testNotifier) Notify(method string, URL string, originalURL string, statusCode int, event string, duration time.Duration) {
 	tf.StatusReceived = statusCode
 }

gateway/handlers/notifiers.go

@@ -13,7 +13,7 @@ import (
 
 // HTTPNotifier notify about HTTP request/response
 type HTTPNotifier interface {
-	Notify(method string, URL string, originalURL string, statusCode int, duration time.Duration)
+	Notify(method string, URL string, originalURL string, statusCode int, event string, duration time.Duration)
 }
 
 // PrometheusServiceNotifier notifier for core service endpoints
@@ -22,7 +22,7 @@ type PrometheusServiceNotifier struct {
 }
 
 // Notify about service metrics
-func (psn PrometheusServiceNotifier) Notify(method string, URL string, originalURL string, statusCode int, duration time.Duration) {
+func (psn PrometheusServiceNotifier) Notify(method string, URL string, originalURL string, statusCode int, event string, duration time.Duration) {
 	code := fmt.Sprintf("%d", statusCode)
 	path := urlToLabel(URL)
 
@@ -46,19 +46,26 @@ type PrometheusFunctionNotifier struct {
 }
 
 // Notify records metrics in Prometheus
-func (p PrometheusFunctionNotifier) Notify(method string, URL string, originalURL string, statusCode int, duration time.Duration) {
-	seconds := duration.Seconds()
-	serviceName := getServiceName(originalURL)
+func (p PrometheusFunctionNotifier) Notify(method string, URL string, originalURL string, statusCode int, event string, duration time.Duration) {
+	if event == "completed" {
 
-	p.Metrics.GatewayFunctionsHistogram.
-		WithLabelValues(serviceName).
-		Observe(seconds)
+		seconds := duration.Seconds()
+		serviceName := getServiceName(originalURL)
 
-	code := strconv.Itoa(statusCode)
+		p.Metrics.GatewayFunctionsHistogram.
+			WithLabelValues(serviceName).
+			Observe(seconds)
+
+		code := strconv.Itoa(statusCode)
+
+		p.Metrics.GatewayFunctionInvocation.
+			With(prometheus.Labels{"function_name": serviceName, "code": code}).
+			Inc()
+	} else if event == "started" {
+		serviceName := getServiceName(originalURL)
+		p.Metrics.StartedCounter.WithLabelValues(serviceName).Inc()
+	}
 
-	p.Metrics.GatewayFunctionInvocation.
-		With(prometheus.Labels{"function_name": serviceName, "code": code}).
-		Inc()
 }
 
 func getServiceName(urlValue string) string {
@@ -83,7 +90,9 @@ func getServiceName(urlValue string) string {
 type LoggingNotifier struct {
 }
 
-// Notify a log about a request
-func (LoggingNotifier) Notify(method string, URL string, originalURL string, statusCode int, duration time.Duration) {
-	log.Printf("Forwarded [%s] to %s - [%d] - %fs", method, originalURL, statusCode, duration.Seconds())
+// Notify the LoggingNotifier about a request
+func (LoggingNotifier) Notify(method string, URL string, originalURL string, statusCode int, event string, duration time.Duration) {
+	if event == "completed" {
+		log.Printf("Forwarded [%s] to %s - [%d] - %fs seconds", method, originalURL, statusCode, duration.Seconds())
+	}
 }

gateway/metrics/exporter.go

@@ -41,6 +41,7 @@ func (e *Exporter) Describe(ch chan<- *prometheus.Desc) {
 	e.metricOptions.GatewayFunctionInvocation.Describe(ch)
 	e.metricOptions.GatewayFunctionsHistogram.Describe(ch)
 	e.metricOptions.ServiceReplicasGauge.Describe(ch)
+	e.metricOptions.StartedCounter.Describe(ch)
 
 	e.metricOptions.ServiceMetrics.Counter.Describe(ch)
 	e.metricOptions.ServiceMetrics.Histogram.Describe(ch)
@@ -51,6 +52,8 @@ func (e *Exporter) Collect(ch chan<- prometheus.Metric) {
 	e.metricOptions.GatewayFunctionInvocation.Collect(ch)
 	e.metricOptions.GatewayFunctionsHistogram.Collect(ch)
 
+	e.metricOptions.StartedCounter.Collect(ch)
+
 	e.metricOptions.ServiceReplicasGauge.Reset()
 	for _, service := range e.services {
 		e.metricOptions.ServiceReplicasGauge.

gateway/metrics/metrics.go

@@ -17,6 +17,7 @@ type MetricOptions struct {
 	GatewayFunctionsHistogram *prometheus.HistogramVec
 	ServiceReplicasGauge      *prometheus.GaugeVec
 	ServiceMetrics            *ServiceMetricOptions
+	StartedCounter            *prometheus.CounterVec
 }
 
 // ServiceMetricOptions provides RED metrics
@@ -81,6 +82,16 @@ func BuildMetricsOptions() MetricOptions {
 		[]string{"method", "path", "status"},
 	)
 
+	startedCounter := prometheus.NewCounterVec(
+		prometheus.CounterOpts{
+			Namespace: "gateway",
+			Subsystem: "function",
+			Name:      "invocation_started",
+			Help:      "The total number of function HTTP requests started.",
+		},
+		[]string{"function_name"},
+	)
+
 	serviceMetricOptions := &ServiceMetricOptions{
 		Counter:   counter,
 		Histogram: histogram,
@@ -91,6 +102,7 @@ func BuildMetricsOptions() MetricOptions {
 		GatewayFunctionInvocation: gatewayFunctionInvocation,
 		ServiceReplicasGauge:      serviceReplicas,
 		ServiceMetrics:            serviceMetricOptions,
+		StartedCounter:            startedCounter,
 	}
 
 	return metricsOptions

gateway/vendor/github.com/gorilla/mux/go.mod

@@ -1 +1,3 @@
 module github.com/gorilla/mux
+
+go 1.13