feat: expose query operation timings

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

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")
+			})
+		})
+	})
+}

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