Track the execution times of bundle mutators (#3097)

## Changes
This PR modifies the `bundle.Apply` method to allow us to track
execution times for all mutators. It also separately tracks the
execution time of the three phases: Initialise, Build and Deploy.

## Why
Tracking the execution times will give us insight into the time sinks
where users spend the most time and thus areas we should invest in
improving to give users a faster experience when using the CLI.

Note: This information can also be extrapolated (to some degree) to
other commands. For example, we could look at how long
`phases.Inititalize` takes to understand the latencies involved in the
bundle validate command.

## Tests
Update existing acceptance test.

Author: shreyas-goenka

acceptance/bundle/telemetry/deploy/output.txt

@@ -6,3 +6,7 @@ Updating deployment state...
 Deployment complete!
 
 >>> cat out.requests.txt
+
+=== Assert that there are atleast 5 mutators for which the execution time is recorded
+>>> cat telemetry.json
+true

acceptance/bundle/telemetry/deploy/script

@@ -1,6 +1,15 @@
 trace $CLI bundle deploy
 
-trace cat out.requests.txt | jq 'select(has("path") and .path == "/telemetry-ext") | .body.protoLogs[] | fromjson' > out.telemetry.txt
+trace cat out.requests.txt | jq 'select(has("path") and .path == "/telemetry-ext") | .body.protoLogs[] | fromjson' > telemetry.json
+
+# Note that the number 5 here is arbitrary. In practice I saw 16 mutators be recorded in acceptance test runs so 5 seems
+# like a reasonably safe number to assert that mutator execution times are being recorded.
+title "Assert that there are atleast 5 mutators for which the execution time is recorded"
+trace cat telemetry.json | jq ' .entry.databricks_cli_log.bundle_deploy_event.experimental.bundle_mutator_execution_time_ms | length > 5'
+
+# bundle_mutator_execution_time_ms can have variable number of entries depending upon the runtime of the mutators. Thus we omit it from
+# being asserted here.
+cat telemetry.json | jq 'del(.entry.databricks_cli_log.bundle_deploy_event.experimental.bundle_mutator_execution_time_ms)' > out.telemetry.txt
 
 cmd_exec_id=$(extract_command_exec_id.py)
 deployment_id=$(cat .databricks/bundle/default/deployment.json | jq -r .id)
@@ -10,3 +19,4 @@ update_file.py out.telemetry.txt "11111111-2222-3333-4444-555555555555"  '[BUNDL
 update_file.py out.telemetry.txt $deployment_id  '[DEPLOYMENT_ID]'
 
 rm out.requests.txt
+rm telemetry.json

bundle/bundle.go

@@ -52,6 +52,7 @@ type Metrics struct {
 	BoolValues                  []protos.BoolMapEntry
 	PythonAddedResourcesCount   int64
 	PythonUpdatedResourcesCount int64
+	ExecutionTimes              []protos.IntMapEntry
 }
 
 func (m *Metrics) AddBoolValue(key string, value bool) {

bundle/mutator.go

@@ -2,9 +2,12 @@ package bundle
 
 import (
 	"context"
+	"reflect"
+	"time"
 
 	"github.com/databricks/cli/libs/diag"
 	"github.com/databricks/cli/libs/log"
+	"github.com/databricks/cli/libs/telemetry/protos"
 )
 
 // Mutator is the interface type that mutates a bundle's configuration or internal state.
@@ -17,7 +20,55 @@ type Mutator interface {
 	Apply(context.Context, *Bundle) diag.Diagnostics
 }
 
+// safeMutatorName returns the package name and type name of the underlying mutator type
+// in the format "package_name.(type_name)".
+//
+// We cannot rely on the .Name() method for the name here because it can contain user
+// input which would then leak into the telemetry. E.g. [SetDefault] or [loader.ProcessInclude]
+func safeMutatorName(m Mutator) string {
+	t := reflect.TypeOf(m)
+
+	// Handle pointer types by getting the element type
+	if t.Kind() == reflect.Ptr {
+		t = t.Elem()
+	}
+
+	// Get the package path and type name
+	pkgPath := t.PkgPath()
+	typeName := t.Name()
+
+	// Extract just the package name from the full package path
+	// e.g., "github.com/databricks/cli/bundle/config/mutator" -> "mutator"
+	packageName := pkgPath
+	if lastSlash := len(pkgPath) - 1; lastSlash >= 0 {
+		for i := lastSlash; i >= 0; i-- {
+			if pkgPath[i] == '/' {
+				packageName = pkgPath[i+1:]
+				break
+			}
+		}
+	}
+
+	return packageName + ".(" + typeName + ")"
+}
+
 func Apply(ctx context.Context, b *Bundle, m Mutator) diag.Diagnostics {
+	// Track the execution time of the mutator.
+	t0 := time.Now()
+	defer func() {
+		duration := time.Since(t0).Milliseconds()
+
+		// Don't track the mutator if it takes less than 1ms to execute.
+		if duration == 0 {
+			return
+		}
+
+		b.Metrics.ExecutionTimes = append(b.Metrics.ExecutionTimes, protos.IntMapEntry{
+			Key:   safeMutatorName(m),
+			Value: duration,
+		})
+	}()
+
 	ctx = log.NewContext(ctx, log.GetLogger(ctx).With("mutator", m.Name()))
 
 	log.Debugf(ctx, "Apply")

bundle/mutator_test.go

@@ -5,6 +5,7 @@ import (
 	"testing"
 
 	"github.com/databricks/cli/libs/diag"
+	"github.com/databricks/cli/libs/dyn"
 	"github.com/stretchr/testify/assert"
 )
 
@@ -43,3 +44,34 @@ func TestMutator(t *testing.T) {
 	assert.Equal(t, 1, nested[0].applyCalled)
 	assert.Equal(t, 1, nested[1].applyCalled)
 }
+
+func TestSafeMutatorName(t *testing.T) {
+	tests := []struct {
+		name     string
+		mutator  Mutator
+		expected string
+	}{
+		{
+			name:     "funcMutator",
+			mutator:  funcMutator{fn: nil},
+			expected: "bundle.(funcMutator)",
+		},
+		{
+			name:     "setDefault mutator",
+			mutator:  SetDefaultMutator(dyn.NewPattern(dyn.Key("test")), "key", "value"),
+			expected: "bundle.(setDefault)",
+		},
+		{
+			name:     "funcMutator as pointer",
+			mutator:  &funcMutator{fn: nil},
+			expected: "bundle.(funcMutator)",
+		},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			result := safeMutatorName(tt.mutator)
+			assert.Equal(t, tt.expected, result, "mutatorName should return correct package.type format")
+		})
+	}
+}

bundle/phases/telemetry.go

@@ -3,6 +3,7 @@ package phases
 import (
 	"context"
 	"slices"
+	"sort"
 
 	"github.com/databricks/cli/bundle"
 	"github.com/databricks/cli/bundle/config"
@@ -13,6 +14,25 @@ import (
 	"github.com/databricks/cli/libs/telemetry/protos"
 )
 
+func getExecutionTimes(b *bundle.Bundle) []protos.IntMapEntry {
+	executionTimes := b.Metrics.ExecutionTimes
+
+	// Sort the execution times in descending order.
+	sort.Slice(executionTimes, func(i, j int) bool {
+		return executionTimes[i].Value > executionTimes[j].Value
+	})
+
+	// Keep only the top 250 execution times. This keeps the telemetry event
+	// reasonable in size. This should be unnecessary in most cases but is
+	// done out of caution since the number of mutators depends upon user input.
+	// Eg: every pattern in `includes:` triggers a new mutator.
+	if len(executionTimes) > 250 {
+		executionTimes = executionTimes[:250]
+	}
+
+	return executionTimes
+}
+
 func logDeployTelemetry(ctx context.Context, b *bundle.Bundle) {
 	resourcesCount := int64(0)
 	_, err := dyn.MapByPattern(b.Config.Value(), dyn.NewPattern(dyn.Key("resources"), dyn.AnyKey(), dyn.AnyKey()), func(p dyn.Path, v dyn.Value) (dyn.Value, error) {
@@ -149,18 +169,19 @@ func logDeployTelemetry(ctx context.Context, b *bundle.Bundle) {
 			ResourceDashboardIDs: dashboardIds,
 
 			Experimental: &protos.BundleDeployExperimental{
-				BundleMode:                  mode,
-				ConfigurationFileCount:      b.Metrics.ConfigurationFileCount,
-				TargetCount:                 b.Metrics.TargetCount,
-				WorkspaceArtifactPathType:   artifactPathType,
-				BoolValues:                  b.Metrics.BoolValues,
-				PythonAddedResourcesCount:   b.Metrics.PythonAddedResourcesCount,
-				PythonUpdatedResourcesCount: b.Metrics.PythonUpdatedResourcesCount,
-				PythonResourceLoadersCount:  int64(len(experimentalConfig.Python.Resources)),
-				PythonResourceMutatorsCount: int64(len(experimentalConfig.Python.Mutators)),
-				VariableCount:               int64(variableCount),
-				ComplexVariableCount:        complexVariableCount,
-				LookupVariableCount:         lookupVariableCount,
+				BundleMode:                   mode,
+				ConfigurationFileCount:       b.Metrics.ConfigurationFileCount,
+				TargetCount:                  b.Metrics.TargetCount,
+				WorkspaceArtifactPathType:    artifactPathType,
+				BoolValues:                   b.Metrics.BoolValues,
+				PythonAddedResourcesCount:    b.Metrics.PythonAddedResourcesCount,
+				PythonUpdatedResourcesCount:  b.Metrics.PythonUpdatedResourcesCount,
+				PythonResourceLoadersCount:   int64(len(experimentalConfig.Python.Resources)),
+				PythonResourceMutatorsCount:  int64(len(experimentalConfig.Python.Mutators)),
+				VariableCount:                int64(variableCount),
+				ComplexVariableCount:         complexVariableCount,
+				LookupVariableCount:          lookupVariableCount,
+				BundleMutatorExecutionTimeMs: getExecutionTimes(b),
 			},
 		},
 	})

cmd/bundle/deploy.go

@@ -4,6 +4,7 @@ import (
 	"context"
 	"fmt"
 	"io"
+	"time"
 
 	"github.com/databricks/cli/bundle"
 	"github.com/databricks/cli/bundle/config/validate"
@@ -13,6 +14,7 @@ import (
 	"github.com/databricks/cli/cmd/root"
 	"github.com/databricks/cli/libs/diag"
 	"github.com/databricks/cli/libs/sync"
+	"github.com/databricks/cli/libs/telemetry/protos"
 	"github.com/spf13/cobra"
 )
 
@@ -70,18 +72,38 @@ func newDeployCommand() *cobra.Command {
 				}
 			}
 
+			t0 := time.Now()
 			diags = diags.Extend(phases.Initialize(ctx, b))
+			b.Metrics.ExecutionTimes = append(b.Metrics.ExecutionTimes, protos.IntMapEntry{
+				Key:   "phases.Initialize",
+				Value: time.Since(t0).Milliseconds(),
+			})
 
 			if !diags.HasError() {
+				t1 := time.Now()
 				diags = diags.Extend(bundle.Apply(ctx, b, validate.FastValidate()))
+				b.Metrics.ExecutionTimes = append(b.Metrics.ExecutionTimes, protos.IntMapEntry{
+					Key:   "validate.FastValidate",
+					Value: time.Since(t1).Milliseconds(),
+				})
 			}
 
 			if !diags.HasError() {
+				t2 := time.Now()
 				diags = diags.Extend(phases.Build(ctx, b))
+				b.Metrics.ExecutionTimes = append(b.Metrics.ExecutionTimes, protos.IntMapEntry{
+					Key:   "phases.Build",
+					Value: time.Since(t2).Milliseconds(),
+				})
 			}
 
 			if !diags.HasError() {
+				t3 := time.Now()
 				diags = diags.Extend(phases.Deploy(ctx, b, outputHandler))
+				b.Metrics.ExecutionTimes = append(b.Metrics.ExecutionTimes, protos.IntMapEntry{
+					Key:   "phases.Deploy",
+					Value: time.Since(t3).Milliseconds(),
+				})
 			}
 		}