command: Add metric for spawning tokensjc-add-metrics-for-spawn-tokens

When git commands take a long time, it's hard to know whether it's from
the actual process or that time is spent waiting for a spawn token. This
adds a metric that measures and emits the time spent waiting for a spawn
token.

Changelog: added

2 files changed, 50 insertions, 0 deletions

diff --git a/internal/command/command.go b/internal/command/command.go
index 85178d995..6bd7c9856 100644
--- a/internal/command/command.go
+++ b/internal/command/command.go
@@ -81,6 +81,13 @@ var (
 		},
 		[]string{"grpc_service", "grpc_method", "cmd", "subcmd", "ctxswitchtype"},
 	)
+	spawnTokenAcquiringSeconds = promauto.NewCounterVec(
+		prometheus.CounterOpts{
+			Name: "gitaly_command_spawn_token_acquiring_seconds_total",
+			Help: "Sum of time spent waiting for a spawn token",
+		},
+		[]string{"grpc_service", "grpc_method", "cmd"},
+	)
 )
 
 // GitEnv contains the ENV variables for git commands
@@ -215,6 +222,10 @@ func (c *Command) SetMetricsSubCmd(metricsSubCmd string) {
 
 type contextWithoutDonePanic string
 
+var getSpawnTokenAcquiringSeconds = func(t time.Time) float64 {
+	return time.Since(t).Seconds()
+}
+
 // New creates a Command from an exec.Cmd. On success, the Command
 // contains a running subprocess. When ctx is canceled the embedded
 // process will be terminated and reaped automatically.
@@ -236,10 +247,17 @@ func New(ctx context.Context, cmd *exec.Cmd, stdin io.Reader, stdout, stderr io.
 		opentracing.Tag{Key: "args", Value: strings.Join(cmd.Args, " ")},
 	)
 
+	spawnStartTime := time.Now()
 	putToken, err := getSpawnToken(ctx)
 	if err != nil {
 		return nil, err
 	}
+	service, method := methodFromContext(ctx)
+	cmdName := path.Base(cmd.Path)
+	spawnTokenAcquiringSeconds.
+		WithLabelValues(service, method, cmdName).
+		Add(getSpawnTokenAcquiringSeconds(spawnStartTime))
+
 	defer putToken()
 
 	logPid := -1
diff --git a/internal/command/command_test.go b/internal/command/command_test.go
index 3ff5cbac8..5dc8833f6 100644
--- a/internal/command/command_test.go
+++ b/internal/command/command_test.go
@@ -13,6 +13,8 @@ import (
 	"time"
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
+	grpcmwtags "github.com/grpc-ecosystem/go-grpc-middleware/tags"
+	"github.com/prometheus/client_golang/prometheus/testutil"
 	"github.com/sirupsen/logrus"
 	"github.com/sirupsen/logrus/hooks/test"
 	"github.com/stretchr/testify/assert"
@@ -384,3 +386,33 @@ func TestCommand_logMessage(t *testing.T) {
 	assert.Equal(t, 0, logEntry.Data["command.exitCode"])
 	assert.Equal(t, cgroupPath, logEntry.Data["command.cgroup_path"])
 }
+
+func TestNewCommandSpawnTokenMetrics(t *testing.T) {
+	spawnTokenAcquiringSeconds.Reset()
+
+	ctx := testhelper.Context(t)
+	getSpawnTokenAcquiringSeconds = func(t time.Time) float64 {
+		return 1
+	}
+
+	tags := grpcmwtags.NewTags()
+	tags.Set("grpc.request.fullMethod", "/test.Service/TestRPC")
+	ctx = grpcmwtags.SetInContext(ctx, tags)
+
+	cmd, err := New(ctx, exec.Command("echo", "goodbye, cruel world."), nil, nil, nil)
+
+	require.NoError(t, err)
+	require.NoError(t, cmd.Wait())
+
+	expectedMetrics := `# HELP gitaly_command_spawn_token_acquiring_seconds_total Sum of time spent waiting for a spawn token
+# TYPE gitaly_command_spawn_token_acquiring_seconds_total counter
+gitaly_command_spawn_token_acquiring_seconds_total{cmd="echo",grpc_method="TestRPC",grpc_service="test.Service"} 1
+`
+	assert.NoError(
+		t,
+		testutil.CollectAndCompare(
+			spawnTokenAcquiringSeconds,
+			bytes.NewBufferString(expectedMetrics),
+		),
+	)
+}