diff options
author | Justin Tobler <jtobler@gitlab.com> | 2023-02-16 03:32:01 +0300 |
---|---|---|
committer | Justin Tobler <jtobler@gitlab.com> | 2023-02-16 03:32:01 +0300 |
commit | d4daa7a154ccc86d1b57372e4265bb502c886537 (patch) | |
tree | 64f6a4b735c7292274630adfa9d1ed22e0207e13 /internal | |
parent | 954816989a09915efa2cad385f92e53b25b01675 (diff) | |
parent | b74f3f6bd8f59bc51659ee39c951bc17bf58037d (diff) |
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>
Diffstat (limited to 'internal')
-rw-r--r-- | internal/command/command.go | 46 | ||||
-rw-r--r-- | internal/git/catfile/cache.go | 9 | ||||
-rw-r--r-- | internal/git/catfile/commit.go | 10 | ||||
-rw-r--r-- | internal/git/catfile/object_content_reader.go | 2 | ||||
-rw-r--r-- | internal/git/catfile/tag.go | 4 | ||||
-rw-r--r-- | internal/git/catfile/tree_entries.go | 17 | ||||
-rw-r--r-- | internal/git/housekeeping/clean_stale_data.go | 4 | ||||
-rw-r--r-- | internal/git/housekeeping/optimize_repository.go | 4 | ||||
-rw-r--r-- | internal/gitaly/server/server.go | 1 | ||||
-rw-r--r-- | internal/gitaly/service/repository/license.go | 4 | ||||
-rw-r--r-- | internal/middleware/limithandler/concurrency_limiter.go | 8 | ||||
-rw-r--r-- | internal/middleware/limithandler/rate_limiter.go | 8 | ||||
-rw-r--r-- | internal/sidechannel/sidechannel.go | 4 |
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") |