From f8dd1f5099a97ca91a3c5a57b99541b7e1546f0a Mon Sep 17 00:00:00 2001 From: Emily Chui Date: Fri, 19 Jan 2024 03:42:06 +0000 Subject: Create new hook to export git trace 2 events in gitaly logs --- doc/trace2_integration.md | 3 + internal/featureflag/ff_log_git_traces.go | 9 ++ internal/git/command_factory.go | 34 +++- internal/git/command_factory_test.go | 21 ++- internal/git/trace2/parser.go | 24 ++- internal/git/trace2/parser_test.go | 38 ++--- internal/git/trace2/testdata/git-status.event | 2 +- internal/git/trace2/trace.go | 26 ++-- internal/git/trace2hooks/log_exporter.go | 68 ++++++++ internal/git/trace2hooks/log_exporter_test.go | 190 +++++++++++++++++++++++ internal/git/trace2hooks/trace_helper_test.go | 101 ++++++++++++ internal/git/trace2hooks/tracingexporter_test.go | 88 +---------- internal/testhelper/testhelper.go | 2 + 13 files changed, 475 insertions(+), 131 deletions(-) create mode 100644 internal/featureflag/ff_log_git_traces.go create mode 100644 internal/git/trace2hooks/log_exporter.go create mode 100644 internal/git/trace2hooks/log_exporter_test.go create mode 100644 internal/git/trace2hooks/trace_helper_test.go diff --git a/doc/trace2_integration.md b/doc/trace2_integration.md index 28757d671..3f4e9ea44 100644 --- a/doc/trace2_integration.md +++ b/doc/trace2_integration.md @@ -358,6 +358,9 @@ We must also add the hook to the [default list of Trace2 hooks](https://gitlab.com/gitlab-org/gitaly/-/blob/d15b9c84faee3eb178e7c7d9360832f26d4107a2/internal/git/command_factory.go#L90-99) to make it effective. +There is an additional hook in the default list of Trace2 hooks called `LogExporter` which is enabled by turning on the feature flag `log_git_traces`. This hook will log the trace2 events to Gitaly logs. +Follow [Configure Gitaly](https://docs.gitlab.com/ee/administration/gitaly/configure_gitaly.html) to setup the feature flag. + ## Custom Trace2 instrumentation Although Trace comes bundled with numerous events and data, they may not be diff --git a/internal/featureflag/ff_log_git_traces.go b/internal/featureflag/ff_log_git_traces.go new file mode 100644 index 000000000..c8307c578 --- /dev/null +++ b/internal/featureflag/ff_log_git_traces.go @@ -0,0 +1,9 @@ +package featureflag + +// LogGitTraces enables the collection of distributed traces via the git trace 2 API +var LogGitTraces = NewFeatureFlag( + "log_git_traces", + "v16.9.0", + "https://gitlab.com/gitlab-org/gitaly/-/issues/5700", + false, +) diff --git a/internal/git/command_factory.go b/internal/git/command_factory.go index 5cf710ca2..a22df685b 100644 --- a/internal/git/command_factory.go +++ b/internal/git/command_factory.go @@ -13,6 +13,7 @@ import ( "github.com/prometheus/client_golang/prometheus" "gitlab.com/gitlab-org/gitaly/v16/internal/cgroups" "gitlab.com/gitlab-org/gitaly/v16/internal/command" + "gitlab.com/gitlab-org/gitaly/v16/internal/featureflag" "gitlab.com/gitlab-org/gitaly/v16/internal/git/alternates" "gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2" "gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2hooks" @@ -21,12 +22,18 @@ import ( "gitlab.com/gitlab-org/gitaly/v16/internal/log" "gitlab.com/gitlab-org/gitaly/v16/internal/tracing" "gitlab.com/gitlab-org/labkit/correlation" + "golang.org/x/time/rate" ) const ( // BigFileThresholdMB is the threshold we configure via `core.bigFileThreshold` and determines the maximum size // after which Git considers files to be big. Please refer to `GlobalConfiguration()` for more details. BigFileThresholdMB = 50 + // maxTrace2EventPerSecond is the maximum number of events that can be processed per second + maxTrace2EventPerSecond = 40 + // Rate limiter is immediately allocated the maxBurstToken value. Burst is the maximum number of tokens + // that can be consumed in a single call + maxBurstToken = 40 ) // CommandFactory is designed to create and run git commands in a protected and fully managed manner. @@ -48,6 +55,7 @@ type execCommandFactoryConfig struct { gitBinaryPath string cgroupsManager cgroups.Manager trace2Hooks []trace2.Hook + traceRateLimiter *rate.Limiter execEnvConstructors []ExecutionEnvironmentConstructor } @@ -91,7 +99,7 @@ func WithTrace2Hooks(hooks []trace2.Hook) ExecCommandFactoryOption { // DefaultTrace2HooksFor creates a list of all Trace2 hooks. It doesn't mean all hooks are triggered. // Each hook's activation status will be evaluated before the command starts. -func DefaultTrace2HooksFor(ctx context.Context, subCmd string) []trace2.Hook { +func DefaultTrace2HooksFor(ctx context.Context, subCmd string, logger log.Logger, rl *rate.Limiter) []trace2.Hook { var hooks []trace2.Hook if tracing.IsSampled(ctx) { hooks = append(hooks, trace2hooks.NewTracingExporter()) @@ -99,6 +107,9 @@ func DefaultTrace2HooksFor(ctx context.Context, subCmd string) []trace2.Hook { if subCmd == "pack-objects" { hooks = append(hooks, trace2hooks.NewPackObjectsMetrics()) } + if featureflag.LogGitTraces.IsEnabled(ctx) { + hooks = append(hooks, trace2hooks.NewLogExporter(rl, logger)) + } return hooks } @@ -127,6 +138,7 @@ type ExecCommandFactory struct { logger log.Logger cgroupsManager cgroups.Manager trace2Hooks []trace2.Hook + traceRateLimiter *rate.Limiter invalidCommandsMetric *prometheus.CounterVec hookDirs hookDirectories @@ -172,13 +184,19 @@ func NewExecCommandFactory(cfg config.Cfg, logger log.Logger, opts ...ExecComman cgroupsManager = cgroups.NewManager(cfg.Cgroups, logger, os.Getpid()) } + traceRateLimiter := factoryCfg.traceRateLimiter + if traceRateLimiter == nil { + traceRateLimiter = rate.NewLimiter(maxTrace2EventPerSecond, maxBurstToken) + } + gitCmdFactory := &ExecCommandFactory{ - cfg: cfg, - execEnvs: execEnvs, - logger: logger, - locator: config.NewLocator(cfg), - cgroupsManager: cgroupsManager, - trace2Hooks: factoryCfg.trace2Hooks, + cfg: cfg, + execEnvs: execEnvs, + logger: logger, + locator: config.NewLocator(cfg), + cgroupsManager: cgroupsManager, + trace2Hooks: factoryCfg.trace2Hooks, + traceRateLimiter: traceRateLimiter, invalidCommandsMetric: prometheus.NewCounterVec( prometheus.CounterOpts{ Name: "gitaly_invalid_commands_total", @@ -469,7 +487,7 @@ func (cf *ExecCommandFactory) newCommand(ctx context.Context, repo storage.Repos trace2Hooks := cf.trace2Hooks if trace2Hooks == nil { - trace2Hooks = DefaultTrace2HooksFor(ctx, sc.Name) + trace2Hooks = DefaultTrace2HooksFor(ctx, sc.Name, cf.logger, cf.traceRateLimiter) } if len(trace2Hooks) != 0 { trace2Manager, err := trace2.NewManager(correlation.ExtractFromContextOrGenerate(ctx), trace2Hooks) diff --git a/internal/git/command_factory_test.go b/internal/git/command_factory_test.go index f1dfca0b4..6e04ceb3a 100644 --- a/internal/git/command_factory_test.go +++ b/internal/git/command_factory_test.go @@ -16,6 +16,7 @@ import ( "testing" "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly/v16/internal/featureflag" "gitlab.com/gitlab-org/gitaly/v16/internal/git" "gitlab.com/gitlab-org/gitaly/v16/internal/git/gittest" "gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2" @@ -26,6 +27,7 @@ import ( "gitlab.com/gitlab-org/gitaly/v16/internal/testhelper" "gitlab.com/gitlab-org/gitaly/v16/internal/testhelper/testcfg" "gitlab.com/gitlab-org/gitaly/v16/internal/tracing" + "golang.org/x/time/rate" ) func TestGitCommandProxy(t *testing.T) { @@ -1058,6 +1060,23 @@ func TestDefaultTrace2HooksFor(t *testing.T) { trace2hooks.NewPackObjectsMetrics(), } + return ctx, hooks + }, + }, + { + desc: "subcmd is pack-objects, active span is sampled and feature flag LogGitTraces enabled", + subCmd: "pack-objects", + setup: func(t *testing.T) (context.Context, []trace2.Hook) { + ctx := testhelper.Context(t) + ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.LogGitTraces, true) + _, ctx = tracing.StartSpan(ctx, "root", nil) + + hooks := []trace2.Hook{ + trace2hooks.NewTracingExporter(), + trace2hooks.NewPackObjectsMetrics(), + trace2hooks.NewLogExporter(rate.NewLimiter(1, 1), testhelper.SharedLogger(t)), + } + return ctx, hooks }, }, @@ -1067,7 +1086,7 @@ func TestDefaultTrace2HooksFor(t *testing.T) { defer cleanup() ctx, expectedHooks := tc.setup(t) - hooks := git.DefaultTrace2HooksFor(ctx, tc.subCmd) + hooks := git.DefaultTrace2HooksFor(ctx, tc.subCmd, testhelper.SharedLogger(t), rate.NewLimiter(1, 1)) require.Equal(t, hookNames(expectedHooks), hookNames(hooks)) }) diff --git a/internal/git/trace2/parser.go b/internal/git/trace2/parser.go index 58248cf13..e5ecbdec7 100644 --- a/internal/git/trace2/parser.go +++ b/internal/git/trace2/parser.go @@ -73,6 +73,9 @@ type jsonEvent struct { ChildID int `json:"child_id"` Msg string `json:"msg"` Code int `json:"code"` + Exe string `json:"exe"` + Evt string `json:"evt"` + Worktree string `json:"worktree"` } var ignoredEvents = map[string]struct{}{ @@ -137,11 +140,11 @@ func (p *parser) parseEvent(event *jsonEvent) error { switch event.Name { case "atexit": p.currentNode.FinishTime = eventTime - p.currentNode.setMetadata("code", fmt.Sprintf("%d", event.Code)) + p.currentNode.SetMetadata("code", fmt.Sprintf("%d", event.Code)) return nil case "child_exit": p.currentNode.FinishTime = eventTime - p.currentNode.setMetadata("code", fmt.Sprintf("%d", event.Code)) + p.currentNode.SetMetadata("code", fmt.Sprintf("%d", event.Code)) p.currentNode = p.currentNode.Parent return nil case "region_leave": @@ -159,17 +162,24 @@ func (p *parser) parseEvent(event *jsonEvent) error { Depth: p.currentNode.Depth + 1, } if event.Msg != "" { - trace.setMetadata("msg", event.Msg) + trace.SetMetadata("msg", event.Msg) } p.currentNode.Children = append(p.currentNode.Children, trace) switch event.Name { + case "version": + trace.setName([]string{event.Name, event.Category, event.Label}) + trace.SetMetadata("exe", event.Exe) + trace.SetMetadata("evt", event.Evt) + case "def_repo": + trace.setName([]string{event.Name, event.Category, event.Label}) + trace.SetMetadata("worktree", event.Worktree) case "start": trace.setName([]string{event.Name, event.Category, event.Label}) - trace.setMetadata("argv", strings.Join(event.Argv, " ")) + trace.SetMetadata("argv", strings.Join(event.Argv, " ")) case "child_start": trace.setName([]string{event.Name, event.Category, event.Label}) - trace.setMetadata("argv", strings.Join(event.Argv, " ")) + trace.SetMetadata("argv", strings.Join(event.Argv, " ")) trace.ChildID = fmt.Sprintf("%d", event.ChildID) p.currentNode = trace case "region_enter": @@ -185,12 +195,12 @@ func (p *parser) parseEvent(event *jsonEvent) error { if err != nil { return fmt.Errorf("mismatched data value: %w", err) } - trace.setMetadata("data", data) + trace.SetMetadata("data", data) } case "data_json": trace.setName([]string{event.Name, event.Category, event.Label, event.DataKey}) if event.DataValue != nil { - trace.setMetadata("data", string(*event.DataValue)) + trace.SetMetadata("data", string(*event.DataValue)) } default: trace.setName([]string{event.Name, event.Category, event.Label}) diff --git a/internal/git/trace2/parser_test.go b/internal/git/trace2/parser_test.go index 8d53f6885..cda886b70 100644 --- a/internal/git/trace2/parser_test.go +++ b/internal/git/trace2/parser_test.go @@ -114,9 +114,9 @@ func TestParser_Parse(t *testing.T) { `, expectedTrace: ` 2023-02-22T12:05:04.840009Z | 0001-01-01T00:00:00Z | | main | root -2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z | | main | .version +2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z | | main | .version (evt="3" exe="2.39.1") 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .start (argv="git pack-objects toon --compression=0") -2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .def_repo +2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .def_repo (worktree="/gitaly") 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .pack-objects:enumerate-objects 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.84343Z | | main | ..progress:Enumerating objects `, @@ -150,9 +150,9 @@ func TestParser_Parse(t *testing.T) { events: string(testhelper.MustReadFile(t, "testdata/git-status.event")), expectedTrace: ` 2023-02-21T08:10:10.668546Z | 2023-02-21T08:10:10.687877Z | | main | root (code="0") -2023-02-21T08:10:10.668546Z | 2023-02-21T08:10:10.668546Z | | main | .version +2023-02-21T08:10:10.668546Z | 2023-02-21T08:10:10.668546Z | | main | .version (evt="3" exe="2.39.1") 2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754608Z | | main | .start (argv="git status") -2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754608Z | | main | .def_repo +2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754608Z | | main | .def_repo (worktree="/Users/userx/www/gitlab-development-kit/gitaly") 2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.755102Z | | main | .index:do_read_index (msg=".git/index") 2023-02-21T08:10:10.754608Z | 2023-02-21T08:10:10.754732Z | | main | ..cache_tree:read 2023-02-21T08:10:10.758297Z | 2023-02-21T08:10:10.758297Z | | main | ..data:index:read/version (data="2") @@ -182,9 +182,9 @@ func TestParser_Parse(t *testing.T) { events: string(testhelper.MustReadFile(t, "testdata/git-fetch.event")), expectedTrace: ` 2023-02-22T07:24:36.291735Z | 2023-02-22T07:24:40.554407Z | | main | root (code="0") -2023-02-22T07:24:36.291735Z | 2023-02-22T07:24:36.291735Z | | main | .version +2023-02-22T07:24:36.291735Z | 2023-02-22T07:24:36.291735Z | | main | .version (evt="3" exe="2.39.1") 2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293932Z | | main | .start (argv="git fetch origin master") -2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293932Z | | main | .def_repo +2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293932Z | | main | .def_repo (worktree="/gitaly") 2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.294119Z | | main | .index:do_read_index (msg=".git/index") 2023-02-22T07:24:36.293932Z | 2023-02-22T07:24:36.293975Z | | main | ..cache_tree:read 2023-02-22T07:24:36.294718Z | 2023-02-22T07:24:36.294718Z | | main | ..data:index:read/version (data="2") @@ -193,15 +193,15 @@ func TestParser_Parse(t *testing.T) { 2023-02-22T07:24:36.294119Z | 2023-02-22T07:24:40.128447Z | 0 | main | ..child_start (argv="ssh -o SendEnv=GIT_PROTOCOL git@gitlab.com git-upload-pack 'gitlab-org/gitaly.git'") 2023-02-22T07:24:39.314775Z | 2023-02-22T07:24:39.314775Z | 0 | main | ...data:transfer:negotiated-version (data="2") 2023-02-22T07:24:40.128447Z | 2023-02-22T07:24:40.165067Z | 1 | main | ..child_start (argv="git rev-list --objects --stdin --not --all --quiet --alternate-refs" code="0") -2023-02-22T07:24:40.148998Z | 2023-02-22T07:24:40.148998Z | 1 | main | ...version +2023-02-22T07:24:40.148998Z | 2023-02-22T07:24:40.148998Z | 1 | main | ...version (evt="3" exe="2.39.1") 2023-02-22T07:24:36.295636Z | 2023-02-22T07:24:36.295636Z | 1 | main | ...start (argv="git rev-list --objects --stdin --not --all --quiet --alternate-refs") -2023-02-22T07:24:36.295636Z | 2023-02-22T07:24:36.295636Z | 1 | main | ...def_repo +2023-02-22T07:24:36.295636Z | 2023-02-22T07:24:36.295636Z | 1 | main | ...def_repo (worktree="/gitaly") 2023-02-22T07:24:40.165067Z | 2023-02-22T07:24:40.1658Z | | main | ..fetch:consume_refs 2023-02-22T07:24:40.539196Z | 2023-02-22T07:24:40.539281Z | | main | .submodule:parallel/fetch (msg="max:1") 2023-02-22T07:24:40.539281Z | 2023-02-22T07:24:40.550543Z | 2 | main | .child_start (argv="git maintenance run --auto --no-quiet" code="0") -2023-02-22T07:24:40.54863Z | 2023-02-22T07:24:40.54863Z | 2 | main | ..version +2023-02-22T07:24:40.54863Z | 2023-02-22T07:24:40.54863Z | 2 | main | ..version (evt="3" exe="2.39.1") 2023-02-22T07:24:36.294627Z | 2023-02-22T07:24:36.294627Z | 2 | main | ..start (argv="git maintenance run --auto --no-quiet") -2023-02-22T07:24:36.294627Z | 2023-02-22T07:24:36.294627Z | 2 | main | ..def_repo +2023-02-22T07:24:36.294627Z | 2023-02-22T07:24:36.294627Z | 2 | main | ..def_repo (worktree="/gitaly") `, }, { @@ -209,9 +209,9 @@ func TestParser_Parse(t *testing.T) { events: string(testhelper.MustReadFile(t, "testdata/git-commit.event")), expectedTrace: ` 2023-02-22T11:26:37.174893Z | 2023-02-22T11:26:38.677971Z | | main | root (code="0") -2023-02-22T11:26:37.174893Z | 2023-02-22T11:26:37.174893Z | | main | .version +2023-02-22T11:26:37.174893Z | 2023-02-22T11:26:37.174893Z | | main | .version (evt="3" exe="2.39.1") 2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180753Z | | main | .start (argv="git commit --amend") -2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180753Z | | main | .def_repo +2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180753Z | | main | .def_repo (worktree="/gitaly") 2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.181072Z | | main | .index:do_read_index (msg=".git/index") 2023-02-22T11:26:37.180753Z | 2023-02-22T11:26:37.180832Z | | main | ..cache_tree:read 2023-02-22T11:26:37.185091Z | 2023-02-22T11:26:37.185091Z | | main | ..data:index:read/version (data="2") @@ -243,16 +243,16 @@ func TestParser_Parse(t *testing.T) { 2023-02-22T11:26:37.21406Z | 2023-02-22T11:26:37.214271Z | | main | .status:print 2023-02-22T11:26:37.214271Z | 2023-02-22T11:26:37.214297Z | | main | .cache_tree:update 2023-02-22T11:26:37.214297Z | 2023-02-22T11:26:38.663953Z | 0 | main | .child_start (argv="nvim /gitaly/.git/COMMIT_EDITMSG" code="0") -2023-02-22T11:26:37.353241Z | 2023-02-22T11:26:37.353241Z | 0 | main | ..version +2023-02-22T11:26:37.353241Z | 2023-02-22T11:26:37.353241Z | 0 | main | ..version (evt="3" exe="2.39.1") 2023-02-22T11:26:37.175671Z | 2023-02-22T11:26:37.175671Z | 0 | main | ..start (argv="git diff --no-color --no-ext-diff -U0 -- COMMIT_EDITMSG") 2023-02-22T11:26:37.175671Z | 2023-02-22T11:26:37.175671Z | 0 | main | ..error (msg="this operation must be run in a work tree") -2023-02-22T11:26:38.624567Z | 2023-02-22T11:26:38.624567Z | 0 | main | ..version +2023-02-22T11:26:38.624567Z | 2023-02-22T11:26:38.624567Z | 0 | main | ..version (evt="3" exe="2.39.1") 2023-02-22T11:26:37.175517Z | 2023-02-22T11:26:37.175517Z | 0 | main | ..start (argv="git branch --no-color --show-current") -2023-02-22T11:26:37.175517Z | 2023-02-22T11:26:37.175517Z | 0 | main | ..def_repo +2023-02-22T11:26:37.175517Z | 2023-02-22T11:26:37.175517Z | 0 | main | ..def_repo (worktree="/gitaly") 2023-02-22T11:26:38.663953Z | 2023-02-22T11:26:38.672888Z | 1 | main | .child_start (argv="git maintenance run --auto --no-quiet" code="0") -2023-02-22T11:26:38.667832Z | 2023-02-22T11:26:38.667832Z | 1 | main | ..version +2023-02-22T11:26:38.667832Z | 2023-02-22T11:26:38.667832Z | 1 | main | ..version (evt="3" exe="2.39.1") 2023-02-22T11:26:37.178802Z | 2023-02-22T11:26:37.178802Z | 1 | main | ..start (argv="git maintenance run --auto --no-quiet") -2023-02-22T11:26:37.178802Z | 2023-02-22T11:26:37.178802Z | 1 | main | ..def_repo +2023-02-22T11:26:37.178802Z | 2023-02-22T11:26:37.178802Z | 1 | main | ..def_repo (worktree="/gitaly") 2023-02-22T11:26:38.672888Z | 2023-02-22T11:26:38.672902Z | | main | .diff:setup 2023-02-22T11:26:38.672902Z | 2023-02-22T11:26:38.672907Z | | main | .diff:write back to queue 2023-02-22T11:26:38.677965Z | 2023-02-22T11:26:38.677965Z | | main | .data_json:traverse_trees:statistics (data="{\"traverse_trees_count\":2,\"traverse_trees_max_depth\":2}") @@ -263,9 +263,9 @@ func TestParser_Parse(t *testing.T) { events: string(testhelper.MustReadFile(t, "testdata/git-pack-objects.event")), expectedTrace: ` 2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.848504Z | | main | root (code="0") -2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z | | main | .version +2023-02-22T12:05:04.840009Z | 2023-02-22T12:05:04.840009Z | | main | .version (evt="3" exe="2.39.1") 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .start (argv="git pack-objects toon --compression=0") -2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .def_repo +2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.842347Z | | main | .def_repo (worktree="/gitaly") 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.843782Z | | main | .pack-objects:enumerate-objects 2023-02-22T12:05:04.842347Z | 2023-02-22T12:05:04.84343Z | | main | ..progress:Enumerating objects 2023-02-22T12:05:04.843782Z | 2023-02-22T12:05:04.843872Z | | main | .pack-objects:prepare-pack diff --git a/internal/git/trace2/testdata/git-status.event b/internal/git/trace2/testdata/git-status.event index be77a79f7..99e16d97e 100644 --- a/internal/git/trace2/testdata/git-status.event +++ b/internal/git/trace2/testdata/git-status.event @@ -1,6 +1,6 @@ {"event":"version","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","time":"2023-02-21T08:10:10.668546Z","evt":"3","exe":"2.39.1"} {"event":"start","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","t_abs":0.086062,"argv":["git","status"]} -{"event":"def_repo","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"worktree":"/Users/qmnguyen/www/gitlab-development-kit/gitaly"} +{"event":"def_repo","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"worktree":"/Users/userx/www/gitlab-development-kit/gitaly"} {"event":"cmd_name","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","name":"status","hierarchy":"status"} {"event":"region_enter","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"nesting":1,"category":"index","label":"do_read_index","msg":".git/index"} {"event":"region_enter","sid":"1234/20230221T081010.667656Z-Ha0f0bee5-P000006c8","thread":"main","repo":1,"nesting":2,"category":"cache_tree","label":"read"} diff --git a/internal/git/trace2/trace.go b/internal/git/trace2/trace.go index 9a80d0253..cc15820e1 100644 --- a/internal/git/trace2/trace.go +++ b/internal/git/trace2/trace.go @@ -13,27 +13,28 @@ import ( type Trace struct { // Thread is the name of the thread of the corresponding event. The default thread name is // "main". A new thread is assigned with a new name. - Thread string + Thread string `json:"thread"` // Name denotes the name of the trace. The node name depends on the event types. Data-type // trace name is the most significant. It can be used to access the accurate data trace node // For example: data:index:refresh/sum_scan - Name string + Name string `json:"name"` // StartTime is the starting time of the trace - StartTime time.Time - // FinishTime is the starting time of the trace - FinishTime time.Time + StartTime time.Time `json:"start_time"` + // FinishTime is the finishing time of the trace + FinishTime time.Time `json:"finish_time"` // Metadata is a map of metadata and data extracted from the event. A data-type trace always // stores its data under "data" key of this map - Metadata map[string]string + Metadata map[string]string `json:"metadata"` // ChildID is the unique ID assigned by the parent process when it spawns a sub-process // The ID of root process is empty. - ChildID string - // Parent points to the parent node of the current trace. The root node's parent is nil - Parent *Trace + ChildID string `json:"child_id,omitempty"` + // Parent points to the parent node of the current trace. The root node's parent is nil. + // Ignore this field when unmarshalling as it causes cyclic errors + Parent *Trace `json:"-"` // Children stores the list of order-significant traces belong to the current trace - Children []*Trace + Children []*Trace `json:"children,omitempty"` // Depth indicates the depth of the trace node - Depth int + Depth int `json:"depth"` } // IsRoot returns true if the current trace is the root of the tree @@ -90,7 +91,8 @@ func (trace *Trace) setName(hints []string) { trace.Name = strings.Join(parts, ":") } -func (trace *Trace) setMetadata(key, value string) { +// SetMetadata sets the metadata for the trace. +func (trace *Trace) SetMetadata(key, value string) { if trace.Metadata == nil { trace.Metadata = map[string]string{} } diff --git a/internal/git/trace2hooks/log_exporter.go b/internal/git/trace2hooks/log_exporter.go new file mode 100644 index 000000000..a714d7fb3 --- /dev/null +++ b/internal/git/trace2hooks/log_exporter.go @@ -0,0 +1,68 @@ +package trace2hooks + +import ( + "context" + "encoding/json" + "fmt" + + "gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2" + "gitlab.com/gitlab-org/gitaly/v16/internal/log" + "golang.org/x/time/rate" +) + +// NewLogExporter initializes LogExporter, which is a hook that uses the parsed +// trace2 events from the manager to export them to the Gitaly log. It's invocations are limited +// by the rateLimiter. The limiter allows maxBurstToken number of events to happen at once and then +// replenishes by maxEventPerSecond. It works on the token bucket algorithm where you have a number +// of tokens in the bucket to start and you can consume them in each call whilst the bucket gets +// refilled at the specified rate. +func NewLogExporter(rl *rate.Limiter, logger log.Logger) *LogExporter { + return &LogExporter{ + rateLimiter: rl, + logger: logger, + } +} + +// LogExporter is a trace2 hook that adds trace2 api event logs to Gitaly's logs. +type LogExporter struct { + logger log.Logger + rateLimiter *rate.Limiter +} + +// Name returns the name of tracing exporter +func (t *LogExporter) Name() string { + return "log_exporter" +} + +// Handle will log the trace in a readable json format in Gitaly's logs. Metadata is also collected +// and additional information is added to the log. It is also rate limited to protect it from overload +// when there are a lot of trace2 events triggered from git operations. +func (t *LogExporter) Handle(rootCtx context.Context, trace *trace2.Trace) error { + if !t.rateLimiter.Allow() { + // When the event is not allowed, return an error to the caller, this may cause traces to be skipped/dropped. + return fmt.Errorf("rate has exceeded current limit") + } + + trace.Walk(rootCtx, func(ctx context.Context, t *trace2.Trace) context.Context { + t.SetMetadata("elapsed_ms", fmt.Sprintf("%d", t.FinishTime.Sub(t.StartTime).Milliseconds())) + + return ctx + }) + + childrenJSON, err := json.Marshal(trace.Children) + if err != nil { + return fmt.Errorf("marshal json: %w", err) + } + escapedChildren := json.RawMessage(childrenJSON) + + t.logger.WithFields(log.Fields{ + "name": trace.Name, + "thread": trace.Thread, + "component": "trace2hooks." + t.Name(), + "start_time": trace.StartTime, + "finish_time": trace.FinishTime, + "metadata": trace.Metadata, + "children": escapedChildren, + }).Info("Git Trace2 API") + return nil +} diff --git a/internal/git/trace2hooks/log_exporter_test.go b/internal/git/trace2hooks/log_exporter_test.go new file mode 100644 index 000000000..6edf998f2 --- /dev/null +++ b/internal/git/trace2hooks/log_exporter_test.go @@ -0,0 +1,190 @@ +package trace2hooks + +import ( + "context" + "encoding/json" + "regexp" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + "gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2" + "gitlab.com/gitlab-org/gitaly/v16/internal/testhelper" + "golang.org/x/time/rate" +) + +func TestLogExporter_Handle(t *testing.T) { + current, err := time.Parse("2006-01-02T15:04:05Z", "2023-01-01T00:00:00Z") + require.NoError(t, err) + endTime := current.Add(7 * time.Second) + exampleTrace := createExampleTrace(current) + + for _, tc := range []struct { + desc string + setup func(*testing.T) (context.Context, *trace2.Trace) + expectedTrace trace2.Trace + }{ + { + desc: "receives trace consisting of root only", + setup: func(t *testing.T) (context.Context, *trace2.Trace) { + ctx := testhelper.Context(t) + return ctx, &trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: current, + FinishTime: endTime, + } + }, + expectedTrace: trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: current, + FinishTime: endTime, + Metadata: map[string]string{"elapsed_ms": "7000"}, + }, + }, + { + desc: "receives a complete trace", + setup: func(t *testing.T) (context.Context, *trace2.Trace) { + ctx := testhelper.Context(t) + return ctx, exampleTrace + }, + expectedTrace: trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: current, + FinishTime: endTime, + Metadata: map[string]string{"elapsed_ms": "7000"}, + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "version", + StartTime: current, + FinishTime: current.Add(1 * time.Second), Metadata: map[string]string{"exe": "2.42.0", "elapsed_ms": "1000"}, + Depth: 1, + }, { + Thread: "main", + Name: "start", + StartTime: current.Add(1 * time.Second), + FinishTime: current.Add(2 * time.Second), + Metadata: map[string]string{"argv": "git fetch origin master", "elapsed_ms": "1000"}, + Depth: 1, + }, { + Thread: "main", + Name: "def_repo", + StartTime: current.Add(2 * time.Second), + FinishTime: current.Add(3 * time.Second), + Metadata: map[string]string{"worktree": "/Users/userx123/Documents/gitlab-development-kit", "elapsed_ms": "1000"}, + Depth: 1, + }, { + Thread: "main", + Name: "index:do_read_index", + StartTime: current.Add(3 * time.Second), + FinishTime: current.Add(6 * time.Second), + Metadata: map[string]string{"elapsed_ms": "3000"}, + Depth: 1, + Children: []*trace2.Trace{ + { + Thread: "main", + ChildID: "0", + Name: "cache_tree:read", + StartTime: current.Add(3 * time.Second), + FinishTime: current.Add(4 * time.Second), + Metadata: map[string]string{"elapsed_ms": "1000"}, + Depth: 2, + }, + { + Thread: "main", + ChildID: "0", + Name: "data:index:read/version", + StartTime: current.Add(4 * time.Second), + FinishTime: current.Add(5 * time.Second), + Metadata: map[string]string{"data": "2", "elapsed_ms": "1000"}, + Depth: 2, + }, + { + Thread: "main", + ChildID: "0", + Name: "data:index:read/cache_nr", + StartTime: current.Add(5 * time.Second), + FinishTime: current.Add(6 * time.Second), + Metadata: map[string]string{ + "elapsed_ms": "1000", + "data": "1500", + }, + Depth: 2, + }, + }, + }, { + Thread: "main", + Name: "submodule:parallel/fetch", + StartTime: current.Add(6 * time.Second), + FinishTime: current.Add(7 * time.Second), + Metadata: map[string]string{"elapsed_ms": "1000"}, + Depth: 1, + }, + }, + }, + }, + } { + t.Run(tc.desc, func(t *testing.T) { + ctx, trace := tc.setup(t) + logger := testhelper.NewLogger(t) + hook := testhelper.AddLoggerHook(logger) + exporter := NewLogExporter(rate.NewLimiter(1, 1), logger) + // execute and assertions + err := exporter.Handle(ctx, trace) + require.NoError(t, err) + logEntry := hook.LastEntry() + + assert.Equal(t, tc.expectedTrace.Thread, logEntry.Data["thread"]) + assert.Equal(t, tc.expectedTrace.Name, logEntry.Data["name"]) + assert.Equal(t, tc.expectedTrace.Metadata, logEntry.Data["metadata"]) + assert.Equal(t, tc.expectedTrace.StartTime, logEntry.Data["start_time"]) + assert.Equal(t, tc.expectedTrace.FinishTime, logEntry.Data["finish_time"]) + var children []*trace2.Trace + childErr := json.Unmarshal(logEntry.Data["children"].(json.RawMessage), &children) + require.NoError(t, childErr) + assert.Equal(t, tc.expectedTrace.Children, children) + }) + } +} + +func TestLogExporter_rateLimitFailureMock(t *testing.T) { + errorMsg := "rate has exceeded current limit" + + for _, tc := range []struct { + desc string + setup func(*testing.T) (context.Context, *trace2.Trace) + expectedError *regexp.Regexp + }{ + { + desc: "rate limit exceeded", + setup: func(t *testing.T) (context.Context, *trace2.Trace) { + ctx := testhelper.Context(t) + return ctx, &trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: time.Time{}, + FinishTime: time.Time{}.Add(1 * time.Second), + } + }, + expectedError: regexp.MustCompile(errorMsg), + }, + } { + t.Run(tc.desc, func(t *testing.T) { + ctx, trace := tc.setup(t) + logger := testhelper.SharedLogger(t) + + rl := rate.NewLimiter(0, 1) // burst limit of 1, refreshing at 0 rps + + exporter := LogExporter{rateLimiter: rl, logger: logger} + err := exporter.Handle(ctx, trace) + require.NoError(t, err) + err = exporter.Handle(ctx, trace) + require.Error(t, err) + require.Regexp(t, tc.expectedError, err) + }) + } +} diff --git a/internal/git/trace2hooks/trace_helper_test.go b/internal/git/trace2hooks/trace_helper_test.go new file mode 100644 index 000000000..267711990 --- /dev/null +++ b/internal/git/trace2hooks/trace_helper_test.go @@ -0,0 +1,101 @@ +package trace2hooks + +import ( + "time" + + "gitlab.com/gitlab-org/gitaly/v16/internal/git/trace2" +) + +func createExampleTrace(startTime time.Time) *trace2.Trace { + // 0s 1s 2s 3s 4s 5s 6s 7s + // root |---->|---->|---->|---->|---->|---->|---->| + // version |---->| | | | | | | + // start | |---->| | | | | | + // def_repo | | |---->| | | | | + // index:do_read_index | | | |---->|---->|---->| | + // cache_tree:read | | | |---->| | | | + // data:index:read/version | | | | |---->| | | + // data:index:read/cache_nr| | | | | |---->| | + // submodule:parallel/fetch| | | | | | |---->| + return connectChildren(&trace2.Trace{ + Thread: "main", + Name: "root", + StartTime: startTime, + FinishTime: startTime.Add(7 * time.Second), + Depth: 0, + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "version", + StartTime: startTime, + FinishTime: startTime.Add(1 * time.Second), Metadata: map[string]string{"exe": "2.42.0"}, + Depth: 1, + }, + { + Thread: "main", + Name: "start", + StartTime: startTime.Add(1 * time.Second), + FinishTime: startTime.Add(2 * time.Second), + Metadata: map[string]string{"argv": "git fetch origin master"}, + Depth: 1, + }, + { + Thread: "main", + Name: "def_repo", + StartTime: startTime.Add(2 * time.Second), + FinishTime: startTime.Add(3 * time.Second), + Metadata: map[string]string{"worktree": "/Users/userx123/Documents/gitlab-development-kit"}, + Depth: 1, + }, + connectChildren(&trace2.Trace{ + Thread: "main", + Name: "index:do_read_index", + StartTime: startTime.Add(3 * time.Second), + FinishTime: startTime.Add(6 * time.Second), + Depth: 1, + Children: []*trace2.Trace{ + { + Thread: "main", + Name: "cache_tree:read", + ChildID: "0", + StartTime: startTime.Add(3 * time.Second), + FinishTime: startTime.Add(4 * time.Second), + Depth: 2, + }, + { + Thread: "main", + ChildID: "0", + Name: "data:index:read/version", + StartTime: startTime.Add(4 * time.Second), + FinishTime: startTime.Add(5 * time.Second), + Metadata: map[string]string{"data": "2"}, + Depth: 2, + }, + { + Thread: "main", + ChildID: "0", + Name: "data:index:read/cache_nr", + StartTime: startTime.Add(5 * time.Second), + FinishTime: startTime.Add(6 * time.Second), + Metadata: map[string]string{"data": "1500"}, + Depth: 2, + }, + }, + }), + { + Thread: "main", + Name: "submodule:parallel/fetch", + StartTime: startTime.Add(6 * time.Second), + FinishTime: startTime.Add(7 * time.Second), + Depth: 1, + }, + }, + }) +} + +func connectChildren(trace *trace2.Trace) *trace2.Trace { + for _, t := range trace.Children { + t.Parent = trace + } + return trace +} diff --git a/internal/git/trace2hooks/tracingexporter_test.go b/internal/git/trace2hooks/tracingexporter_test.go index 062f98a96..0c7ab5a91 100644 --- a/internal/git/trace2hooks/tracingexporter_test.go +++ b/internal/git/trace2hooks/tracingexporter_test.go @@ -20,80 +20,7 @@ func TestTracingExporter_Handle(t *testing.T) { current, err := time.Parse("2006-01-02T15:04:05Z", "2023-01-01T00:00:00Z") require.NoError(t, err) - // 0s 1s 2s 3s 4s 5s 6s 7s - // root |---->|---->|---->|---->|---->|---->|---->| - // version |---->| | | | | | | - // start | |---->| | | | | | - // def_repo | | |---->| | | | | - // index:do_read_index | | | |---->|---->|---->| | - // cache_tree:read | | | |---->| | | | - // data:index:read/version | | | | |---->| | | - // data:index:read/cache_nr| | | | | |---->| | - // submodule:parallel/fetch| | | | | | |---->| - exampleTrace := connectChildren(&trace2.Trace{ - Thread: "main", - Name: "root", - StartTime: current, - FinishTime: current.Add(7 * 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 fetch origin master"}, - }, - { - Thread: "main", - Name: "def_repo", - StartTime: current.Add(2 * time.Second), - FinishTime: current.Add(3 * time.Second), - }, - connectChildren(&trace2.Trace{ - Thread: "main", - Name: "index:do_read_index", - StartTime: current.Add(3 * time.Second), - FinishTime: current.Add(6 * time.Second), - Children: []*trace2.Trace{ - { - Thread: "main", - Name: "cache_tree:read", - ChildID: "0", - StartTime: current.Add(3 * time.Second), - FinishTime: current.Add(4 * time.Second), - }, - { - Thread: "main", - ChildID: "0", - Name: "data:index:read/version", - StartTime: current.Add(4 * time.Second), - FinishTime: current.Add(5 * time.Second), - Metadata: map[string]string{"data": "2"}, - }, - { - Thread: "main", - ChildID: "0", - Name: "data:index:read/cache_nr", - StartTime: current.Add(5 * time.Second), - FinishTime: current.Add(6 * time.Second), - Metadata: map[string]string{"data": "1500"}, - }, - }, - }), - { - Thread: "main", - Name: "submodule:parallel/fetch", - StartTime: current.Add(6 * time.Second), - FinishTime: current.Add(7 * time.Second), - }, - }, - }) + exampleTrace := createExampleTrace(current) for _, tc := range []struct { desc string @@ -136,6 +63,7 @@ func TestTracingExporter_Handle(t *testing.T) { Tags: map[string]string{ "childID": "", "thread": "main", + "exe": "2.42.0", }, }, { @@ -153,8 +81,9 @@ func TestTracingExporter_Handle(t *testing.T) { StartTime: current.Add(2 * time.Second), Duration: 1 * time.Second, Tags: map[string]string{ - "childID": "", - "thread": "main", + "childID": "", + "thread": "main", + "worktree": "/Users/userx123/Documents/gitlab-development-kit", }, }, { @@ -227,10 +156,3 @@ func TestTracingExporter_Handle(t *testing.T) { }) } } - -func connectChildren(trace *trace2.Trace) *trace2.Trace { - for _, t := range trace.Children { - t.Parent = trace - } - return trace -} diff --git a/internal/testhelper/testhelper.go b/internal/testhelper/testhelper.go index 59663b0ab..39f371de3 100644 --- a/internal/testhelper/testhelper.go +++ b/internal/testhelper/testhelper.go @@ -262,6 +262,8 @@ func ContextWithoutCancel(opts ...ContextOpt) context.Context { ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.ExecCommandDirectlyInCgroup, rand.Int()%2 == 0) // Randomly enable newer Git version. ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.GitV243, rand.Int()%2 == 0) + // Disable LogGitTraces + ctx = featureflag.ContextWithFeatureFlag(ctx, featureflag.LogGitTraces, false) for _, opt := range opts { ctx = opt(ctx) -- cgit v1.2.3