From 784af157506250cd39b4b64a1382387053939cd9 Mon Sep 17 00:00:00 2001 From: Alessandro Pagnin Date: Thu, 30 Oct 2025 19:58:01 +0100 Subject: [PATCH 1/4] chore: initial logic to track timing --- router/core/plan_generator.go | 93 ++++++++++++++----- router/core/plan_generator_test.go | 2 +- .../planningbenchmark/benchmark_test.go | 8 +- router/pkg/plan_generator/plan_generator.go | 16 ++-- .../pkg/plan_generator/plan_generator_test.go | 33 ++++++- 5 files changed, 113 insertions(+), 39 deletions(-) diff --git a/router/core/plan_generator.go b/router/core/plan_generator.go index da16b527b7..c5829764c0 100644 --- a/router/core/plan_generator.go +++ b/router/core/plan_generator.go @@ -7,6 +7,7 @@ import ( "fmt" "net/http" "os" + "time" "github.com/wundergraph/cosmo/router/pkg/metric" @@ -53,6 +54,28 @@ type Planner struct { operationValidator *astvalidation.OperationValidator } +type OperationTimes struct { + ParseTime time.Duration + NormalizeTime time.Duration + ValidateTime time.Duration + PostProcessTime time.Duration + PlanTime time.Duration +} + +func (ot *OperationTimes) TotalTime() time.Duration { + return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PostProcessTime + ot.PlanTime +} + +func (ot OperationTimes) Merge(other OperationTimes) OperationTimes { + return OperationTimes{ + ParseTime: ot.ParseTime + other.ParseTime, + NormalizeTime: ot.NormalizeTime + other.NormalizeTime, + ValidateTime: ot.ValidateTime + other.ValidateTime, + PostProcessTime: ot.PostProcessTime + other.PostProcessTime, + PlanTime: ot.PlanTime + other.PlanTime, + } +} + type PlanOutputFormat string const ( @@ -75,57 +98,76 @@ func NewPlanner(planConfiguration *plan.Configuration, definition *ast.Document, } // PlanOperation creates a query plan from an operation file in a pretty-printed text or JSON format -func (pl *Planner) PlanOperation(operationFilePath string, outputFormat PlanOutputFormat) (string, error) { - operation, err := pl.ParseAndPrepareOperation(operationFilePath) +func (pl *Planner) PlanOperation(operationFilePath string, outputFormat PlanOutputFormat) (string, OperationTimes, error) { + operation, opTimes, err := pl.ParseAndPrepareOperation(operationFilePath) if err != nil { - return "", err + return "", OperationTimes{}, err } - rawPlan, err := pl.PlanPreparedOperation(operation) + start := time.Now() + rawPlan, opTimes2, err := pl.PlanPreparedOperation(operation) + opTimes = opTimes.Merge(opTimes2) if err != nil { - return "", fmt.Errorf("failed to plan operation: %w", err) + return "", opTimes, fmt.Errorf("failed to plan operation: %w", err) } + opTimes.PlanTime = time.Since(start) switch outputFormat { case PlanOutputFormatText: - return rawPlan.PrettyPrint(), nil + return rawPlan.PrettyPrint(), opTimes, nil case PlanOutputFormatJSON: marshal, err := json.Marshal(rawPlan) if err != nil { - return "", fmt.Errorf("failed to marshal raw plan: %w", err) + return "", opTimes, fmt.Errorf("failed to marshal raw plan: %w", err) } - return string(marshal), nil + return string(marshal), opTimes, nil } - return "", fmt.Errorf("invalid outputFormat specified: %q", outputFormat) + return "", opTimes, fmt.Errorf("invalid outputFormat specified: %q", outputFormat) } // ParseAndPrepareOperation parses, normalizes and validates the operation -func (pl *Planner) ParseAndPrepareOperation(operationFilePath string) (*ast.Document, error) { +func (pl *Planner) ParseAndPrepareOperation(operationFilePath string) (*ast.Document, OperationTimes, error) { + start := time.Now() operation, err := pl.parseOperation(operationFilePath) + parseTime := time.Since(start) if err != nil { - return nil, &PlannerOperationValidationError{err: err} + return nil, OperationTimes{ParseTime: parseTime}, &PlannerOperationValidationError{err: err} } - return pl.PrepareOperation(operation) + operation, opTimes, err := pl.PrepareOperation(operation) + opTimes.ParseTime = parseTime + if err != nil { + return nil, opTimes, err + } + + return operation, opTimes, nil } // PrepareOperation normalizes and validates the operation -func (pl *Planner) PrepareOperation(operation *ast.Document) (*ast.Document, error) { +func (pl *Planner) PrepareOperation(operation *ast.Document) (*ast.Document, OperationTimes, error) { operationName := findOperationName(operation) if operationName == nil { - return nil, &PlannerOperationValidationError{err: errors.New("operation name not found")} + return nil, OperationTimes{}, &PlannerOperationValidationError{err: errors.New("operation name not found")} } + opTimes := OperationTimes{} + + start := time.Now() if err := pl.normalizeOperation(operation, operationName); err != nil { - return nil, &PlannerOperationValidationError{err: err} + opTimes.NormalizeTime = time.Since(start) + return nil, opTimes, &PlannerOperationValidationError{err: err} } + opTimes.NormalizeTime = time.Since(start) + start = time.Now() if err := pl.validateOperation(operation); err != nil { - return nil, &PlannerOperationValidationError{err: err} + opTimes.ValidateTime = time.Since(start) + return nil, opTimes, &PlannerOperationValidationError{err: err} } + opTimes.ValidateTime = time.Since(start) - return operation, nil + return operation, opTimes, nil } func (pl *Planner) normalizeOperation(operation *ast.Document, operationName []byte) (err error) { @@ -160,7 +202,7 @@ func (pl *Planner) normalizeOperation(operation *ast.Document, operationName []b } // PlanPreparedOperation creates a query plan from a normalized and validated operation -func (pl *Planner) PlanPreparedOperation(operation *ast.Document) (planNode *resolve.FetchTreeQueryPlanNode, err error) { +func (pl *Planner) PlanPreparedOperation(operation *ast.Document) (planNode *resolve.FetchTreeQueryPlanNode, opTimes OperationTimes, err error) { defer func() { if r := recover(); r != nil { err = fmt.Errorf("panic during plan generation: %v", r) @@ -172,25 +214,30 @@ func (pl *Planner) PlanPreparedOperation(operation *ast.Document) (planNode *res operationName := findOperationName(operation) if operationName == nil { - return nil, errors.New("operation name not found") + return nil, opTimes, errors.New("operation name not found") } // create and postprocess the plan + start := time.Now() preparedPlan := pl.planner.Plan(operation, pl.definition, string(operationName), &report, plan.IncludeQueryPlanInResponse()) + opTimes.PlanTime = time.Since(start) if report.HasErrors() { - return nil, errors.New(report.Error()) + return nil, opTimes, errors.New(report.Error()) } + + start = time.Now() post := postprocess.NewProcessor() post.Process(preparedPlan) + opTimes.PostProcessTime = time.Since(start) switch p := preparedPlan.(type) { case *plan.SynchronousResponsePlan: - return p.Response.Fetches.QueryPlan(), nil + return p.Response.Fetches.QueryPlan(), opTimes, nil case *plan.SubscriptionResponsePlan: - return p.Response.Response.Fetches.QueryPlan(), nil + return p.Response.Response.Fetches.QueryPlan(), opTimes, nil } - return &resolve.FetchTreeQueryPlanNode{}, nil + return &resolve.FetchTreeQueryPlanNode{}, opTimes, nil } func (pl *Planner) validateOperation(operation *ast.Document) (err error) { diff --git a/router/core/plan_generator_test.go b/router/core/plan_generator_test.go index a94dbb1aaf..089791aa73 100644 --- a/router/core/plan_generator_test.go +++ b/router/core/plan_generator_test.go @@ -29,7 +29,7 @@ func TestPlanOperationPanic(t *testing.T) { } assert.NotPanics(t, func() { - _, err = planner.PlanPreparedOperation(invalidOperation) + _, _, err = planner.PlanPreparedOperation(invalidOperation) assert.Error(t, err) }) } diff --git a/router/internal/planningbenchmark/benchmark_test.go b/router/internal/planningbenchmark/benchmark_test.go index 45dcf70117..94ad02a08d 100644 --- a/router/internal/planningbenchmark/benchmark_test.go +++ b/router/internal/planningbenchmark/benchmark_test.go @@ -34,11 +34,11 @@ func TestPlanning(t *testing.T) { pl, err := pg.GetPlanner() require.NoError(t, err) - opDoc, err := pl.ParseAndPrepareOperation(cfg.OperationPath) + opDoc, _, err := pl.ParseAndPrepareOperation(cfg.OperationPath) require.NoError(t, err) start := time.Now() - _, err = pl.PlanPreparedOperation(opDoc) + _, _, err = pl.PlanPreparedOperation(opDoc) require.NoError(t, err) t.Logf("Planning completed in %v", time.Since(start)) } @@ -65,12 +65,12 @@ func BenchmarkPlanning(b *testing.B) { for b.Loop() { b.StopTimer() - opDoc, err := pl.ParseAndPrepareOperation(cfg.OperationPath) + opDoc, _, err := pl.ParseAndPrepareOperation(cfg.OperationPath) require.NoError(b, err) b.SetBytes(int64(len(opDoc.Input.RawBytes))) b.StartTimer() - _, err = pl.PlanPreparedOperation(opDoc) + _, _, err = pl.PlanPreparedOperation(opDoc) require.NoError(b, err) } } diff --git a/router/pkg/plan_generator/plan_generator.go b/router/pkg/plan_generator/plan_generator.go index a2668d3bc2..df50e66fa3 100644 --- a/router/pkg/plan_generator/plan_generator.go +++ b/router/pkg/plan_generator/plan_generator.go @@ -42,10 +42,11 @@ type QueryPlanResults struct { } type QueryPlanResult struct { - FileName string `json:"file_name,omitempty"` - Plan string `json:"plan,omitempty"` - Error string `json:"error,omitempty"` - Warning string `json:"warning,omitempty"` + FileName string `json:"file_name,omitempty"` + Plan string `json:"plan,omitempty"` + Error string `json:"error,omitempty"` + Warning string `json:"warning,omitempty"` + Timings core.OperationTimes `json:"timings,omitempty"` } func PlanGenerator(ctx context.Context, cfg QueryPlanConfig) error { @@ -145,10 +146,11 @@ func PlanGenerator(ctx context.Context, cfg QueryPlanConfig) error { queryFilePath := filepath.Join(queriesPath, queryFile.Name()) - outContent, err := planner.PlanOperation(queryFilePath, cfg.OutputFormat) + outContent, opTimes, err := planner.PlanOperation(queryFilePath, cfg.OutputFormat) res := QueryPlanResult{ - FileName: queryFile.Name(), - Plan: outContent, + FileName: queryFile.Name(), + Plan: outContent, + Timings: opTimes, } if err != nil { if _, ok := err.(*core.PlannerOperationValidationError); ok { diff --git a/router/pkg/plan_generator/plan_generator_test.go b/router/pkg/plan_generator/plan_generator_test.go index 4247824b35..2e8e692fdc 100644 --- a/router/pkg/plan_generator/plan_generator_test.go +++ b/router/pkg/plan_generator/plan_generator_test.go @@ -3,7 +3,6 @@ package plan_generator import ( "context" "encoding/json" - "github.com/wundergraph/cosmo/router/core" "os" "path" "path/filepath" @@ -11,6 +10,8 @@ import ( "strings" "testing" + "github.com/wundergraph/cosmo/router/core" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" "go.uber.org/zap" @@ -210,7 +211,15 @@ func TestPlanGenerator(t *testing.T) { assert.NoError(t, err) resultsExpected, err := os.ReadFile(path.Join(getTestDataDir(), "plans", "base", ReportFileName)) assert.NoError(t, err) - assert.Equal(t, string(resultsExpected), string(results)) + resultsStruct := QueryPlanResults{} + json.Unmarshal(results, &resultsStruct) + resultsExpectedStruct := QueryPlanResults{} + json.Unmarshal(resultsExpected, &resultsExpectedStruct) + for i := range resultsStruct.Plans { + assert.Equal(t, resultsStruct.Plans[i].Plan, resultsExpectedStruct.Plans[i].Plan) + assert.Equal(t, resultsStruct.Plans[i].Error, resultsExpectedStruct.Plans[i].Error) + assert.Equal(t, resultsStruct.Plans[i].Warning, resultsExpectedStruct.Plans[i].Warning) + } }) t.Run("will not fail on warnings and results should return the warnings and generate results file", func(t *testing.T) { @@ -241,7 +250,15 @@ func TestPlanGenerator(t *testing.T) { assert.NoError(t, err) resultsExpected, err := os.ReadFile(path.Join(getTestDataDir(), "plans", "base", ReportFileName)) assert.NoError(t, err) - assert.Equal(t, string(resultsExpected), string(results)) + resultsStruct := QueryPlanResults{} + json.Unmarshal(results, &resultsStruct) + resultsExpectedStruct := QueryPlanResults{} + json.Unmarshal(resultsExpected, &resultsExpectedStruct) + for i := range resultsStruct.Plans { + assert.Equal(t, resultsStruct.Plans[i].Plan, resultsExpectedStruct.Plans[i].Plan) + assert.Equal(t, resultsStruct.Plans[i].Error, resultsExpectedStruct.Plans[i].Error) + assert.Equal(t, resultsStruct.Plans[i].Warning, resultsExpectedStruct.Plans[i].Warning) + } }) t.Run("will not fail on warnings and files should have warnings and generate files", func(t *testing.T) { @@ -270,7 +287,15 @@ func TestPlanGenerator(t *testing.T) { assert.NoError(t, err) expected, err := os.ReadFile(path.Join(getTestDataDir(), "plans", "base", filename)) assert.NoError(t, err) - assert.Equal(t, string(expected), string(queryPlan)) + resultsStruct := QueryPlanResults{} + json.Unmarshal(queryPlan, &resultsStruct) + resultsExpectedStruct := QueryPlanResults{} + json.Unmarshal(expected, &resultsExpectedStruct) + for i := range resultsStruct.Plans { + assert.Equal(t, resultsStruct.Plans[i].Plan, resultsExpectedStruct.Plans[i].Plan) + assert.Equal(t, resultsStruct.Plans[i].Error, resultsExpectedStruct.Plans[i].Error) + assert.Equal(t, resultsStruct.Plans[i].Warning, resultsExpectedStruct.Plans[i].Warning) + } }) } }) From 74a46aef057e4bfab46e0725a8579fa932261ef2 Mon Sep 17 00:00:00 2001 From: Alessandro Pagnin Date: Fri, 14 Nov 2025 11:45:31 +0100 Subject: [PATCH 2/4] chore: improve tests and structure --- router/core/plan_generator.go | 16 ++++++++-------- router/pkg/plan_generator/plan_generator_test.go | 2 ++ 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/router/core/plan_generator.go b/router/core/plan_generator.go index c5829764c0..484341d5c7 100644 --- a/router/core/plan_generator.go +++ b/router/core/plan_generator.go @@ -101,16 +101,16 @@ func NewPlanner(planConfiguration *plan.Configuration, definition *ast.Document, func (pl *Planner) PlanOperation(operationFilePath string, outputFormat PlanOutputFormat) (string, OperationTimes, error) { operation, opTimes, err := pl.ParseAndPrepareOperation(operationFilePath) if err != nil { - return "", OperationTimes{}, err + return "", opTimes, err } start := time.Now() rawPlan, opTimes2, err := pl.PlanPreparedOperation(operation) opTimes = opTimes.Merge(opTimes2) + opTimes.PlanTime = time.Since(start) if err != nil { return "", opTimes, fmt.Errorf("failed to plan operation: %w", err) } - opTimes.PlanTime = time.Since(start) switch outputFormat { case PlanOutputFormatText: @@ -154,18 +154,18 @@ func (pl *Planner) PrepareOperation(operation *ast.Document) (*ast.Document, Ope opTimes := OperationTimes{} start := time.Now() - if err := pl.normalizeOperation(operation, operationName); err != nil { - opTimes.NormalizeTime = time.Since(start) + err := pl.normalizeOperation(operation, operationName) + opTimes.NormalizeTime = time.Since(start) + if err != nil { return nil, opTimes, &PlannerOperationValidationError{err: err} } - opTimes.NormalizeTime = time.Since(start) start = time.Now() - if err := pl.validateOperation(operation); err != nil { - opTimes.ValidateTime = time.Since(start) + err = pl.validateOperation(operation) + opTimes.ValidateTime = time.Since(start) + if err != nil { return nil, opTimes, &PlannerOperationValidationError{err: err} } - opTimes.ValidateTime = time.Since(start) return operation, opTimes, nil } diff --git a/router/pkg/plan_generator/plan_generator_test.go b/router/pkg/plan_generator/plan_generator_test.go index 2e8e692fdc..0cadbe3313 100644 --- a/router/pkg/plan_generator/plan_generator_test.go +++ b/router/pkg/plan_generator/plan_generator_test.go @@ -215,6 +215,7 @@ func TestPlanGenerator(t *testing.T) { json.Unmarshal(results, &resultsStruct) resultsExpectedStruct := QueryPlanResults{} json.Unmarshal(resultsExpected, &resultsExpectedStruct) + require.Len(t, resultsStruct.Plans, len(resultsExpectedStruct.Plans)) for i := range resultsStruct.Plans { assert.Equal(t, resultsStruct.Plans[i].Plan, resultsExpectedStruct.Plans[i].Plan) assert.Equal(t, resultsStruct.Plans[i].Error, resultsExpectedStruct.Plans[i].Error) @@ -254,6 +255,7 @@ func TestPlanGenerator(t *testing.T) { json.Unmarshal(results, &resultsStruct) resultsExpectedStruct := QueryPlanResults{} json.Unmarshal(resultsExpected, &resultsExpectedStruct) + require.Len(t, resultsStruct.Plans, len(resultsExpectedStruct.Plans)) for i := range resultsStruct.Plans { assert.Equal(t, resultsStruct.Plans[i].Plan, resultsExpectedStruct.Plans[i].Plan) assert.Equal(t, resultsStruct.Plans[i].Error, resultsExpectedStruct.Plans[i].Error) From 26f51b8aedcd1fdddc6de022c7eaf3f22da782b6 Mon Sep 17 00:00:00 2001 From: Alessandro Pagnin Date: Fri, 14 Nov 2025 11:55:31 +0100 Subject: [PATCH 3/4] chore: fix wrong plan time --- router/core/plan_generator.go | 2 -- 1 file changed, 2 deletions(-) diff --git a/router/core/plan_generator.go b/router/core/plan_generator.go index 484341d5c7..e4b7a16f2c 100644 --- a/router/core/plan_generator.go +++ b/router/core/plan_generator.go @@ -104,10 +104,8 @@ func (pl *Planner) PlanOperation(operationFilePath string, outputFormat PlanOutp return "", opTimes, err } - start := time.Now() rawPlan, opTimes2, err := pl.PlanPreparedOperation(operation) opTimes = opTimes.Merge(opTimes2) - opTimes.PlanTime = time.Since(start) if err != nil { return "", opTimes, fmt.Errorf("failed to plan operation: %w", err) } From d0ac7f38cb43586b6ede047c4c5faac4559e5fa1 Mon Sep 17 00:00:00 2001 From: Alessandro Pagnin Date: Wed, 19 Nov 2025 11:54:41 +0100 Subject: [PATCH 4/4] fix: measure PostProcessTime as part of the PlanTime --- router/core/plan_generator.go | 24 +++++++++++------------- 1 file changed, 11 insertions(+), 13 deletions(-) diff --git a/router/core/plan_generator.go b/router/core/plan_generator.go index e4b7a16f2c..ee50e513b4 100644 --- a/router/core/plan_generator.go +++ b/router/core/plan_generator.go @@ -55,24 +55,22 @@ type Planner struct { } type OperationTimes struct { - ParseTime time.Duration - NormalizeTime time.Duration - ValidateTime time.Duration - PostProcessTime time.Duration - PlanTime time.Duration + ParseTime time.Duration + NormalizeTime time.Duration + ValidateTime time.Duration + PlanTime time.Duration } func (ot *OperationTimes) TotalTime() time.Duration { - return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PostProcessTime + ot.PlanTime + return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PlanTime } func (ot OperationTimes) Merge(other OperationTimes) OperationTimes { return OperationTimes{ - ParseTime: ot.ParseTime + other.ParseTime, - NormalizeTime: ot.NormalizeTime + other.NormalizeTime, - ValidateTime: ot.ValidateTime + other.ValidateTime, - PostProcessTime: ot.PostProcessTime + other.PostProcessTime, - PlanTime: ot.PlanTime + other.PlanTime, + ParseTime: ot.ParseTime + other.ParseTime, + NormalizeTime: ot.NormalizeTime + other.NormalizeTime, + ValidateTime: ot.ValidateTime + other.ValidateTime, + PlanTime: ot.PlanTime + other.PlanTime, } } @@ -223,10 +221,10 @@ func (pl *Planner) PlanPreparedOperation(operation *ast.Document) (planNode *res return nil, opTimes, errors.New(report.Error()) } - start = time.Now() post := postprocess.NewProcessor() post.Process(preparedPlan) - opTimes.PostProcessTime = time.Since(start) + // measure postprocessing time as part of planning time + opTimes.PlanTime = time.Since(start) switch p := preparedPlan.(type) { case *plan.SynchronousResponsePlan: