diff --git a/router-tests/modules/custom-operation-timings/module.go b/router-tests/modules/custom-operation-timings/module.go new file mode 100644 index 0000000000..015136986a --- /dev/null +++ b/router-tests/modules/custom-operation-timings/module.go @@ -0,0 +1,48 @@ +package custom_operation_timings + +import ( + "net/http" + + "github.com/wundergraph/cosmo/router/core" +) + +const myModuleID = "operationTimingsModule" + +// OperationTimingsModule is a simple module that reads and logs the operation timings +type OperationTimingsModule struct { + ResultsChan chan core.OperationTimings +} + +func (m *OperationTimingsModule) Middleware(ctx core.RequestContext, next http.Handler) { + timings := ctx.Operation().Timings() + + if m.ResultsChan != nil { + select { + case m.ResultsChan <- timings: + default: + // drop if nobody is listening to avoid blocking the request path + } + } + + // Call the next handler in the chain or return early by calling w.Write() + next.ServeHTTP(ctx.ResponseWriter(), ctx.Request()) +} + +func (m *OperationTimingsModule) Module() core.ModuleInfo { + return core.ModuleInfo{ + // This is the ID of your module, it must be unique + ID: myModuleID, + // The priority of your module, lower numbers are executed first + Priority: 1, + New: func() core.Module { + return &OperationTimingsModule{ + ResultsChan: make(chan core.OperationTimings, 1), + } + }, + } +} + +// Interface guard +var ( + _ core.RouterMiddlewareHandler = (*OperationTimingsModule)(nil) +) diff --git a/router-tests/modules/operation_timings_test.go b/router-tests/modules/operation_timings_test.go new file mode 100644 index 0000000000..1417ece09d --- /dev/null +++ b/router-tests/modules/operation_timings_test.go @@ -0,0 +1,130 @@ +package module_test + +import ( + "encoding/json" + "testing" + "time" + + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + operationTimingsModule "github.com/wundergraph/cosmo/router-tests/modules/custom-operation-timings" + "github.com/wundergraph/cosmo/router-tests/testenv" + "github.com/wundergraph/cosmo/router/cmd/custom/module" + "github.com/wundergraph/cosmo/router/core" + "github.com/wundergraph/cosmo/router/pkg/config" +) + +func TestCustomModuleOperationTimings(t *testing.T) { + t.Run("gets the correct timings for a simple query", func(t *testing.T) { + t.Parallel() + + resultsChan := make(chan core.OperationTimings, 1) + + cfg := config.Config{ + Graph: config.Graph{}, + Modules: map[string]any{ + "myModule": module.MyModule{ + Value: 1, + }, + "operationTimingsModule": operationTimingsModule.OperationTimingsModule{ + ResultsChan: resultsChan, + }, + }, + } + + testenv.Run(t, &testenv.Config{ + RouterOptions: []core.Option{ + core.WithModulesConfig(cfg.Modules), + core.WithCustomModules(&module.MyModule{}, &operationTimingsModule.OperationTimingsModule{}), + }, + }, func(t *testing.T, xEnv *testenv.Environment) { + res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{ + Query: `query MyQuery { employee(id: 1) { id currentMood } }`, + OperationName: json.RawMessage(`"MyQuery"`), + }) + require.NoError(t, err) + assert.Equal(t, 200, res.Response.StatusCode) + + testenv.AwaitChannelWithT(t, 10*time.Second, resultsChan, func(t *testing.T, timings core.OperationTimings) { + // Verify that timings are populated (they should be non-zero for a real query) + // We don't check exact values as they depend on the machine, but we verify they are set + assert.GreaterOrEqual(t, timings.ParsingTime, time.Duration(0), "ParsingTime should be non-negative") + assert.GreaterOrEqual(t, timings.ValidationTime, time.Duration(0), "ValidationTime should be non-negative") + assert.GreaterOrEqual(t, timings.PlanningTime, time.Duration(0), "PlanningTime should be non-negative") + assert.GreaterOrEqual(t, timings.NormalizationTime, time.Duration(0), "NormalizationTime should be non-negative") + + // At least one timing should be non-zero to verify timings are actually being captured + totalTime := timings.ParsingTime + timings.ValidationTime + timings.PlanningTime + timings.NormalizationTime + assert.Greater(t, totalTime, time.Duration(0), "At least one timing should be non-zero") + }) + }) + }) + + t.Run("gets the correct timings for a complex query", func(t *testing.T) { + t.Parallel() + + resultsChan := make(chan core.OperationTimings, 1) + + cfg := config.Config{ + Graph: config.Graph{}, + Modules: map[string]any{ + "myModule": module.MyModule{ + Value: 1, + }, + "operationTimingsModule": operationTimingsModule.OperationTimingsModule{ + ResultsChan: resultsChan, + }, + }, + } + + testenv.Run(t, &testenv.Config{ + RouterOptions: []core.Option{ + core.WithModulesConfig(cfg.Modules), + core.WithCustomModules(&module.MyModule{}, &operationTimingsModule.OperationTimingsModule{}), + }, + }, func(t *testing.T, xEnv *testenv.Environment) { + res, err := xEnv.MakeGraphQLRequest(testenv.GraphQLRequest{ + Query: ` + query Employees { + employees { + id + tag + notes + updatedAt + currentMood + derivedMood + isAvailable + products + details { + forename + surname + middlename + hasChildren + maritalStatus + nationality + } + role { + departments + title + } + } + }`, + OperationName: json.RawMessage(`"Employees"`), + }) + require.NoError(t, err) + assert.Equal(t, 200, res.Response.StatusCode) + + testenv.AwaitChannelWithT(t, 10*time.Second, resultsChan, func(t *testing.T, timings core.OperationTimings) { + // Verify that timings are populated + assert.GreaterOrEqual(t, timings.ParsingTime, time.Duration(0), "ParsingTime should be non-negative") + assert.GreaterOrEqual(t, timings.ValidationTime, time.Duration(0), "ValidationTime should be non-negative") + assert.GreaterOrEqual(t, timings.PlanningTime, time.Duration(0), "PlanningTime should be non-negative") + assert.GreaterOrEqual(t, timings.NormalizationTime, time.Duration(0), "NormalizationTime should be non-negative") + + // At least one timing should be non-zero to verify timings are actually being captured + totalTime := timings.ParsingTime + timings.ValidationTime + timings.PlanningTime + timings.NormalizationTime + assert.Greater(t, totalTime, time.Duration(0), "At least one timing should be non-zero") + }) + }) + }) +} diff --git a/router/core/context.go b/router/core/context.go index 1a490ac81c..6162f96499 100644 --- a/router/core/context.go +++ b/router/core/context.go @@ -578,6 +578,11 @@ type OperationContext interface { // if called too early in request chain, it may be inaccurate for modules, using // in Middleware is recommended QueryPlanStats() (QueryPlanStats, error) + + // Timings returns the timing information for various stages of operation processing + // if called too early in request chain, it may be inaccurate for modules, using + // in Middleware is recommended + Timings() OperationTimings } var _ OperationContext = (*operationContext)(nil) @@ -683,6 +688,15 @@ func (o *operationContext) Sha256Hash() string { return o.sha256Hash } +func (o *operationContext) Timings() OperationTimings { + return OperationTimings{ + ParsingTime: o.parsingTime, + ValidationTime: o.validationTime, + PlanningTime: o.planningTime, + NormalizationTime: o.normalizationTime, + } +} + // GetTypeFieldUsageInfoMetrics returns the cached conversion of typeFieldUsageInfo. // This avoids repeated allocations when multiple exporters need the same data. func (o *operationContext) GetTypeFieldUsageInfoMetrics() []*graphqlmetrics.TypeFieldUsageInfo { @@ -692,6 +706,14 @@ func (o *operationContext) GetTypeFieldUsageInfoMetrics() []*graphqlmetrics.Type return o.typeFieldUsageInfoMetrics } +// OperationTimings contains timing information for various stages of operation processing +type OperationTimings struct { + ParsingTime time.Duration + ValidationTime time.Duration + PlanningTime time.Duration + NormalizationTime time.Duration +} + type QueryPlanStats struct { TotalSubgraphFetches int SubgraphFetches map[string]int