[perf] Profile possibly slow functions (#1491)

## Summary

Profile a few functions. This shows any function that takes more than 1
ms.

Q: does trace have this functionality? It looks like it does time events
but we have to explicitly enable it using the `trace` flag?

## How was it tested?



```bash
export DEVBOX_PRINT_EXEC_TIME=1

devbox add curl
...
Exec times over 1ms:
"syncPackagesToProfile" took 343.118292ms
"nixEnv" took 128.018333ms
"nixEnv" took 128.219083ms
"CreateWrappers" took 257.527167ms
"ensurePackagesAreInstalled" took 768.378084ms
"CreateWrappers" took 2.56ms
"devbox add curl" took 1.21434s
```

Author: mikeland73

internal/boxcli/root.go

@@ -106,6 +106,7 @@ func Execute(ctx context.Context, args []string) int {
 }
 
 func Main() {
+	timer := debug.Timer(strings.Join(os.Args, " "))
 	ctx := context.Background()
 	if strings.HasSuffix(os.Args[0], "ssh") ||
 		strings.HasSuffix(os.Args[0], "scp") {
@@ -126,7 +127,7 @@ func Main() {
 	code := Execute(ctx, os.Args[1:])
 	// Run out here instead of as a middleware so we can capture any time we spend
 	// in middlewares as well.
-	debug.PrintExecutionTime()
+	timer.End()
 	os.Exit(code)
 }
 

internal/debug/time.go

@@ -6,22 +6,54 @@ package debug
 import (
 	"fmt"
 	"os"
+	"runtime"
 	"strconv"
 	"strings"
 	"time"
 )
 
+var timerEnabled, _ = strconv.ParseBool(os.Getenv(devboxPrintExecTime))
+
 const devboxPrintExecTime = "DEVBOX_PRINT_EXEC_TIME"
 
-var start = time.Now()
+var headerPrinted = false
+
+type timer struct {
+	name string
+	time time.Time
+}
+
+func Timer(name string) *timer {
+	if !timerEnabled {
+		return nil
+	}
+	return &timer{
+		name: name,
+		time: time.Now(),
+	}
+}
+
+func FunctionTimer() *timer {
+	if !timerEnabled {
+		return nil
+	}
+	pc := make([]uintptr, 15)
+	n := runtime.Callers(2, pc)
+	frames := runtime.CallersFrames(pc[:n])
+	frame, _ := frames.Next()
+	parts := strings.Split(frame.Function, ".")
+	return Timer(parts[len(parts)-1])
+}
 
-func PrintExecutionTime() {
-	if enabled, _ := strconv.ParseBool(os.Getenv(devboxPrintExecTime)); !enabled {
+func (t *timer) End() {
+	if t == nil {
 		return
 	}
-	fmt.Fprintf(
-		os.Stderr,
-		"\"%s\" took %s\n", strings.Join(os.Args, " "),
-		time.Since(start),
-	)
+	if !headerPrinted {
+		fmt.Fprintln(os.Stderr, "\nExec times over 1ms:")
+		headerPrinted = true
+	}
+	if time.Since(t.time) >= time.Millisecond {
+		fmt.Fprintf(os.Stderr, "\"%s\" took %s\n", t.name, time.Since(t.time))
+	}
 }

internal/impl/devbox.go

@@ -934,6 +934,7 @@ var nixEnvCache map[string]string
 // Note that this is in-memory cache of the final environment, and not the same
 // as the nix print-dev-env cache which is stored in a file.
 func (d *Devbox) nixEnv(ctx context.Context) (map[string]string, error) {
+	defer debug.FunctionTimer().End()
 	if nixEnvCache != nil {
 		return nixEnvCache, nil
 	}

internal/impl/packages.go

@@ -203,6 +203,7 @@ const (
 // what operations are happening, because this function may take time to execute.
 func (d *Devbox) ensurePackagesAreInstalled(ctx context.Context, mode installMode) error {
 	defer trace.StartRegion(ctx, "ensurePackages").End()
+	defer debug.FunctionTimer().End()
 
 	if upToDate, err := d.lockfile.IsUpToDateAndInstalled(); err != nil || upToDate {
 		return err
@@ -266,6 +267,7 @@ func (d *Devbox) profilePath() (string, error) {
 // syncPackagesToProfile ensures that all packages in devbox.json exist in the nix profile,
 // and no more.
 func (d *Devbox) syncPackagesToProfile(ctx context.Context, mode installMode) error {
+	defer debug.FunctionTimer().End()
 	// TODO: we can probably merge these two operations to be faster and minimize chances of
 	// the devbox.json and nix profile falling out of sync.
 	if err := d.addPackagesToProfile(ctx, mode); err != nil {

internal/shellgen/scripts.go

@@ -33,6 +33,7 @@ type devboxer interface {
 // WriteScriptsToFiles writes scripts defined in devbox.json into files inside .devbox/gen/scripts.
 // Scripts (and hooks) are persisted so that we can easily call them from devbox run (inside or outside shell).
 func WriteScriptsToFiles(devbox devboxer) error {
+	defer debug.FunctionTimer().End()
 	err := os.MkdirAll(filepath.Join(devbox.ProjectDir(), scriptsDir), 0755) // Ensure directory exists.
 	if err != nil {
 		return errors.WithStack(err)

internal/wrapnix/wrapper.go

@@ -38,6 +38,7 @@ var devboxSymlinkDir = xdg.CacheSubpath(filepath.Join("devbox", "bin", "current"
 
 // CreateWrappers creates wrappers for all the executables in nix paths
 func CreateWrappers(ctx context.Context, devbox devboxer) error {
+	defer debug.FunctionTimer().End()
 	shellEnvHash, err := devbox.ShellEnvHash(ctx)
 	if err != nil {
 		return err