feat: expose timing of planning in the report #2312
Conversation
WalkthroughInstruments the planning pipeline with per-operation timing via a new public Changes
Estimated code review effort🎯 3 (Moderate) | ⏱️ ~25 minutes
Possibly related PRs
Pre-merge checks and finishing touches❌ Failed checks (1 warning)
✅ Passed checks (2 passed)
✨ Finishing touches
Comment |
Router-nonroot image scan passed✅ No security vulnerabilities found in image: |
|
This PR was marked stale due to lack of activity. It will be closed in 14 days. |
alepane21
changed the title
…ry-planner-regression-ci-aware-of-query-plan-timings
alepane21
requested review from
Noroth,
StarpTech,
devsergiy,
endigma and
jensneuse
as code owners
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (5)
router/core/plan_generator.go (2)
57-77: OperationTimes struct and helpers are sound; consider value receiver for TotalTimeThe shape of
OperationTimesandMergeis clear and composable. SinceOperationTimesis small and immutable in practice,TotalTimecould use a value receiver for consistency withMergeand to avoid accidental nil-pointer calls on*OperationTimes. This is optional and non‑blocking.-func (ot *OperationTimes) TotalTime() time.Duration { - return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PostProcessTime + ot.PlanTime -} +func (ot OperationTimes) TotalTime() time.Duration { + return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PostProcessTime + ot.PlanTime +}
148-171: Simplify timing capture in PrepareOperation to avoid duplicated assignments
NormalizeTimeandValidateTimeare each assigned twice (once in the error branch and once after theif). This is correct but a bit noisy and easy to get wrong on future edits. You can measure once, then branch on the error:- opTimes := OperationTimes{} - - start := time.Now() - if err := pl.normalizeOperation(operation, operationName); err != nil { - 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 { - opTimes.ValidateTime = time.Since(start) - return nil, opTimes, &PlannerOperationValidationError{err: err} - } - opTimes.ValidateTime = time.Since(start) + opTimes := OperationTimes{} + + start := time.Now() + err := pl.normalizeOperation(operation, operationName) + opTimes.NormalizeTime = time.Since(start) + if err != nil { + return nil, opTimes, &PlannerOperationValidationError{err: err} + } + + start = time.Now() + err = pl.validateOperation(operation) + opTimes.ValidateTime = time.Since(start) + if err != nil { + return nil, opTimes, &PlannerOperationValidationError{err: err} + }Semantics stay the same, but the timing code is easier to follow and less error‑prone.
router/pkg/plan_generator/plan_generator_test.go (3)
214-222: Check json.Unmarshal errors and lengths when comparing results vs expectedThe switch from raw string equality to JSON struct comparison is the right move now that
Timingsadds extra fields. However, the current code ignoresjson.Unmarshalerrors and does not assert thatresultsStruct.PlansandresultsExpectedStruct.Planshave the same length, which can let malformed JSON or mismatched plan counts slip through silently.- resultsStruct := QueryPlanResults{} - json.Unmarshal(results, &resultsStruct) - resultsExpectedStruct := QueryPlanResults{} - json.Unmarshal(resultsExpected, &resultsExpectedStruct) - for i := range resultsStruct.Plans { + var resultsStruct QueryPlanResults + require.NoError(t, json.Unmarshal(results, &resultsStruct)) + var resultsExpectedStruct QueryPlanResults + require.NoError(t, 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) assert.Equal(t, resultsStruct.Plans[i].Warning, resultsExpectedStruct.Plans[i].Warning) }(Use
requirehere since malformed JSON should fail the test immediately.)
253-261: Apply the same JSON error/length checks in warning/report testSame pattern as above: unmarshal errors and plan count mismatches should fail the test, not silently pass.
- resultsStruct := QueryPlanResults{} - json.Unmarshal(results, &resultsStruct) - resultsExpectedStruct := QueryPlanResults{} - json.Unmarshal(resultsExpected, &resultsExpectedStruct) - for i := range resultsStruct.Plans { + var resultsStruct QueryPlanResults + require.NoError(t, json.Unmarshal(results, &resultsStruct)) + var resultsExpectedStruct QueryPlanResults + require.NoError(t, 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) assert.Equal(t, resultsStruct.Plans[i].Warning, resultsExpectedStruct.Plans[i].Warning) }
290-298: Also harden per-file JSON comparison in OutputFiles + warnings testSame concern: unmarshal errors are ignored, and slice lengths are not checked. Tighten this to avoid tests silently succeeding on malformed output.
- resultsStruct := QueryPlanResults{} - json.Unmarshal(queryPlan, &resultsStruct) - resultsExpectedStruct := QueryPlanResults{} - json.Unmarshal(expected, &resultsExpectedStruct) - for i := range resultsStruct.Plans { + var resultsStruct QueryPlanResults + require.NoError(t, json.Unmarshal(queryPlan, &resultsStruct)) + var resultsExpectedStruct QueryPlanResults + require.NoError(t, json.Unmarshal(expected, &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) assert.Equal(t, resultsStruct.Plans[i].Warning, resultsExpectedStruct.Plans[i].Warning) }
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (5)
router/core/plan_generator.go(5 hunks)router/core/plan_generator_test.go(1 hunks)router/internal/planningbenchmark/benchmark_test.go(2 hunks)router/pkg/plan_generator/plan_generator.go(2 hunks)router/pkg/plan_generator/plan_generator_test.go(4 hunks)
🧰 Additional context used
🧠 Learnings (5)
📚 Learning: 2025-10-01T20:39:16.113Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2252
File: router-tests/telemetry/telemetry_test.go:9684-9693
Timestamp: 2025-10-01T20:39:16.113Z
Learning: Repo preference: In router-tests/telemetry/telemetry_test.go, keep strict > 0 assertions for request.operation.*Time (parsingTime, normalizationTime, validationTime, planningTime) in telemetry-related tests; do not relax to >= 0 unless CI flakiness is observed.
Applied to files:
router/pkg/plan_generator/plan_generator.gorouter/internal/planningbenchmark/benchmark_test.gorouter/core/plan_generator.gorouter/pkg/plan_generator/plan_generator_test.gorouter/core/plan_generator_test.go
📚 Learning: 2025-08-14T16:47:03.744Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2137
File: router/pkg/pubsub/redis/adapter.go:114-116
Timestamp: 2025-08-14T16:47:03.744Z
Learning: In the Cosmo router codebase, EventMetricStore fields are never nil - the system uses the null object pattern with NewNoopEventMetricStore() when metrics are disabled, eliminating the need for nil checks before calling EventMetricStore methods.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-09-24T12:54:00.765Z
Learnt from: endigma
Repo: wundergraph/cosmo PR: 2222
File: router-tests/websocket_test.go:2238-2302
Timestamp: 2025-09-24T12:54:00.765Z
Learning: The wundergraph/cosmo project uses Go 1.25 (Go 1.23+ minimum), so fmt.Appendf and other newer Go standard library functions are available and can be used without compatibility concerns.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-26T17:19:28.178Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2167
File: router/internal/expr/retry_context.go:3-10
Timestamp: 2025-08-26T17:19:28.178Z
Learning: In the Cosmo router codebase, prefer using netErr.Timeout() checks over explicit context.DeadlineExceeded checks for timeout detection in retry logic, as Go's networking stack typically wraps context deadline exceeded errors in proper net.Error implementations.
Applied to files:
router/core/plan_generator.gorouter/pkg/plan_generator/plan_generator_test.go
📚 Learning: 2025-08-20T22:13:25.222Z
Learnt from: StarpTech
Repo: wundergraph/cosmo PR: 2157
File: router-tests/go.mod:16-16
Timestamp: 2025-08-20T22:13:25.222Z
Learning: github.com/mark3labs/mcp-go v0.38.0 has regressions and should not be used in the wundergraph/cosmo project. v0.36.0 is the stable version that should be used across router-tests and other modules.
Applied to files:
router/pkg/plan_generator/plan_generator_test.go
🧬 Code graph analysis (2)
router/pkg/plan_generator/plan_generator.go (1)
router/core/plan_generator.go (1)
OperationTimes(57-63)
router/pkg/plan_generator/plan_generator_test.go (1)
router/pkg/plan_generator/plan_generator.go (1)
QueryPlanResults(39-42)
🔇 Additional comments (8)
router/core/plan_generator.go (1)
205-241: PlanPreparedOperation timing layout looks consistentThe separation between
PlanTime(planner call) andPostProcessTimeis clear, and error/ panic paths correctly propagate any accumulatedopTimeswithout panicking the caller. This aligns well with the timing model introduced inOperationTimes.router/pkg/plan_generator/plan_generator_test.go (2)
13-14: Importing core for PlanOutputFormat is appropriateUsing
core.PlanOutputFormat*in tests keeps them aligned with the core API and avoids duplicating constants.
341-373: OutputFormat tests correctly distinguish JSON vs text outputUsing
core.PlanOutputFormatJSONandcore.PlanOutputFormatTextin these tests verifies both raw JSON mode and textual plan mode:
- JSON mode: content is either JSON or a
Warning:prefix.- Text mode: files keep
.graphqlsuffix and content is non‑JSON textual plans or warnings.This matches the intended semantics of the new
OutputFormatparameter.Also applies to: 375-405
router/core/plan_generator_test.go (1)
31-33: Test correctly updated for new PlanPreparedOperation signatureCapturing the extra
OperationTimesreturn value with_and continuing to assert onerrkeeps the panic‑handling behavior test intact while aligning with the new(planNode, OperationTimes, error)signature.router/internal/planningbenchmark/benchmark_test.go (2)
39-45: Benchmark test adapts correctly to new ParseAndPrepareOperation/PlanPreparedOperation signaturesUsing
_to ignore the newOperationTimeswhile preserving existing error checks and timing log (time.Since(start)) is correct and non‑breaking.
70-79: Benchmark loop correctly ignores timings while using new signaturesThe benchmark now calls
ParseAndPrepareOperationandPlanPreparedOperationwith the additional return value ignored. The core benchmarking logic (alloc reporting, bytes measurement, error checking) remains intact.router/pkg/plan_generator/plan_generator.go (2)
45-50: Adding Timings to QueryPlanResult is a clean extensionAdding
Timings core.OperationTimeswithomitemptycleanly exposes per‑operation timings to consumers of the JSON report without breaking existing fields. This matches the PR’s stated objective.
149-154: Correctly propagating opTimes into QueryPlanResultCapturing
opTimesfromplanner.PlanOperationand assigning it toQueryPlanResult.Timingsensures timing data is available regardless of whether the plan is written to individual files or the aggregate report. OncePlanOperationis adjusted to preserve timings on validation errors, this will give complete coverage of operation timings for both success and warning/error entries.
There was a problem hiding this comment.
Actionable comments posted: 0
♻️ Duplicate comments (1)
router/core/plan_generator.go (1)
107-110: Fix PlanTime double counting.The outer timing wrapper at lines 107-110 overwrites
PlanTimewith the total duration ofPlanPreparedOperation, which already measuredPlanTimeandPostProcessTimeseparately. This causesTotalTime()to double-countPostProcessTime.Remove the outer timing wrapper and rely solely on the timing measurements inside
PlanPreparedOperation.Apply this diff:
- 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) }
🧹 Nitpick comments (1)
router/core/plan_generator.go (1)
65-67: Consider value receiver for consistency.
TotalTime()uses a pointer receiver but doesn't mutate state. For consistency with the value receiver used inMerge()and to avoid unnecessary pointer dereferences, consider using a value receiver.Apply this diff:
-func (ot *OperationTimes) TotalTime() time.Duration { +func (ot OperationTimes) TotalTime() time.Duration { return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PostProcessTime + ot.PlanTime }
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (2)
router/core/plan_generator.go(5 hunks)router/pkg/plan_generator/plan_generator_test.go(4 hunks)
🚧 Files skipped from review as they are similar to previous changes (1)
- router/pkg/plan_generator/plan_generator_test.go
🧰 Additional context used
🧠 Learnings (4)
📚 Learning: 2025-10-01T20:39:16.113Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2252
File: router-tests/telemetry/telemetry_test.go:9684-9693
Timestamp: 2025-10-01T20:39:16.113Z
Learning: Repo preference: In router-tests/telemetry/telemetry_test.go, keep strict > 0 assertions for request.operation.*Time (parsingTime, normalizationTime, validationTime, planningTime) in telemetry-related tests; do not relax to >= 0 unless CI flakiness is observed.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-14T16:47:03.744Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2137
File: router/pkg/pubsub/redis/adapter.go:114-116
Timestamp: 2025-08-14T16:47:03.744Z
Learning: In the Cosmo router codebase, EventMetricStore fields are never nil - the system uses the null object pattern with NewNoopEventMetricStore() when metrics are disabled, eliminating the need for nil checks before calling EventMetricStore methods.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-09-24T12:54:00.765Z
Learnt from: endigma
Repo: wundergraph/cosmo PR: 2222
File: router-tests/websocket_test.go:2238-2302
Timestamp: 2025-09-24T12:54:00.765Z
Learning: The wundergraph/cosmo project uses Go 1.25 (Go 1.23+ minimum), so fmt.Appendf and other newer Go standard library functions are available and can be used without compatibility concerns.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-26T17:19:28.178Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2167
File: router/internal/expr/retry_context.go:3-10
Timestamp: 2025-08-26T17:19:28.178Z
Learning: In the Cosmo router codebase, prefer using netErr.Timeout() checks over explicit context.DeadlineExceeded checks for timeout detection in retry logic, as Go's networking stack typically wraps context deadline exceeded errors in proper net.Error implementations.
Applied to files:
router/core/plan_generator.go
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (9)
- GitHub Check: build-router
- GitHub Check: build_push_image (nonroot)
- GitHub Check: build_push_image
- GitHub Check: image_scan
- GitHub Check: build_test
- GitHub Check: integration_test (./. ./fuzzquery ./lifecycle ./modules)
- GitHub Check: image_scan (nonroot)
- GitHub Check: Analyze (javascript-typescript)
- GitHub Check: Analyze (go)
🔇 Additional comments (3)
router/core/plan_generator.go (3)
130-145: LGTM! Timing preserved on error paths.The implementation correctly measures parse time and preserves collected timings on both parse and prepare errors, which enables tracking even for operations that fail validation.
148-171: LGTM! Clean phase-by-phase timing.The function correctly measures normalization and validation times separately, and preserves accumulated timings on error paths. The early return for missing operation names appropriately returns an empty
OperationTimessince no work has been performed yet.
205-241: LGTM! Accurate plan and post-process timing.The function correctly measures planning and post-processing as separate phases and preserves timing information through all error and success paths. The distinction between
PlanTimeandPostProcessTimeenables fine-grained performance analysis.
…i-aware-of-query-plan-timings
There was a problem hiding this comment.
Actionable comments posted: 0
🧹 Nitpick comments (1)
router/core/plan_generator.go (1)
57-77: LGTM! Clean timing instrumentation design.The
OperationTimesstruct and its helper methods are well-structured for capturing and aggregating per-phase durations. TheMerge()method correctly combines non-overlapping timings from different pipeline stages, andTotalTime()provides a convenient aggregate.Optionally, consider adding doc comments to the exported type and methods for discoverability:
+// OperationTimes captures timing measurements for each phase of GraphQL operation planning. type OperationTimes struct { ParseTime time.Duration NormalizeTime time.Duration ValidateTime time.Duration PostProcessTime time.Duration PlanTime time.Duration } +// TotalTime returns the sum of all recorded phase durations. func (ot *OperationTimes) TotalTime() time.Duration { return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PostProcessTime + ot.PlanTime } +// Merge combines timing data from another OperationTimes by summing corresponding fields. 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, } }
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (1)
router/core/plan_generator.go(5 hunks)
🧰 Additional context used
🧠 Learnings (4)
📚 Learning: 2025-10-01T20:39:16.113Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2252
File: router-tests/telemetry/telemetry_test.go:9684-9693
Timestamp: 2025-10-01T20:39:16.113Z
Learning: Repo preference: In router-tests/telemetry/telemetry_test.go, keep strict > 0 assertions for request.operation.*Time (parsingTime, normalizationTime, validationTime, planningTime) in telemetry-related tests; do not relax to >= 0 unless CI flakiness is observed.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-14T16:47:03.744Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2137
File: router/pkg/pubsub/redis/adapter.go:114-116
Timestamp: 2025-08-14T16:47:03.744Z
Learning: In the Cosmo router codebase, EventMetricStore fields are never nil - the system uses the null object pattern with NewNoopEventMetricStore() when metrics are disabled, eliminating the need for nil checks before calling EventMetricStore methods.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-09-24T12:54:00.765Z
Learnt from: endigma
Repo: wundergraph/cosmo PR: 2222
File: router-tests/websocket_test.go:2238-2302
Timestamp: 2025-09-24T12:54:00.765Z
Learning: The wundergraph/cosmo project uses Go 1.25 (Go 1.23+ minimum), so fmt.Appendf and other newer Go standard library functions are available and can be used without compatibility concerns.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-26T17:19:28.178Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2167
File: router/internal/expr/retry_context.go:3-10
Timestamp: 2025-08-26T17:19:28.178Z
Learning: In the Cosmo router codebase, prefer using netErr.Timeout() checks over explicit context.DeadlineExceeded checks for timeout detection in retry logic, as Go's networking stack typically wraps context deadline exceeded errors in proper net.Error implementations.
Applied to files:
router/core/plan_generator.go
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (5)
- GitHub Check: build_push_image
- GitHub Check: build_push_image (nonroot)
- GitHub Check: integration_test (./. ./fuzzquery ./lifecycle ./modules)
- GitHub Check: build_test
- GitHub Check: Analyze (go)
🔇 Additional comments (4)
router/core/plan_generator.go (4)
101-125: LGTM! Timing aggregation is correct.The function properly merges timings from the parse/prepare and plan phases, and all error paths now preserve the accumulated
opTimes. The previous double-counting issue (outer wrapper overwritingPlanTime) has been correctly resolved.
128-143: LGTM! Parse timing correctly captured and propagated.The function accurately measures parse time and merges it with downstream normalization and validation timings from
PrepareOperation. Both error paths correctly preserve the timing data collected up to the point of failure.
146-169: LGTM! Normalization and validation timing instrumentation is sound.The function correctly measures and records both normalization and validation durations, and all error paths preserve the accumulated timing state. The early return for a missing operation name appropriately returns an empty
OperationTimes{}since no timed work has occurred.
203-239: LGTM! Plan and postprocess timings are accurately instrumented.The function correctly measures planning and post-processing as separate phases and returns the accumulated
opTimeson all code paths, including errors. The timing measurements are appropriately placed to capture the actual work performed by the planner and postprocessor.
…i-aware-of-query-plan-timings
…i-aware-of-query-plan-timings
…i-aware-of-query-plan-timings
There was a problem hiding this comment.
Actionable comments posted: 0
🧹 Nitpick comments (2)
router/core/plan_generator.go (2)
10-75: OperationTimes layout and helpers look good; consider value receiver for TotalTimeThe
OperationTimesstruct andMergehelper provide a clear, non-allocating way to aggregate phase timings and match the intended parse/normalize/validate/plan breakdown. One small polish:TotalTimedoesn’t mutate the receiver, so you could switch it to a value receiver for consistency withMergeand to avoid any (unlikely) nil-pointer surprises:-func (ot *OperationTimes) TotalTime() time.Duration { +func (ot OperationTimes) TotalTime() time.Duration { return ot.ParseTime + ot.NormalizeTime + ot.ValidateTime + ot.PlanTime }This is purely stylistic; current behavior is correct.
201-237: PlanPreparedOperation timing behavior is correct; minor readability tweak possible
PlanPreparedOperationnow:
- Returns
opTimeson all paths (includingoperation name not foundandreport.HasErrors()).- Measures
PlanTimefor planner-only failures (assignment before theHasErrorscheck).- On success, includes postprocessing in
PlanTimeby measuring from the samestartthroughpost.Process, without any outer wrapper inPlanOperation, so there’s no double-counting.Functionally this is correct and matches the comment about including postprocessing in planning time. If you want to make the control flow slightly clearer, you could assign
PlanTimeonly in the error and success branches, e.g.:- 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, opTimes, errors.New(report.Error()) - } - - post := postprocess.NewProcessor() - post.Process(preparedPlan) - // measure postprocessing time as part of planning time - opTimes.PlanTime = time.Since(start) + start := time.Now() + preparedPlan := pl.planner.Plan(operation, pl.definition, string(operationName), &report, plan.IncludeQueryPlanInResponse()) + if report.HasErrors() { + opTimes.PlanTime = time.Since(start) + return nil, opTimes, errors.New(report.Error()) + } + + post := postprocess.NewProcessor() + post.Process(preparedPlan) + // measure postprocessing time as part of planning time + opTimes.PlanTime = time.Since(start)But this is a clarity improvement only; the current implementation is logically correct.
📜 Review details
Configuration used: CodeRabbit UI
Review profile: CHILL
Plan: Pro
📒 Files selected for processing (1)
router/core/plan_generator.go(5 hunks)
🧰 Additional context used
🧠 Learnings (4)
📚 Learning: 2025-10-01T20:39:16.113Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2252
File: router-tests/telemetry/telemetry_test.go:9684-9693
Timestamp: 2025-10-01T20:39:16.113Z
Learning: Repo preference: In router-tests/telemetry/telemetry_test.go, keep strict > 0 assertions for request.operation.*Time (parsingTime, normalizationTime, validationTime, planningTime) in telemetry-related tests; do not relax to >= 0 unless CI flakiness is observed.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-14T16:47:03.744Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2137
File: router/pkg/pubsub/redis/adapter.go:114-116
Timestamp: 2025-08-14T16:47:03.744Z
Learning: In the Cosmo router codebase, EventMetricStore fields are never nil - the system uses the null object pattern with NewNoopEventMetricStore() when metrics are disabled, eliminating the need for nil checks before calling EventMetricStore methods.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-09-24T12:54:00.765Z
Learnt from: endigma
Repo: wundergraph/cosmo PR: 2222
File: router-tests/websocket_test.go:2238-2302
Timestamp: 2025-09-24T12:54:00.765Z
Learning: The wundergraph/cosmo project uses Go 1.25 (Go 1.23+ minimum), so fmt.Appendf and other newer Go standard library functions are available and can be used without compatibility concerns.
Applied to files:
router/core/plan_generator.go
📚 Learning: 2025-08-26T17:19:28.178Z
Learnt from: SkArchon
Repo: wundergraph/cosmo PR: 2167
File: router/internal/expr/retry_context.go:3-10
Timestamp: 2025-08-26T17:19:28.178Z
Learning: In the Cosmo router codebase, prefer using netErr.Timeout() checks over explicit context.DeadlineExceeded checks for timeout detection in retry logic, as Go's networking stack typically wraps context deadline exceeded errors in proper net.Error implementations.
Applied to files:
router/core/plan_generator.go
⏰ Context from checks skipped due to timeout of 90000ms. You can increase the timeout in your CodeRabbit configuration to a maximum of 15 minutes (900000ms). (10)
- GitHub Check: check-labels-and-engine-changes
- GitHub Check: image_scan (nonroot)
- GitHub Check: build_push_image
- GitHub Check: image_scan
- GitHub Check: build_push_image (nonroot)
- GitHub Check: integration_test (./. ./fuzzquery ./lifecycle ./modules)
- GitHub Check: build_test
- GitHub Check: integration_test (./events)
- GitHub Check: integration_test (./telemetry)
- GitHub Check: Analyze (go)
🔇 Additional comments (3)
router/core/plan_generator.go (3)
98-123: PlanOperation now correctly preserves and returns accumulated timingsThe updated
PlanOperationcleanly threadsOperationTimesthrough parse/prepare and plan phases, and importantly returns the collectedopTimeson all error paths (including parse/validation failures and marshal errors). This aligns with the goal of exposing timings even when planning fails and avoids the earlier double-counting issue by relying solely onPlanPreparedOperationfor plan timing.
125-141: ParseAndPrepareOperation timing and error propagation are sound
ParseAndPrepareOperationnow measures parse time once aroundparseOperation, attaches it to the returnedopTimes(including in error cases), and delegates normalization/validation timing toPrepareOperation. On validation-like errors wrapped inPlannerOperationValidationError, the caller still receives accurateParseTimeplus any normalization/validation timings, which is exactly what you want for regression tracking.
144-167: PrepareOperation correctly captures normalize/validate timings and wraps validation errorsThe normalization and validation steps are now individually timed and stored in
NormalizeTimeandValidateTime, with errors consistently wrapped inPlannerOperationValidationError. When called viaParseAndPrepareOperation, the parse duration is then injected on top, yielding a complete timing picture for validation failures. Behavior for direct callers ofPrepareOperationremains intuitive (noParseTimepopulated).
alepane21
deleted the
ale/eng-8412-make-query-planner-regression-ci-aware-of-query-plan-timings
branch
We want to expose query planning time to make easier and more precise to track query planner's performance regressions.
Summary by CodeRabbit
New Features
Tests
Checklist