From ac644b95337fc4e88cf865b400112aca804b942c Mon Sep 17 00:00:00 2001 From: AlexandreBrg Date: Sun, 14 May 2023 01:01:11 +0200 Subject: [PATCH] feat(controller): add timimg http header responses Signed-off-by: AlexandreBrg --- controller/api/handlers/invoke-function.go | 10 +++- controller/api/handlers/types.go | 67 ++++++++++++++++++++++ 2 files changed, 75 insertions(+), 2 deletions(-) diff --git a/controller/api/handlers/invoke-function.go b/controller/api/handlers/invoke-function.go index c4f37df..4c1e55e 100644 --- a/controller/api/handlers/invoke-function.go +++ b/controller/api/handlers/invoke-function.go @@ -25,7 +25,8 @@ var ( func InvokeFunctionHandler(s state.State, orch orchestration.Orchestrator) gin.HandlerFunc { return func(c *gin.Context) { - start := time.Now() + // Start the analytics + analytics := NewInvokeAnalytics() ctx, fnName, fnVersion := c.Request.Context(), c.Param("name"), c.Param("version") log.Debugf("Invoke version '%s' of function '%s'", fnVersion, fnName) @@ -71,6 +72,7 @@ func InvokeFunctionHandler(s state.State, orch orchestration.Orchestrator) gin.H log.Infof("Function '%s' is healthy and ready to receive requests", fnName) break } + analytics.UpsertOrchestrate() // Each invocation warn up function for 15 minutes if err := s.SetWithExpiry(ctx, instance.Id, 15*time.Minute); err != nil { @@ -85,7 +87,7 @@ func InvokeFunctionHandler(s state.State, orch orchestration.Orchestrator) gin.H proxy.ModifyResponse = func(r *http.Response) error { // Record the execution time of the invocation - elapsed := time.Since(start).Seconds() + elapsed := float64(analytics.UpsertInvoke()) / 1000 log.Debugf("Function '%s' was invoked in %vs (is cold start: %v)", fnName, elapsed, isColdStart) telemetry.FunctionInvocationDurationHistogram.WithLabelValues(labels...).Observe(elapsed) @@ -119,6 +121,10 @@ func InvokeFunctionHandler(s state.State, orch orchestration.Orchestrator) gin.H r.ContentLength = int64(contentLength) r.Header.Set("Content-Length", strconv.Itoa(contentLength)) + r.Header.Set(string(HttpHeaderFunctionResponseTime), strconv.FormatInt(analytics.UpsertInvoke(), 10)) + r.Header.Set(string(HttpHeaderOrchestrateResponseTime), strconv.FormatInt(analytics.UpsertOrchestrate(), 10)) + r.Header.Set(string(HttpHeaderMortyResponseTime), strconv.FormatInt(analytics.UpsertTotal(), 10)) + return nil } diff --git a/controller/api/handlers/types.go b/controller/api/handlers/types.go index 68d13f5..7093bce 100644 --- a/controller/api/handlers/types.go +++ b/controller/api/handlers/types.go @@ -1,5 +1,21 @@ package handlers +import "time" + +type CustomHttpHeader string + +const ( + // Function-Response-Time + // ref: https://github.com/morty-faas/morty/issues/25 + HttpHeaderFunctionResponseTime CustomHttpHeader = "Function-Response-Time" + // Orchestrate-Response-Time + // ref: https://github.com/morty-faas/morty/issues/25 + HttpHeaderOrchestrateResponseTime CustomHttpHeader = "Orchestrate-Response-Time" + // Morty-Response-Time + // ref: https://github.com/morty-faas/morty/issues/25 + HttpHeaderMortyResponseTime CustomHttpHeader = "Morty-Response-Time" +) + type APIError struct { Message string `json:"message"` } @@ -9,3 +25,54 @@ func makeApiError(err error) *APIError { Message: err.Error(), } } + +// InvokeAnalytics contains few information about the function invocation, it can be used for debugging purposes +// and for benchmarking +type InvokeAnalytics struct { + start time.Time + // Total is the total time spent in the function handler, from the moment the request is received until the + // response is sent back to the client + total int64 + // Orchestrate is the time spent in the orchestration layer, from the moment the request is received until the + // function is deployed and ready to be invoked + orchestrate int64 + // Invoke is the time spent in the function handler, from the moment the function is invoked until the response + // is sent back to the client + invoke int64 +} + +func NewInvokeAnalytics() *InvokeAnalytics { + return &InvokeAnalytics{ + start: time.Now(), + } +} + +// UpsertOrchestrate returns the time spent in the orchestration layer, in milliseconds. If the value is not set, it will +// be calculated else it will return a cached value. +func (i *InvokeAnalytics) UpsertOrchestrate() int64 { + if i.orchestrate != 0 { + return i.orchestrate + } + i.orchestrate = time.Since(i.start).Milliseconds() + return i.orchestrate +} + +// UpsertInvoke returns the time spent in for the invoke, in milliseconds. If the value is not set, it will be calculated +// else it will return a cached value. +func (i *InvokeAnalytics) UpsertInvoke() int64 { + if i.invoke != 0 { + return i.invoke + } + i.invoke = time.Since(i.start).Milliseconds() - i.UpsertOrchestrate() + return i.invoke +} + +// UpsertTotal returns the total time spent in the function handler, in milliseconds. If it's the first call to this +// method, it will register the time spent since start and return it, otherwise it will return the cached value. +func (i *InvokeAnalytics) UpsertTotal() int64 { + if i.total != 0 { + return i.total + } + i.total = time.Since(i.start).Milliseconds() + return i.total +}