diff --git a/sg/initfile.go b/sg/initfile.go index 0e467811..70d33c25 100644 --- a/sg/initfile.go +++ b/sg/initfile.go @@ -1,3 +1,4 @@ +//nolint:lll package sg import ( @@ -47,6 +48,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 +92,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\")") diff --git a/sg/internal/runner/runner.go b/sg/internal/runner/runner.go index 5edaa003..15993d61 100644 --- a/sg/internal/runner/runner.go +++ b/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 {