Trace execution of getSpawnToken

We've seen quite a few traces where there is a long gap before
a git command runs. This additional instrumentation should help
us determine whether we're waiting on spawn tokens during bursts.

Changelog: changed

1 files changed, 13 insertions, 6 deletions

diff --git a/internal/command/spawntoken.go b/internal/command/spawntoken.go
index 95874d88c..cc70d08e6 100644
--- a/internal/command/spawntoken.go
+++ b/internal/command/spawntoken.go
@@ -7,6 +7,7 @@ import (
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
 	"github.com/kelseyhightower/envconfig"
+	"github.com/opentracing/opentracing-go"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/prometheus/client_golang/prometheus/promauto"
 )
@@ -57,15 +58,18 @@ func getSpawnToken(ctx context.Context) (putToken func(), err error) {
 	// https://gitlab.com/gitlab-org/gitaly/issues/823.
 	start := time.Now()
 
+	span, ctx := opentracing.StartSpanFromContext(ctx, "command.getSpawnToken")
+	defer span.Finish()
+
 	select {
 	case spawnTokens <- struct{}{}:
-		logTime(ctx, start, "spawn token acquired")
+		logTime(ctx, start, "spawn token acquired", span)
 
 		return func() {
 			<-spawnTokens
 		}, nil
 	case <-time.After(spawnConfig.Timeout):
-		logTime(ctx, start, "spawn token timeout")
+		logTime(ctx, start, "spawn token timeout", span)
 		spawnTimeoutCount.Inc()
 
 		return nil, fmt.Errorf("process spawn timed out after %v", spawnConfig.Timeout)
@@ -74,11 +78,14 @@ func getSpawnToken(ctx context.Context) (putToken func(), err error) {
 	}
 }
 
-func logTime(ctx context.Context, start time.Time, msg string) {
+func logTime(ctx context.Context, start time.Time, msg string, span opentracing.Span) {
 	delta := time.Since(start)
-	if delta < logDurationThreshold {
-		return
+	if delta >= logDurationThreshold {
+		ctxlogrus.Extract(ctx).WithField("spawn_queue_ms", delta.Seconds()*1000).Info(msg)
 	}
 
-	ctxlogrus.Extract(ctx).WithField("spawn_queue_ms", delta.Seconds()*1000).Info(msg)
+	span.LogKV(
+		"spawn_queue_ms", delta.Seconds()*1000,
+		"msg", msg,
+	)
 }