Skip to content

feat: execution trace gantt chart #2114

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 15 commits into
base: main
Choose a base branch
from
Open
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions executor.go
Original file line number Diff line number Diff line change
@@ -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)
}
}
8 changes: 8 additions & 0 deletions internal/flags/flags.go
Original file line number Diff line number Diff line change
@@ -73,6 +73,8 @@ var (
Offline bool
ClearCache bool
Timeout time.Duration

ExecutionTraceOutput string
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Might it be possible to consider a more generic operation:

# Select one tracer or the other, with default options.
task default --tracer=mermaid
task default --tracer=csv

# Select a tracer and also provide some options, without adding additional CLI parameters.
task default --tracer="mermaid;filename=foo.out"

)

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),
)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think here, the same pattern as other executors should be used (above calls).

if ExecutionTraceOutput != "" {
task.ExecutorWithTracer(ExecutionTraceOutput)(e)
}
}
}
83 changes: 83 additions & 0 deletions internal/tracing/tracing.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,83 @@
package tracing
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here perhaps an interface, and then implementation for the Mermaid tracer.

type Tracer interface {
    Start(task)
    Stop()
    ...
}


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
}
52 changes: 52 additions & 0 deletions internal/tracing/tracing_test.go
Original file line number Diff line number Diff line change
@@ -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))
}
18 changes: 16 additions & 2 deletions task.go
Original file line number Diff line number Diff line change
@@ -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
})
}
40 changes: 40 additions & 0 deletions task_test.go
Original file line number Diff line number Diff line change
@@ -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()

1 change: 1 addition & 0 deletions website/versioned_docs/version-latest/reference/cli.mdx
Original file line number Diff line number Diff line change
@@ -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