Merge branch 'qmnguyen0711/improve-tracing' into 'master'

Make distributed tracing useful to Gitaly

See merge request https://gitlab.com/gitlab-org/gitaly/-/merge_requests/5338

Merged-by: Justin Tobler <jtobler@gitlab.com>
Approved-by: Justin Tobler <jtobler@gitlab.com>
Approved-by: Toon Claes <toon@gitlab.com>
Reviewed-by: Justin Tobler <jtobler@gitlab.com>
Co-authored-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>

13 files changed, 93 insertions, 28 deletions

diff --git a/internal/command/command.go b/internal/command/command.go
index 6228b1c07..490faad40 100644
--- a/internal/command/command.go
+++ b/internal/command/command.go
@@ -171,12 +171,6 @@ func New(ctx context.Context, nameAndArgs []string, opts ...Option) (*Command, e
 		opt(&cfg)
 	}
 
-	span, ctx := opentracing.StartSpanFromContext(
-		ctx,
-		nameAndArgs[0],
-		opentracing.Tag{Key: "args", Value: strings.Join(nameAndArgs[1:], " ")},
-	)
-
 	spawnStartTime := time.Now()
 	putToken, err := getSpawnToken(ctx)
 	if err != nil {
@@ -199,6 +193,18 @@ func New(ctx context.Context, nameAndArgs []string, opts ...Option) (*Command, e
 		}).Debug("spawn")
 	}()
 
+	var spanName string
+	if cfg.commandName != "" && cfg.subcommandName != "" {
+		spanName = fmt.Sprintf("%s-%s", cfg.commandName, cfg.subcommandName)
+	} else {
+		spanName = cmdName
+	}
+	span, ctx := opentracing.StartSpanFromContext(
+		ctx,
+		spanName,
+		opentracing.Tag{Key: "path", Value: nameAndArgs[0]},
+		opentracing.Tag{Key: "args", Value: strings.Join(nameAndArgs[1:], " ")},
+	)
 	cmd := exec.Command(nameAndArgs[0], nameAndArgs[1:]...)
 
 	command := &Command{
@@ -471,26 +477,20 @@ func (c *Command) logProcessComplete() {
 		contextSwitchesTotal.WithLabelValues(service, method, cmdName, c.metricsSubCmd, "nonvoluntary", c.cmdGitVersion).Add(float64(rusage.Nivcsw))
 	}
 
-	c.span.LogKV(
-		"pid", cmd.ProcessState.Pid(),
-		"exit_code", exitCode,
-		"system_time_ms", systemTime.Milliseconds(),
-		"user_time_ms", userTime.Milliseconds(),
-		"real_time_ms", realTime.Milliseconds(),
-	)
+	c.span.SetTag("pid", cmd.ProcessState.Pid())
+	c.span.SetTag("exit_code", exitCode)
+	c.span.SetTag("system_time_ms", systemTime.Milliseconds())
+	c.span.SetTag("user_time_ms", userTime.Milliseconds())
+	c.span.SetTag("real_time_ms", realTime.Milliseconds())
 	if ok {
-		c.span.LogKV(
-			"maxrss", rusage.Maxrss,
-			"inblock", rusage.Inblock,
-			"oublock", rusage.Oublock,
-			"minflt", rusage.Minflt,
-			"majflt", rusage.Majflt,
-		)
+		c.span.SetTag("maxrss", rusage.Maxrss)
+		c.span.SetTag("inblock", rusage.Inblock)
+		c.span.SetTag("oublock", rusage.Oublock)
+		c.span.SetTag("minflt", rusage.Minflt)
+		c.span.SetTag("majflt", rusage.Majflt)
 	}
 	if c.cgroupPath != "" {
-		c.span.LogKV(
-			"cgroup_path", c.cgroupPath,
-		)
+		c.span.SetTag("cgroup_path", c.cgroupPath)
 	}
 	c.span.Finish()
 }
