feat(tracing): print execution times if SAGE_TRACE=true

Set the SAGE_TRACE env var to true to output execution times for
targets. Can be useful in CI to see what is slowing things down.

sg/initfile.go

@@ -47,6 +47,7 @@ func generateInitFile(g *codegen.File, pkg *doc.Package, mks []Makefile) error {
 		if strings.Contains(loggerName, ":") {
 			loggerName = strings.Split(loggerName, ":")[1]
 		}
+		g.P("before := ", g.Import("time"), ".Now()")
 		g.P("logger := ", g.Import("go.einride.tech/sage/sg"), ".NewLogger(\"", loggerName, "\")")
 		g.P("ctx = ", g.Import("go.einride.tech/sage/sg"), ".WithLogger(ctx, logger)")
 		if len(function.Decl.Type.Params.List) > 1 {
@@ -90,14 +91,17 @@ func generateInitFile(g *codegen.File, pkg *doc.Package, mks []Makefile) error {
 				")",
 			)
 			g.P("if err != nil {")
+			g.P(`if os.Getenv("SAGE_TRACE") == "true" {println("`, getTargetFunctionName(function), ` took", `, g.Import("time"), `.Since(before).String(), "to error")}`)
 			g.P("logger.Fatal(err)")
 			g.P("}")
 		} else {
 			g.P("err = ", strings.ReplaceAll(getTargetFunctionName(function), ":", nsStruct), "(ctx)")
 			g.P("if err != nil {")
+			g.P(`if os.Getenv("SAGE_TRACE") == "true" {println("`, getTargetFunctionName(function), ` took", `, g.Import("time"), `.Since(before).String(), "to error")}`)
 			g.P("logger.Fatal(err)")
 			g.P("}")
 		}
+		g.P(`if os.Getenv("SAGE_TRACE") == "true" {println("`, getTargetFunctionName(function), ` took", `, g.Import("time"), ".Since(before).String())}")
 	})
 	g.P("default:")
 	g.P("logger := ", g.Import("go.einride.tech/sage/sg"), ".NewLogger(\"sagefile\")")

sg/internal/runner/runner.go

@@ -2,7 +2,9 @@ package runner
 
 import (
 	"context"
+	"os"
 	"sync"
+	"time"
 )
 
 // global state for the runner.
@@ -15,6 +17,13 @@ var (
 
 // RunOnce uses key to ensure that fn runs exactly once and always returns the error from the initial run.
 func RunOnce(ctx context.Context, key string, fn func(context.Context) error) error {
+	before := time.Now()
+	defer func() {
+		if os.Getenv("SAGE_TRACE") == "true" {
+			elapsed := time.Since(before)
+			println(key, "took", elapsed.String())
+		}
+	}()
 	mu.Lock()
 	onceFn, ok := onceFns[key]
 	if !ok {