diff --git a/executor.go b/executor.go index 6b8d991fde..35be14c5ef 100644 --- a/executor.go +++ b/executor.go @@ -12,6 +12,7 @@ import ( "github.com/go-task/task/v3/internal/logger" "github.com/go-task/task/v3/internal/output" "github.com/go-task/task/v3/internal/sort" + "github.com/go-task/task/v3/internal/tracing" "github.com/go-task/task/v3/taskfile/ast" ) @@ -65,6 +66,8 @@ type ( mkdirMutexMap map[string]*sync.Mutex executionHashes map[string]context.Context executionHashesMutex sync.Mutex + + tracer *tracing.Tracer } TempDir struct { Remote string @@ -317,3 +320,10 @@ func ExecutorWithVersionCheck(enableVersionCheck bool) ExecutorOption { e.EnableVersionCheck = enableVersionCheck } } + +// ExecutorWithTracer configures execution tracing +func ExecutorWithTracer(outFile string) ExecutorOption { + return func(e *Executor) { + e.tracer = tracing.NewTracer(outFile) + } +} diff --git a/internal/flags/flags.go b/internal/flags/flags.go index 7d437537de..f3b96f6685 100644 --- a/internal/flags/flags.go +++ b/internal/flags/flags.go @@ -73,6 +73,8 @@ var ( Offline bool ClearCache bool Timeout time.Duration + + ExecutionTraceOutput string ) func init() { @@ -133,6 +135,8 @@ func init() { pflag.BoolVar(&ClearCache, "clear-cache", false, "Clear the remote cache.") } + pflag.StringVar(&ExecutionTraceOutput, "execution-trace-output", "", "When supplied, generates a Mermaid Gantt chart of each task's invocation. Useful to visualize highly parallel execution.") + pflag.Parse() } @@ -221,5 +225,9 @@ func WithExecutorOptions() task.ExecutorOption { task.ExecutorWithTaskSorter(sorter), task.ExecutorWithVersionCheck(true), ) + + if ExecutionTraceOutput != "" { + task.ExecutorWithTracer(ExecutionTraceOutput)(e) + } } } diff --git a/internal/tracing/tracing.go b/internal/tracing/tracing.go new file mode 100644 index 0000000000..693fe13529 --- /dev/null +++ b/internal/tracing/tracing.go @@ -0,0 +1,83 @@ +package tracing + +import ( + "fmt" + "os" + "strings" + "sync" + "time" +) + +type Tracer struct { + mu sync.Mutex + spans []*Span + outFile string + + timeFn func() time.Time +} + +func NewTracer(outFile string) *Tracer { + return &Tracer{ + outFile: outFile, + } +} + +type Span struct { + parent *Tracer + name string + startedAt time.Time + endedAt time.Time +} + +func (t *Tracer) Start(name string) *Span { + t.mu.Lock() + defer t.mu.Unlock() + + if t.timeFn == nil { + t.timeFn = time.Now + } + + result := &Span{ + parent: t, + name: name, + startedAt: t.timeFn(), + } + t.spans = append(t.spans, result) + return result +} + +func (s *Span) Stop() { + s.parent.mu.Lock() + defer s.parent.mu.Unlock() + + s.endedAt = s.parent.timeFn() +} + +func (t *Tracer) WriteOutput() error { + t.mu.Lock() + defer t.mu.Unlock() + + if t.outFile == "" { + return nil + } + return os.WriteFile(t.outFile, []byte(t.toMermaidOutput()), 0o644) +} + +func (t *Tracer) toMermaidOutput() string { + out := `gantt + title Task Execution Timeline + dateFormat YYYY-MM-DD HH:mm:ss.SSS + axisFormat %X +` + dateFormat := "2006-01-02 15:04:05.000" + for _, span := range t.spans { + if span.endedAt.IsZero() { + continue + } + name := strings.Replace(span.name, ":", "|", -1) + duration := span.endedAt.Sub(span.startedAt).Truncate(time.Millisecond * 100) + out += fmt.Sprintf(" %s [%v] :done, %s, %s\n", name, duration, span.startedAt.Format(dateFormat), span.endedAt.Format(dateFormat)) + } + + return out +} diff --git a/internal/tracing/tracing_test.go b/internal/tracing/tracing_test.go new file mode 100644 index 0000000000..a6404d3bc3 --- /dev/null +++ b/internal/tracing/tracing_test.go @@ -0,0 +1,52 @@ +package tracing + +import ( + "os" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func TestTracer_Start(t *testing.T) { + t.Parallel() + tracer := NewTracer(t.TempDir() + "/tracing.txt") + + currentTime, err := time.Parse(time.DateTime, "2025-01-02 15:42:23") + require.NoError(t, err) + tracer.timeFn = func() time.Time { + return currentTime + } + + task1 := tracer.Start("task one") + currentTime = currentTime.Add(time.Second) + + // special chars handling: will be replaced with "namespace|task two" in the output + task2 := tracer.Start("namespace:task two") + tracer.Start("task three - did not finish, should not show up in end result") + currentTime = currentTime.Add(time.Second * 2) + + task1.Stop() + currentTime = currentTime.Add(time.Second * 3) + task2.Stop() + + // very short tasks should still show up as a point in timeline + tracer.Start("very short task").Stop() + + r := require.New(t) + r.NoError(tracer.WriteOutput()) + + contents, err := os.ReadFile(tracer.outFile) + r.NoError(err) + + expectedContents := `gantt + title Task Execution Timeline + dateFormat YYYY-MM-DD HH:mm:ss.SSS + axisFormat %X + task one [3s] :done, 2025-01-02 15:42:23.000, 2025-01-02 15:42:26.000 + namespace|task two [5s] :done, 2025-01-02 15:42:24.000, 2025-01-02 15:42:29.000 + very short task [0s] :done, 2025-01-02 15:42:29.000, 2025-01-02 15:42:29.000 +` + + r.Equal(expectedContents, string(contents)) +} diff --git a/task.go b/task.go index 8d54a065f5..b74931b4bd 100644 --- a/task.go +++ b/task.go @@ -39,6 +39,16 @@ type MatchingTask struct { // Run runs Task func (e *Executor) Run(ctx context.Context, calls ...*Call) error { + defer func() { + if e.tracer == nil { + return + } + err := e.tracer.WriteOutput() + if err != nil { + e.Logger.VerboseErrf(logger.Magenta, "failed to write execution trace: %v\n", err) + } + }() + // check if given tasks exist for _, call := range calls { task, err := e.GetTask(call) @@ -151,10 +161,14 @@ func (e *Executor) RunTask(ctx context.Context, call *Call) error { defer release() return e.startExecution(ctx, t, func(ctx context.Context) error { - e.Logger.VerboseErrf(logger.Magenta, "task: %q started\n", call.Task) + e.Logger.VerboseErrf(logger.Magenta, "task: %q started\n", t.Name()) if err := e.runDeps(ctx, t); err != nil { return err } + if e.tracer != nil { + span := e.tracer.Start(t.Name()) + defer span.Stop() + } skipFingerprinting := e.ForceAll || (!call.Indirect && e.Force) if !skipFingerprinting { @@ -236,7 +250,7 @@ func (e *Executor) RunTask(ctx context.Context, call *Call) error { return &errors.TaskRunError{TaskName: t.Task, Err: err} } } - e.Logger.VerboseErrf(logger.Magenta, "task: %q finished\n", call.Task) + e.Logger.VerboseErrf(logger.Magenta, "task: %q finished\n", t.Name()) return nil }) } diff --git a/task_test.go b/task_test.go index 0a2c982122..e7ad472d7d 100644 --- a/task_test.go +++ b/task_test.go @@ -1074,6 +1074,46 @@ func TestTaskVersion(t *testing.T) { } } +func TestTraceOutput(t *testing.T) { + t.Parallel() + + tests := []struct { + inputDir string + task string + }{ + { + inputDir: "testdata/concurrency", + task: "default", + }, + { + // should produce tracing results even if task execution fails + inputDir: "testdata/exit_code", + task: "exit-one", + }, + } + + for _, tt := range tests { + t.Run("should produce trace output for "+tt.inputDir+"-"+tt.task, func(t *testing.T) { + t.Parallel() + + outFile := t.TempDir() + "/tracing-gantt.out" + + e := task.NewExecutor( + task.ExecutorWithDir(tt.inputDir), + task.ExecutorWithTracer(outFile), + ) + r := require.New(t) + r.NoError(e.Setup()) + _ = e.Run(context.Background(), &task.Call{Task: tt.task}) + + contents, err := os.ReadFile(outFile) + r.NoError(err) + + r.Contains(string(contents), `gantt`) + }) + } +} + func TestTaskIgnoreErrors(t *testing.T) { t.Parallel() diff --git a/website/versioned_docs/version-latest/reference/cli.mdx b/website/versioned_docs/version-latest/reference/cli.mdx index 4afe84b836..a163fa75a1 100644 --- a/website/versioned_docs/version-latest/reference/cli.mdx +++ b/website/versioned_docs/version-latest/reference/cli.mdx @@ -49,6 +49,7 @@ If `--` is given, all remaining arguments will be assigned to a special | `-v` | `--verbose` | `bool` | `false` | Enables verbose mode. | | | `--version` | `bool` | `false` | Show Task version. | | `-w` | `--watch` | `bool` | `false` | Enables watch of the given task. +| | `--execution-trace-output` | `string` | | Execution trace output file name. When supplied, generates a text file in Mermaid Gantt format, containing name and timing of each executed task. Useful to visualize highly parallel execution. | ## Exit Codes