diff --git a/internal/git/catfile/cache.go b/internal/git/catfile/cache.go
index 493e7b9d3..1e21c31ee 100644
--- a/internal/git/catfile/cache.go
+++ b/internal/git/catfile/cache.go
@@ -212,6 +212,9 @@ func (c *ProcessCache) getOrCreateProcess(
 ) (_ cacheable, _ func(), returnedErr error) {
 	defer c.reportCacheMembers()
 
+	span, ctx := opentracing.StartSpanFromContext(ctx, spanName)
+	defer span.Finish()
+
 	cacheKey, isCacheable := newCacheKey(metadata.GetValue(ctx, SessionIDField), repo)
 	if isCacheable {
 		// We only try to look up cached processes in case it is cacheable, which requires a
@@ -222,12 +225,14 @@ func (c *ProcessCache) getOrCreateProcess(
 
 		if entry, ok := processes.Checkout(cacheKey); ok {
 			c.catfileCacheCounter.WithLabelValues("hit").Inc()
+			span.SetTag("hit", true)
 			return entry.value, func() {
 				c.returnToCache(processes, cacheKey, entry.value, entry.cancel)
 			}, nil
 		}
 
 		c.catfileCacheCounter.WithLabelValues("miss").Inc()
+		span.SetTag("hit", false)
 
 		// We have not found any cached process, so we need to create a new one. In this
 		// case, we need to detach the process from the current context such that it does
@@ -243,11 +248,8 @@ func (c *ProcessCache) getOrCreateProcess(
 		// We have to decorrelate the process from the current context given that it
 		// may potentially be reused across different RPC calls.
 		ctx = correlation.ContextWithCorrelation(ctx, "")
-		ctx = opentracing.ContextWithSpan(ctx, nil)
 	}
 
-	span, ctx := opentracing.StartSpanFromContext(ctx, spanName)
-
 	// Create a new cancellable process context such that we can kill it on demand. If it's a
 	// cached process, then it will only be killed when the cache evicts the entry because we
 	// detached the background further up. If it's an uncached value, we either kill it manually
@@ -280,7 +282,6 @@ func (c *ProcessCache) getOrCreateProcess(
 	closeProcess := func() {
 		cancelProcessContext()
 		process.close()
-		span.Finish()
 		c.currentCatfileProcesses.Dec()
 	}
 
diff --git a/internal/git/catfile/commit.go b/internal/git/catfile/commit.go
index 66402c037..3d59ceacc 100644
--- a/internal/git/catfile/commit.go
+++ b/internal/git/catfile/commit.go
@@ -7,6 +7,7 @@ import (
 	"fmt"
 	"io"
 
+	"github.com/opentracing/opentracing-go"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/repository"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/trailerparser"
@@ -15,6 +16,9 @@ import (
 
 // GetCommit looks up a commit by revision using an existing Batch instance.
 func GetCommit(ctx context.Context, objectReader ObjectContentReader, revision git.Revision) (*gitalypb.GitCommit, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "catfile.GetCommit", opentracing.Tag{Key: "revision", Value: revision.String()})
+	defer span.Finish()
+
 	object, err := objectReader.Object(ctx, revision+"^{commit}")
 	if err != nil {
 		return nil, err
@@ -32,6 +36,9 @@ func GetCommitWithTrailers(
 	objectReader ObjectContentReader,
 	revision git.Revision,
 ) (*gitalypb.GitCommit, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "catfile.GetCommitWithTrailers", opentracing.Tag{Key: "revision", Value: revision.String()})
+	defer span.Finish()
+
 	commit, err := GetCommit(ctx, objectReader, revision)
 	if err != nil {
 		return nil, err
@@ -68,6 +75,9 @@ func GetCommitWithTrailers(
 
 // GetCommitMessage looks up a commit message and returns it in its entirety.
 func GetCommitMessage(ctx context.Context, objectReader ObjectContentReader, repo repository.GitRepo, revision git.Revision) ([]byte, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "catfile.GetCommitMessage", opentracing.Tag{Key: "revision", Value: revision.String()})
+	defer span.Finish()
+
 	obj, err := objectReader.Object(ctx, revision+"^{commit}")
 	if err != nil {
 		return nil, err
diff --git a/internal/git/catfile/object_content_reader.go b/internal/git/catfile/object_content_reader.go
index 620e857fc..c3cbb12e9 100644
--- a/internal/git/catfile/object_content_reader.go
+++ b/internal/git/catfile/object_content_reader.go
@@ -143,7 +143,7 @@ func (o *objectContentReader) Object(ctx context.Context, revision git.Revision)
 }
 
 func (o *objectContentReader) ObjectContentQueue(ctx context.Context) (ObjectContentQueue, func(), error) {
-	queue, finish, err := o.objectQueue(ctx, "catfile.ObjectQueue")
+	queue, finish, err := o.objectQueue(ctx, "catfile.ObjectContentQueue")
 	if err != nil {
 		return nil, nil, err
 	}
diff --git a/internal/git/catfile/tag.go b/internal/git/catfile/tag.go
index 2636ed1ca..dbc46a121 100644
--- a/internal/git/catfile/tag.go
+++ b/internal/git/catfile/tag.go
@@ -6,6 +6,7 @@ import (
 	"fmt"
 	"io"
 
+	"github.com/opentracing/opentracing-go"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/helper"
 	"gitlab.com/gitlab-org/gitaly/v15/proto/go/gitalypb"
@@ -15,6 +16,9 @@ import (
 // in the tagName because the tag name from refs/tags may be different than the name found in the
 // actual tag object. We want to use the tagName found in refs/tags
 func GetTag(ctx context.Context, objectReader ObjectContentReader, tagID git.Revision, tagName string) (*gitalypb.Tag, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "catfile.GetTag", opentracing.Tag{Key: "tagName", Value: tagName})
+	defer span.Finish()
+
 	object, err := objectReader.Object(ctx, tagID)
 	if err != nil {
 		return nil, err
diff --git a/internal/git/catfile/tree_entries.go b/internal/git/catfile/tree_entries.go
index 91bc4b663..96b781641 100644
--- a/internal/git/catfile/tree_entries.go
+++ b/internal/git/catfile/tree_entries.go
@@ -11,6 +11,7 @@ import (
 	"path/filepath"
 	"strings"
 
+	"github.com/opentracing/opentracing-go"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/proto/go/gitalypb"
 )
@@ -35,6 +36,14 @@ func NewTreeEntryFinder(objectReader ObjectContentReader, objectInfoReader Objec
 
 // FindByRevisionAndPath returns a TreeEntry struct for the object present at the revision/path pair.
 func (tef *TreeEntryFinder) FindByRevisionAndPath(ctx context.Context, revision, path string) (*gitalypb.TreeEntry, error) {
+	span, ctx := opentracing.StartSpanFromContext(
+		ctx,
+		"catfile.FindByRevisionAndPatch",
+		opentracing.Tag{Key: "revision", Value: revision},
+		opentracing.Tag{Key: "path", Value: path},
+	)
+	defer span.Finish()
+
 	dir := pathPkg.Dir(path)
 	cacheKey := revisionPath{revision: revision, path: dir}
 	entries, ok := tef.treeCache[cacheKey]
@@ -111,6 +120,14 @@ func TreeEntries(
 	objectInfoReader ObjectInfoReader,
 	revision, path string,
 ) (_ []*gitalypb.TreeEntry, returnedErr error) {
+	span, ctx := opentracing.StartSpanFromContext(
+		ctx,
+		"catfile.TreeEntries",
+		opentracing.Tag{Key: "revision", Value: revision},
+		opentracing.Tag{Key: "path", Value: path},
+	)
+	defer span.Finish()
+
 	if path == "." {
 		path = ""
 	}
diff --git a/internal/git/housekeeping/clean_stale_data.go b/internal/git/housekeeping/clean_stale_data.go
index 5d896ea4f..f4e1303cb 100644
--- a/internal/git/housekeeping/clean_stale_data.go
+++ b/internal/git/housekeeping/clean_stale_data.go
@@ -12,6 +12,7 @@ import (
 	"time"
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
+	"github.com/opentracing/opentracing-go"
 	log "github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/localrepo"
@@ -44,6 +45,9 @@ type staleFileFinderFn func(context.Context, string) ([]string, error)
 
 // CleanStaleData cleans up any stale data in the repository.
 func (m *RepositoryManager) CleanStaleData(ctx context.Context, repo *localrepo.Repo) error {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "housekeeping.CleanStaleData")
+	defer span.Finish()
+
 	repoPath, err := repo.Path()
 	if err != nil {
 		myLogger(ctx).WithError(err).Warn("housekeeping failed to get repo path")
diff --git a/internal/git/housekeeping/optimize_repository.go b/internal/git/housekeeping/optimize_repository.go
index 387a8b7f9..ff9b32eb7 100644
--- a/internal/git/housekeeping/optimize_repository.go
+++ b/internal/git/housekeeping/optimize_repository.go
@@ -7,6 +7,7 @@ import (
 	"strconv"
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
+	"github.com/opentracing/opentracing-go"
 	"github.com/prometheus/client_golang/prometheus"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/localrepo"
@@ -42,6 +43,9 @@ func (m *RepositoryManager) OptimizeRepository(
 	repo *localrepo.Repo,
 	opts ...OptimizeRepositoryOption,
 ) error {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "housekeeping.OptimizeRepository")
+	defer span.Finish()
+
 	path, err := repo.Path()
 	if err != nil {
 		return err
diff --git a/internal/gitaly/server/server.go b/internal/gitaly/server/server.go
index c529a9038..861140cd8 100644
--- a/internal/gitaly/server/server.go
+++ b/internal/gitaly/server/server.go
@@ -165,6 +165,7 @@ func (s *GitalyServerFactory) New(secure bool, opts ...Option) (*grpc.Server, er
 	)
 
 	unaryServerInterceptors = append(unaryServerInterceptors,
+		grpctracing.UnaryServerTracingInterceptor(),
 		cache.UnaryInvalidator(s.cacheInvalidator, protoregistry.GitalyProtoPreregistered),
 		// Panic handler should remain last so that application panics will be
 		// converted to errors and logged
diff --git a/internal/gitaly/service/repository/license.go b/internal/gitaly/service/repository/license.go
index c0b12833a..2d8400977 100644
--- a/internal/gitaly/service/repository/license.go
+++ b/internal/gitaly/service/repository/license.go
@@ -13,6 +13,7 @@ import (
 	"github.com/go-enry/go-license-detector/v4/licensedb"
 	"github.com/go-enry/go-license-detector/v4/licensedb/api"
 	"github.com/go-enry/go-license-detector/v4/licensedb/filer"
+	"github.com/opentracing/opentracing-go"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/localrepo"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/git/lstree"
@@ -85,6 +86,9 @@ func (s *server) FindLicense(ctx context.Context, req *gitalypb.FindLicenseReque
 }
 
 func findLicense(ctx context.Context, repo *localrepo.Repo, commitID git.ObjectID) (*gitalypb.FindLicenseResponse, error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "repository.findLicense")
+	defer span.Finish()
+
 	repoFiler := &gitFiler{ctx: ctx, repo: repo, treeishID: commitID}
 	detectedLicenses, err := licensedb.Detect(repoFiler)
 	if err != nil {
diff --git a/internal/middleware/limithandler/concurrency_limiter.go b/internal/middleware/limithandler/concurrency_limiter.go
index 9e2082214..4de23c691 100644
--- a/internal/middleware/limithandler/concurrency_limiter.go
+++ b/internal/middleware/limithandler/concurrency_limiter.go
@@ -8,6 +8,7 @@ import (
 	"time"
 
 	"github.com/grpc-ecosystem/go-grpc-middleware/logging/logrus/ctxlogrus"
+	"github.com/opentracing/opentracing-go"
 	"github.com/prometheus/client_golang/prometheus"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/gitaly/config"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/helper"
@@ -159,6 +160,13 @@ func NewConcurrencyLimiter(maxConcurrencyLimit, maxQueueLength int, maxQueuedTic
 //     semaphore. If this takes longer than the maximum queueing limit then the caller will be
 //     dequeued and gets an error.
 func (c *ConcurrencyLimiter) Limit(ctx context.Context, limitingKey string, f LimitedFunc) (interface{}, error) {
+	span, ctx := opentracing.StartSpanFromContext(
+		ctx,
+		"limithandler.ConcurrencyLimiter.Limit",
+		opentracing.Tag{Key: "key", Value: limitingKey},
+	)
+	defer span.Finish()
+
 	if c.maxConcurrencyLimit <= 0 {
 		return f()
 	}
diff --git a/internal/middleware/limithandler/rate_limiter.go b/internal/middleware/limithandler/rate_limiter.go
index 9e4114e23..68ac5513d 100644
--- a/internal/middleware/limithandler/rate_limiter.go
+++ b/internal/middleware/limithandler/rate_limiter.go
@@ -6,6 +6,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/opentracing/opentracing-go"
 	"github.com/prometheus/client_golang/prometheus"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/gitaly/config"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/helper"
@@ -32,6 +33,13 @@ var ErrRateLimit = errors.New("rate limit reached")
 // Limit rejects an incoming reequest if the maximum number of requests per
 // second has been reached
 func (r *RateLimiter) Limit(ctx context.Context, lockKey string, f LimitedFunc) (interface{}, error) {
+	span, _ := opentracing.StartSpanFromContext(
+		ctx,
+		"limithandler.RateLimiterLimit",
+		opentracing.Tag{Key: "key", Value: lockKey},
+	)
+	defer span.Finish()
+
 	limiter, _ := r.limitersByKey.LoadOrStore(
 		lockKey,
 		rate.NewLimiter(rate.Every(r.refillInterval), r.burst),
diff --git a/internal/sidechannel/sidechannel.go b/internal/sidechannel/sidechannel.go
index fcd8d5258..d29ab9420 100644
--- a/internal/sidechannel/sidechannel.go
+++ b/internal/sidechannel/sidechannel.go
@@ -9,6 +9,7 @@ import (
 	"strconv"
 	"time"
 
+	"github.com/opentracing/opentracing-go"
 	"github.com/sirupsen/logrus"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/backchannel"
 	"gitlab.com/gitlab-org/gitaly/v15/internal/gitaly/client"
@@ -33,6 +34,9 @@ const (
 // OpenSidechannel opens a sidechannel connection from the stream opener
 // extracted from the current peer connection.
 func OpenSidechannel(ctx context.Context) (_ *ServerConn, err error) {
+	span, ctx := opentracing.StartSpanFromContext(ctx, "sidechannel.OpenSidechannel")
+	defer span.Finish()
+
 	md, ok := metadata.FromIncomingContext(ctx)
 	if !ok {
 		return nil, fmt.Errorf("sidechannel: failed to extract incoming metadata")