Add trace timer (#261)

This PR adds a `StartTimer` utility that we can use to show how much
time different internal stages of the system are taking if the
playground runs in `--log-level=trace` mode.

Example of the output:
```$ go run main.go cook l1 --output ./output --log-level trace
2025/12/17 09:08:57 Log level: trace
2025/12/17 09:08:57 deleting existing output directory ./output
2025/12/17 09:08:57 Genesis block hash: 0xf755a8f8203a2a94c3b9c028898f0c218c220bbc4a99648274726912da70e2ee
2025/12/17 09:09:00 [TRACE] artifacts.builder: 3.435216667s
2025/12/17 09:09:00 [TRACE] docker.pull-available-images: 23.35025ms
2025/12/17 09:09:18 [TRACE] docker.up: 18.081256709s
```

Note that in this case, `docker.up` contains the time for
`mev-boost-relay` to be ready and healthy which needs beacon to be
running.

Author: ferranbt

main.go

@@ -10,6 +10,7 @@ import (
 	"time"
 
 	"github.com/flashbots/builder-playground/playground"
+	"github.com/flashbots/builder-playground/utils"
 	"github.com/flashbots/builder-playground/utils/mainctx"
 	"github.com/spf13/cobra"
 )
@@ -205,6 +206,11 @@ func runIt(recipe playground.Recipe) error {
 		return fmt.Errorf("failed to parse log level: %w", err)
 	}
 
+	if logLevel == playground.LevelTrace {
+		// TODO: We can remove this once we have a logger with log.Trace support
+		utils.TraceMode = true
+	}
+
 	log.Printf("Log level: %s\n", logLevel)
 
 	// parse the overrides

playground/artifacts.go

@@ -31,6 +31,7 @@ import (
 	"github.com/ethereum/go-ethereum/common/hexutil"
 	"github.com/ethereum/go-ethereum/core/types"
 	ecrypto "github.com/ethereum/go-ethereum/crypto"
+	"github.com/flashbots/builder-playground/utils"
 	"github.com/hashicorp/go-uuid"
 	keystorev4 "github.com/wealdtech/go-eth2-wallet-encryptor-keystorev4"
 	"gopkg.in/yaml.v2"
@@ -115,6 +116,8 @@ type Artifacts struct {
 }
 
 func (b *ArtifactsBuilder) Build() (*Artifacts, error) {
+	defer utils.StartTimer("artifacts.builder")()
+
 	homeDir, err := GetHomeDir()
 	if err != nil {
 		return nil, err

playground/local_runner.go

@@ -26,6 +26,7 @@ import (
 	"github.com/docker/docker/client"
 	"github.com/docker/docker/pkg/stdcopy"
 	"github.com/ethereum/go-ethereum/log"
+	"github.com/flashbots/builder-playground/utils"
 	"golang.org/x/sync/errgroup"
 	"gopkg.in/yaml.v2"
 )
@@ -884,6 +885,8 @@ func (d *LocalRunner) ensureImage(ctx context.Context, imageName string) error {
 }
 
 func (d *LocalRunner) pullNotAvailableImages(ctx context.Context) error {
+	defer utils.StartTimer("docker.pull-available-images")()
+
 	g, ctx := errgroup.WithContext(ctx)
 
 	for _, svc := range d.manifest.Services {
@@ -921,6 +924,8 @@ func (d *LocalRunner) Run(ctx context.Context) error {
 		return err
 	}
 
+	defer utils.StartTimer("docker.up")()
+
 	// First start the services that are running in docker-compose
 	cmd := exec.CommandContext(
 		ctx, "docker", "compose",

utils/time_watcher.go

@@ -0,0 +1,20 @@
+package utils
+
+import (
+	"log"
+	"time"
+)
+
+var TraceMode bool
+
+// StartTimer starts a timer with the given name and returns a function that prints the elapsed time when called.
+// The elapsed time is only printed if TraceMode is enabled.
+func StartTimer(name string) func() {
+	start := time.Now()
+	return func() {
+		if TraceMode {
+			elapsed := time.Since(start)
+			log.Printf("[TRACE] %s: %v\n", name, elapsed)
+		}
+	}
+}