diff options
author | John Cai <jcai@gitlab.com> | 2023-03-29 22:01:09 +0300 |
---|---|---|
committer | John Cai <jcai@gitlab.com> | 2023-03-29 22:01:09 +0300 |
commit | 0b31e634f58b0495a20eaa00b588714dfdefefd7 (patch) | |
tree | caab1cd611ad4796f58857ab4eae827a8677a73f | |
parent | d41dacd832cc71860f8e069647b539880263392c (diff) | |
parent | 85249660e66b596d69d4c95d3fe8bb64af5c83ab (diff) |
Merge branch 'qmnguyen0711/implement-trace2-pack-file-metrics' into 'master'
Trace2: Expose internal pack objects metrics with trace2
See merge request https://gitlab.com/gitlab-org/gitaly/-/merge_requests/5442
Merged-by: John Cai <jcai@gitlab.com>
Approved-by: John Cai <jcai@gitlab.com>
Reviewed-by: Patrick Steinhardt <psteinhardt@gitlab.com>
Reviewed-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>
Co-authored-by: Quang-Minh Nguyen <qmnguyen@gitlab.com>
-rw-r--r-- | internal/git/command_factory.go | 5 | ||||
-rw-r--r-- | internal/git/command_factory_test.go | 44 | ||||
-rw-r--r-- | internal/git/trace2hooks/packobjects_metrics.go | 93 | ||||
-rw-r--r-- | internal/git/trace2hooks/packobjects_metrics_ext_test.go | 213 | ||||
-rw-r--r-- | internal/git/trace2hooks/packobjects_metrics_test.go | 398 | ||||
-rw-r--r-- | internal/git/trace2hooks/tracingexporter.go | 6 | ||||
-rw-r--r-- | internal/git/trace2hooks/tracingexporter_test.go | 2 | ||||
-rw-r--r-- | internal/metadata/featureflag/ff_export_trace2_pack_objects_metrics.go | 10 | ||||
-rw-r--r-- | internal/testhelper/testhelper.go | 3 |
9 files changed, 763 insertions, 11 deletions
diff --git a/internal/git/command_factory.go b/internal/git/command_factory.go index d8115ddc5..61d62c74c 100644 --- a/internal/git/command_factory.go +++ b/internal/git/command_factory.go @@ -96,7 +96,10 @@ func WithTrace2Hooks(hooks []trace2.Hook) ExecCommandFactoryOption { func DefaultTrace2HooksFor(ctx context.Context, subCmd string) []trace2.Hook { var hooks []trace2.Hook if featureflag.ExportTrace2Tracing.IsEnabled(ctx) && tracing.IsSampled(ctx) { - hooks = append(hooks, &trace2hooks.TracingExporter{}) + hooks = append(hooks, trace2hooks.NewTracingExporter()) + } + if featureflag.ExportTrace2PackObjectsMetrics.IsEnabled(ctx) { + hooks = append(hooks, trace2hooks.NewPackObjectsMetrics()) } return hooks } diff --git a/internal/git/command_factory_test.go b/internal/git/command_factory_test.go index a4129be38..5a998da76 100644 --- a/internal/git/command_factory_test.go +++ b/internal/git/command_factory_test.go @@ -973,6 +973,9 @@ func testTrace2TracingExporter(t *testing.T, testCtx context.Context) { }, } { t.Run(tc.desc, func(t *testing.T) { + // Disable other hooks + testCtx := featureflag.ContextWithFeatureFlag(testCtx, featureflag.ExportTrace2PackObjectsMetrics, false) + reporter, cleanup := testhelper.StubTracingReporter(t, tc.tracerOptions...) defer cleanup() ctx := tc.setup(t, command.InitContextStats(testCtx)) @@ -1000,7 +1003,12 @@ func testTrace2TracingExporter(t *testing.T, testCtx context.Context) { } func TestDefaultTrace2HooksFor(t *testing.T) { - featureSet := testhelper.NewFeatureSets(featureflag.ExportTrace2Tracing) + t.Parallel() + + featureSet := testhelper.NewFeatureSets( + featureflag.ExportTrace2Tracing, + featureflag.ExportTrace2PackObjectsMetrics, + ) featureSet.Run(t, testDefaultTrace2HooksFor) } @@ -1015,29 +1023,41 @@ func testDefaultTrace2HooksFor(t *testing.T, ctx context.Context) { { desc: "there is no active span", setup: func(t *testing.T) (context.Context, []trace2.Hook) { - return testhelper.Context(t), nil + ctx := testhelper.Context(t) + var hooks []trace2.Hook + if featureflag.ExportTrace2PackObjectsMetrics.IsEnabled(ctx) { + hooks = append(hooks, trace2hooks.NewPackObjectsMetrics()) + } + return ctx, hooks }, }, { desc: "active span is sampled", setup: func(t *testing.T) (context.Context, []trace2.Hook) { _, ctx = tracing.StartSpan(testhelper.Context(t), "root", nil) + var hooks []trace2.Hook - if !featureflag.ExportTrace2Tracing.IsEnabled(ctx) { - return ctx, nil + if featureflag.ExportTrace2Tracing.IsEnabled(ctx) { + hooks = append(hooks, &trace2hooks.TracingExporter{}) } - return ctx, []trace2.Hook{ - &trace2hooks.TracingExporter{}, + if featureflag.ExportTrace2PackObjectsMetrics.IsEnabled(ctx) { + hooks = append(hooks, trace2hooks.NewPackObjectsMetrics()) } + + return ctx, hooks }, }, { desc: "active span is not sampled", setup: func(t *testing.T) (context.Context, []trace2.Hook) { _, ctx = tracing.StartSpan(testhelper.Context(t), "root", nil) + var hooks []trace2.Hook + if featureflag.ExportTrace2PackObjectsMetrics.IsEnabled(ctx) { + hooks = append(hooks, trace2hooks.NewPackObjectsMetrics()) + } - return ctx, nil + return ctx, hooks }, tracerOptions: []testhelper.StubTracingReporterOption{testhelper.NeverSampled()}, }, @@ -1049,7 +1069,7 @@ func testDefaultTrace2HooksFor(t *testing.T, ctx context.Context) { ctx, expectedHooks := tc.setup(t) hooks := git.DefaultTrace2HooksFor(ctx, tc.subCmd) - require.Equal(t, expectedHooks, hooks) + require.Equal(t, hookNames(expectedHooks), hookNames(hooks)) }) } } @@ -1083,3 +1103,11 @@ func performPackObjectGit(t *testing.T, ctx context.Context, opts ...git.ExecCom err = cmd.Wait() require.NoError(t, err) } + +func hookNames(hooks []trace2.Hook) []string { + var names []string + for _, hook := range hooks { + names = append(names, hook.Name()) + } + return names +} diff --git a/internal/git/trace2hooks/packobjects_metrics.go b/internal/git/trace2hooks/packobjects_metrics.go new file mode 100644 index 000000000..e2339f39d --- /dev/null +++ b/internal/git/trace2hooks/packobjects_metrics.go @@ -0,0 +1,93 @@ +package trace2hooks + +import ( + "context" + "strconv" + + "github.com/prometheus/client_golang/prometheus" + "gitlab.com/gitlab-org/gitaly/v15/internal/command" + "gitlab.com/gitlab-org/gitaly/v15/internal/git/trace2" +) + +var statsIntData = map[string]string{ + "data:pack-objects:write_pack_file/wrote": "pack_objects.written_object_count", + "data:pack-objects:loosen_unused_packed_objects/loosened": "pack_objects.loosened_unused_packed_objects", + "data:pack-objects:stdin_packs_found": "pack_objects.stdin_packs_found", + "data:pack-objects:stdin_packs_hints": "pack_objects.stdin_packs_hints", +} + +var statsElapsedTimes = map[string]string{ + "pack-objects:enumerate-objects": "pack_objects.enumerate_objects_ms", + "pack-objects:prepare-pack": "pack_objects.prepare_pack_ms", + "pack-objects:write-pack-file": "pack_objects.write_pack_file_ms", +} + +var histogramStageNames = map[string]string{ + "pack-objects:enumerate-objects": "enumerate-objects", + "pack-objects:prepare-pack": "prepare-pack", + "pack-objects:write-pack-file": "write-pack-file", +} + +// PackObjectsMetrics is a trace2 hook that export pack-objects Prometheus metrics and stats log +// fields. This information is extracted by traversing the trace2 event tree. +type PackObjectsMetrics struct { + metrics *prometheus.HistogramVec +} + +// NewPackObjectsMetrics is the initializer for PackObjectsMetrics +func NewPackObjectsMetrics() *PackObjectsMetrics { + return &PackObjectsMetrics{ + metrics: prometheus.NewHistogramVec( + prometheus.HistogramOpts{ + Name: "gitaly_pack_objects_stages_seconds", + Help: "Time of pack-objects command on different stage", + }, + []string{"stage"}, + ), + } +} + +// Name returns the name of the hooks +func (p *PackObjectsMetrics) Name() string { + return "pack_objects_metrics" +} + +// Handle traverses input trace2 event tree for data nodes containing relevant pack-objects data. +// When it finds one, it updates Prometheus objects and log fields accordingly. +func (p *PackObjectsMetrics) Handle(rootCtx context.Context, trace *trace2.Trace) error { + trace.Walk(rootCtx, func(ctx context.Context, trace *trace2.Trace) context.Context { + stats := command.StatsFromContext(ctx) + if stats != nil { + if field, ok := statsIntData[trace.Name]; ok { + data, err := strconv.Atoi(trace.Metadata["data"]) + if err == nil { + stats.RecordSum(field, data) + } + } + + if field, ok := statsElapsedTimes[trace.Name]; ok { + elapsedTime := trace.FinishTime.Sub(trace.StartTime).Milliseconds() + stats.RecordSum(field, int(elapsedTime)) + } + + if stage, ok := histogramStageNames[trace.Name]; ok { + elapsedTime := trace.FinishTime.Sub(trace.StartTime).Seconds() + p.metrics.WithLabelValues(stage).Observe(elapsedTime) + } + + return ctx + } + return ctx + }) + return nil +} + +// Describe describes Prometheus metrics exposed by the PackObjectsMetrics structure. +func (p *PackObjectsMetrics) Describe(descs chan<- *prometheus.Desc) { + prometheus.DescribeByCollect(p, descs) +} + +// Collect collects Prometheus metrics exposed by the PackObjectsMetrics structure. +func (p *PackObjectsMetrics) Collect(c chan<- prometheus.Metric) { + p.metrics.Collect(c) +} diff --git a/internal/git/trace2hooks/packobjects_metrics_ext_test.go b/internal/git/trace2hooks/packobjects_metrics_ext_test.go new file mode 100644 index 000000000..0785e4cd8 --- /dev/null +++ b/internal/git/trace2hooks/packobjects_metrics_ext_test.go @@ -0,0 +1,213 @@ +package trace2hooks_test + +import ( + "bytes" + "context" + "fmt" + "testing" + + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly/v15/internal/command" + "gitlab.com/gitlab-org/gitaly/v15/internal/git" + "gitlab.com/gitlab-org/gitaly/v15/internal/git/gittest" + "gitlab.com/gitlab-org/gitaly/v15/internal/git/trace2" + "gitlab.com/gitlab-org/gitaly/v15/internal/git/trace2hooks" + "gitlab.com/gitlab-org/gitaly/v15/internal/gitaly/config" + "gitlab.com/gitlab-org/gitaly/v15/internal/testhelper" + "gitlab.com/gitlab-org/gitaly/v15/internal/testhelper/testcfg" + "gitlab.com/gitlab-org/gitaly/v15/proto/go/gitalypb" +) + +func TestMain(m *testing.M) { + testhelper.Run(m) +} + +func TestPackObjectsMetrics(t *testing.T) { + t.Parallel() + + for _, tc := range []struct { + desc string + setupRepo func(ctx context.Context) (*gitalypb.Repository, config.Cfg, bytes.Buffer) + assert func(*testing.T, logrus.Fields) + }{ + { + desc: "pack blobs", + setupRepo: func(ctx context.Context) (*gitalypb.Repository, config.Cfg, bytes.Buffer) { + cfg := testcfg.Build(t) + repoProto, repoPath := gittest.CreateRepository(t, ctx, cfg, + gittest.CreateRepositoryConfig{SkipCreationViaService: true}, + ) + + var input bytes.Buffer + for i := 0; i <= 10; i++ { + content := fmt.Sprintf("hello %d", i) + input.WriteString(gittest.WriteBlob(t, cfg, repoPath, []byte(content)).String()) + input.WriteString("\n") + } + + return repoProto, cfg, input + }, + assert: func(t *testing.T, statFields logrus.Fields) { + require.Equal(t, 11, statFields["pack_objects.written_object_count"]) + }, + }, + { + desc: "pack commits", + setupRepo: func(ctx context.Context) (*gitalypb.Repository, config.Cfg, bytes.Buffer) { + cfg := testcfg.Build(t) + repoProto, repoPath := gittest.CreateRepository(t, ctx, cfg, + gittest.CreateRepositoryConfig{SkipCreationViaService: true}, + ) + + var input bytes.Buffer + input.WriteString(gittest.WriteCommit(t, cfg, repoPath, gittest.WithMessage("reachable"), gittest.WithBranch("reachable")).String()) + input.WriteString("\n") + input.WriteString(gittest.WriteCommit(t, cfg, repoPath, gittest.WithMessage("unreachable")).String()) + input.WriteString("\n") + + return repoProto, cfg, input + }, + assert: func(t *testing.T, statFields logrus.Fields) { + require.Equal(t, 3, statFields["pack_objects.written_object_count"]) + }, + }, + { + desc: "pack refs", + setupRepo: func(ctx context.Context) (*gitalypb.Repository, config.Cfg, bytes.Buffer) { + cfg := testcfg.Build(t) + repoProto, repoPath := gittest.CreateRepository(t, ctx, cfg, + gittest.CreateRepositoryConfig{SkipCreationViaService: true}, + ) + + var input bytes.Buffer + commit := gittest.WriteCommit(t, cfg, repoPath, gittest.WithMessage("commit"), gittest.WithBranch("main")) + for i := 0; i <= 10; i++ { + ref := fmt.Sprintf("ref-%d", i) + gittest.WriteRef(t, cfg, repoPath, git.ReferenceName(ref), commit) + input.WriteString(ref) + input.WriteString("\n") + } + + return repoProto, cfg, input + }, + assert: func(t *testing.T, statFields logrus.Fields) { + require.Equal(t, 2, statFields["pack_objects.written_object_count"]) + }, + }, + { + desc: "pack tags", + setupRepo: func(ctx context.Context) (*gitalypb.Repository, config.Cfg, bytes.Buffer) { + cfg := testcfg.Build(t) + repoProto, repoPath := gittest.CreateRepository(t, ctx, cfg, + gittest.CreateRepositoryConfig{SkipCreationViaService: true}, + ) + + var input bytes.Buffer + commit := gittest.WriteCommit(t, cfg, repoPath, gittest.WithMessage("commit"), gittest.WithBranch("main")) + for i := 0; i <= 10; i++ { + tag := fmt.Sprintf("tag-%d", i) + gittest.WriteTag(t, cfg, repoPath, tag, commit.Revision()) + input.WriteString(tag) + input.WriteString("\n") + } + + return repoProto, cfg, input + }, + assert: func(t *testing.T, statFields logrus.Fields) { + require.Equal(t, 2, statFields["pack_objects.written_object_count"]) + }, + }, + { + desc: "pack tree", + setupRepo: func(ctx context.Context) (*gitalypb.Repository, config.Cfg, bytes.Buffer) { + cfg := testcfg.Build(t) + repoProto, repoPath := gittest.CreateRepository(t, ctx, cfg, + gittest.CreateRepositoryConfig{SkipCreationViaService: true}, + ) + + var input bytes.Buffer + tree := gittest.WriteTree(t, cfg, repoPath, []gittest.TreeEntry{ + { + Mode: "100644", + Path: "file1", + Content: "file1", + }, + { + Mode: "100644", + Path: "file2", + Content: "file2", + }, + { + Mode: "100644", + Path: "file3", + Content: "file3", + }, + { + OID: gittest.WriteTree(t, cfg, repoPath, []gittest.TreeEntry{ + { + Mode: "100644", + Path: "subfile1", + Content: "subfile1", + }, + { + Mode: "100644", + Path: "subfile2", + Content: "subfile2", + }, + }), + Mode: "040000", + Path: "subdir", + }, + }) + input.WriteString(tree.String()) + input.WriteString("\n") + + return repoProto, cfg, input + }, + assert: func(t *testing.T, statFields logrus.Fields) { + require.Equal(t, 7, statFields["pack_objects.written_object_count"]) + }, + }, + } { + tc := tc + + t.Run(tc.desc, func(t *testing.T) { + t.Parallel() + + ctx := command.InitContextStats(testhelper.Context(t)) + repoProto, cfg, input := tc.setupRepo(ctx) + gitCmdFactory, cleanup, err := git.NewExecCommandFactory(cfg, git.WithTrace2Hooks([]trace2.Hook{ + trace2hooks.NewPackObjectsMetrics(), + })) + require.NoError(t, err) + defer cleanup() + + cmd, err := gitCmdFactory.New(ctx, repoProto, git.Command{ + Name: "pack-objects", + Flags: []git.Option{ + git.Flag{Name: "--compression=0"}, + git.Flag{Name: "--stdout"}, + git.Flag{Name: "--unpack-unreachable"}, + git.Flag{Name: "-q"}, + }, + }, git.WithStdin(&input)) + require.NoError(t, err) + + err = cmd.Wait() + require.NoError(t, err) + + stats := command.StatsFromContext(ctx) + require.NotNil(t, stats) + + statFields := stats.Fields() + require.Equal(t, "true", statFields["trace2.activated"]) + require.Equal(t, "pack_objects_metrics", statFields["trace2.hooks"]) + require.Contains(t, statFields, "pack_objects.enumerate_objects_ms") + require.Contains(t, statFields, "pack_objects.prepare_pack_ms") + require.Contains(t, statFields, "pack_objects.write_pack_file_ms") + + tc.assert(t, statFields) + }) + } +} diff --git a/internal/git/trace2hooks/packobjects_metrics_test.go b/internal/git/trace2hooks/packobjects_metrics_test.go new file mode 100644 index 000000000..ded1fa95e --- /dev/null +++ b/internal/git/trace2hooks/packobjects_metrics_test.go @@ -0,0 +1,398 @@ +package trace2hooks + +import ( + "bytes" + "testing" + "time" + + "github.com/prometheus/client_golang/prometheus/testutil" + "github.com/sirupsen/logrus" + "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly/v15/internal/command" + "gitlab.com/gitlab-org/gitaly/v15/internal/git/trace2" + "gitlab.com/gitlab-org/gitaly/v15/internal/testhelper" +) + +func TestPackObjectsMetrics_Handle(t *testing.T) { + t.Parallel() + + // Pin a timestamp for trace tree generation below. This way enables asserting the time + // frames of spans correctly. + current, err := time.Parse("2006-01-02T15:04:05Z", "2023-01-01T00:00:00Z") + require.NoError(t, err) + + for _, tc := range []struct { + desc string + inputTrace *trace2.Trace + expectedMetrics string + expectedStats logrus.Fields + }{ + { + desc: "empty trace", + inputTrace: nil, + expectedStats: logrus.Fields{}, + expectedMetrics: ``, + }, + { + desc: "receives trace consisting of root only", + inputTrace: &trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: current, + FinishTime: time.Time{}, + }, + expectedStats: logrus.Fields{}, + expectedMetrics: ``, + }, + { + desc: "receives a complete trace", + inputTrace: connectChildren(&trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: current, + FinishTime: current.Add(9 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "version", + StartTime: current, + FinishTime: current.Add(1 * time.Second), + }, + { + Thread: "main", + Name: "start", + StartTime: current.Add(1 * time.Second), + FinishTime: current.Add(2 * time.Second), + Metadata: map[string]string{"argv": "git pack-objects toon --compression=0"}, + }, + { + Thread: "main", + Name: "def_repo", + StartTime: current.Add(2 * time.Second), + FinishTime: current.Add(3 * time.Second), + }, + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:enumerate-objects", + StartTime: current.Add(3 * time.Second), + FinishTime: current.Add(5 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "data:pack-objects:stdin_packs_hints", + ChildID: "0", + Metadata: map[string]string{ + "data": "999", + }, + StartTime: current.Add(3 * time.Second), + FinishTime: current.Add(4 * time.Second), + }, + { + Thread: "main", + Name: "data:pack-objects:stdin_packs_found", + ChildID: "0", + Metadata: map[string]string{ + "data": "998", + }, + StartTime: current.Add(4 * time.Second), + FinishTime: current.Add(5 * time.Second), + }, + }, + }), + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:prepare-pack", + StartTime: current.Add(5 * time.Second), + FinishTime: current.Add(7 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "progress:Counting objects", + ChildID: "0", + StartTime: current.Add(5 * time.Second), + FinishTime: current.Add(6 * time.Second), + }, + { + Thread: "main", + Name: "data:pack-objects:loosen_unused_packed_objects/loosened", + ChildID: "0", + Metadata: map[string]string{ + "data": "1234", + }, + StartTime: current.Add(6 * time.Second), + FinishTime: current.Add(7 * time.Second), + }, + }, + }, + ), + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:write-pack-file", + StartTime: current.Add(7 * time.Second), + FinishTime: current.Add(9 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "progress:Writing objects", + ChildID: "0", + StartTime: current.Add(7 * time.Second), + FinishTime: current.Add(8 * time.Second), + }, + { + Thread: "main", + Name: "data:pack-objects:write_pack_file/wrote", + ChildID: "0", + Metadata: map[string]string{ + "data": "99", + }, + StartTime: current.Add(8 * time.Second), + FinishTime: current.Add(9 * time.Second), + }, + }, + }, + ), + }, + }), + expectedStats: logrus.Fields{ + "pack_objects.written_object_count": 99, + "pack_objects.loosened_unused_packed_objects": 1234, + "pack_objects.stdin_packs_hints": 999, + "pack_objects.stdin_packs_found": 998, + "pack_objects.enumerate_objects_ms": 2000, + "pack_objects.prepare_pack_ms": 2000, + "pack_objects.write_pack_file_ms": 2000, + }, + expectedMetrics: `# HELP gitaly_pack_objects_stages_seconds Time of pack-objects command on different stage +# TYPE gitaly_pack_objects_stages_seconds histogram +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.005"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.01"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.025"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.05"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.25"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.5"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="2.5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="10"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="+Inf"} 1 +gitaly_pack_objects_stages_seconds_sum{stage="enumerate-objects"} 2 +gitaly_pack_objects_stages_seconds_count{stage="enumerate-objects"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.005"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.01"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.025"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.05"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.25"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.5"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="2.5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="10"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="+Inf"} 1 +gitaly_pack_objects_stages_seconds_sum{stage="prepare-pack"} 2 +gitaly_pack_objects_stages_seconds_count{stage="prepare-pack"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.005"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.01"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.025"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.05"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.25"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.5"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="2.5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="10"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="+Inf"} 1 +gitaly_pack_objects_stages_seconds_sum{stage="write-pack-file"} 2 +gitaly_pack_objects_stages_seconds_count{stage="write-pack-file"} 1 + +`, + }, + { + desc: "tree contains multiple relative fields", + inputTrace: connectChildren(&trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: current, + FinishTime: current.Add(9 * time.Second), + Children: []*trace2.Trace{ + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:enumerate-objects", + StartTime: current.Add(3 * time.Second), + FinishTime: current.Add(5 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "data:pack-objects:stdin_packs_hints", + ChildID: "0", + Metadata: map[string]string{ + "data": "999", + }, + StartTime: current.Add(3 * time.Second), + FinishTime: current.Add(4 * time.Second), + }, + { + Thread: "main", + Name: "data:pack-objects:stdin_packs_found", + ChildID: "0", + Metadata: map[string]string{ + "data": "998", + }, + StartTime: current.Add(4 * time.Second), + FinishTime: current.Add(5 * time.Second), + }, + }, + }), + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:prepare-pack", + StartTime: current, + FinishTime: current.Add(5 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "data:pack-objects:loosen_unused_packed_objects/loosened", + ChildID: "0", + Metadata: map[string]string{ + "data": "1234", + }, + }, + { + Thread: "main", + Name: "data:pack-objects:loosen_unused_packed_objects/loosened", + ChildID: "0", + Metadata: map[string]string{ + "data": "3456", + }, + }, + }, + }, + ), + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:prepare-pack", + StartTime: current.Add(5 * time.Second), + FinishTime: current.Add(7 * time.Second), + Children: []*trace2.Trace{}, + }, + ), + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:write-pack-file", + StartTime: current.Add(7 * time.Second), + FinishTime: current.Add(8 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "data:pack-objects:write_pack_file/wrote", + ChildID: "0", + Metadata: map[string]string{ + "data": "99", + }, + }, + }, + }, + ), + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "pack-objects:write-pack-file", + StartTime: current.Add(8 * time.Second), + FinishTime: current.Add(9 * time.Second), + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "data:pack-objects:write_pack_file/wrote", + ChildID: "0", + Metadata: map[string]string{ + "data": "2", + }, + }, + }, + }, + ), + }, + }), + expectedStats: logrus.Fields{ + "pack_objects.written_object_count": 101, + "pack_objects.loosened_unused_packed_objects": 4690, + "pack_objects.stdin_packs_hints": 999, + "pack_objects.stdin_packs_found": 998, + "pack_objects.enumerate_objects_ms": 2000, + "pack_objects.prepare_pack_ms": 7000, + "pack_objects.write_pack_file_ms": 2000, + }, + expectedMetrics: `# HELP gitaly_pack_objects_stages_seconds Time of pack-objects command on different stage +# TYPE gitaly_pack_objects_stages_seconds histogram +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.005"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.01"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.025"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.05"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.25"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="0.5"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="2.5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="10"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="enumerate-objects",le="+Inf"} 1 +gitaly_pack_objects_stages_seconds_sum{stage="enumerate-objects"} 2 +gitaly_pack_objects_stages_seconds_count{stage="enumerate-objects"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.005"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.01"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.025"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.05"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.25"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="0.5"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="2.5"} 1 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="5"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="10"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="prepare-pack",le="+Inf"} 2 +gitaly_pack_objects_stages_seconds_sum{stage="prepare-pack"} 7 +gitaly_pack_objects_stages_seconds_count{stage="prepare-pack"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.005"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.01"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.025"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.05"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.1"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.25"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="0.5"} 0 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="1"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="2.5"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="5"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="10"} 2 +gitaly_pack_objects_stages_seconds_bucket{stage="write-pack-file",le="+Inf"} 2 +gitaly_pack_objects_stages_seconds_sum{stage="write-pack-file"} 2 +gitaly_pack_objects_stages_seconds_count{stage="write-pack-file"} 2 + +`, + }, + } { + tc := tc + + t.Run(tc.desc, func(t *testing.T) { + t.Parallel() + ctx := command.InitContextStats(testhelper.Context(t)) + + exporter := NewPackObjectsMetrics() + + err := exporter.Handle(ctx, tc.inputTrace) + require.NoError(t, err) + + require.NoError( + t, + testutil.CollectAndCompare( + exporter, + bytes.NewBufferString(tc.expectedMetrics), + ), + ) + + stats := command.StatsFromContext(ctx) + require.NotNil(t, stats) + require.Equal(t, tc.expectedStats, stats.Fields()) + }) + } +} diff --git a/internal/git/trace2hooks/tracingexporter.go b/internal/git/trace2hooks/tracingexporter.go index 1f7e9f3bd..94a00da93 100644 --- a/internal/git/trace2hooks/tracingexporter.go +++ b/internal/git/trace2hooks/tracingexporter.go @@ -9,6 +9,12 @@ import ( "gitlab.com/gitlab-org/gitaly/v15/internal/tracing" ) +// NewTracingExporter initializes TracingExporter, which is a hook to convert Trace2 events to +// corresponding distributed tracing +func NewTracingExporter() *TracingExporter { + return &TracingExporter{} +} + // TracingExporter is a trace2 hook that converts the trace2 tree to corresponding distributed // tracing's spans. These spans are then collected if the process initializes labkit's tracing // utility. diff --git a/internal/git/trace2hooks/tracingexporter_test.go b/internal/git/trace2hooks/tracingexporter_test.go index a506d7612..5c3afb03d 100644 --- a/internal/git/trace2hooks/tracingexporter_test.go +++ b/internal/git/trace2hooks/tracingexporter_test.go @@ -218,7 +218,7 @@ func TestTracingExporter_Handle(t *testing.T) { reporter.Reset() ctx, trace := tc.setup(t) - exporter := TracingExporter{} + exporter := NewTracingExporter() err := exporter.Handle(ctx, trace) require.NoError(t, err) diff --git a/internal/metadata/featureflag/ff_export_trace2_pack_objects_metrics.go b/internal/metadata/featureflag/ff_export_trace2_pack_objects_metrics.go new file mode 100644 index 000000000..9ccfa3e97 --- /dev/null +++ b/internal/metadata/featureflag/ff_export_trace2_pack_objects_metrics.go @@ -0,0 +1,10 @@ +package featureflag + +// ExportTrace2PackObjectsMetrics allows Gitaly enables trace2 and export internal Git metrics +// of pack-objects commands +var ExportTrace2PackObjectsMetrics = NewFeatureFlag( + "export_trace2_pack_objects_metrics", + "v15.11.0", + "https://gitlab.com/gitlab-org/gitaly/-/issues/4997", + false, +) diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go index 9f810c58d..db19842c9 100644 --- a/internal/testhelper/testhelper.go +++ b/internal/testhelper/testhelper.go @@ -204,8 +204,9 @@ func ContextWithoutCancel(opts ...ContextOpt) context.Context { // Randomly enable the use of the catfile cache in localrepo.ReadObject. ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.LocalrepoReadObjectCached, rnd.Int()%2 == 0) - // Randomly enable the use of trace2 tracing exporter. + // Randomly enable the use of trace2 flags ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.ExportTrace2Tracing, rnd.Int()%2 == 0) + ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.ExportTrace2PackObjectsMetrics, rnd.Int()%2 == 0) for _, opt := range opts { ctx = opt(ctx) |