Capture read times

graphql/handler.go

@@ -24,6 +24,8 @@ type (
 		OperationName string                 `json:"operationName"`
 		Variables     map[string]interface{} `json:"variables"`
 		Extensions    map[string]interface{} `json:"extensions"`
+
+		ReadTime TraceTiming `json:"-"`
 	}
 
 	GraphExecutor interface {

graphql/handler/apollotracing/tracer_test.go

@@ -6,6 +6,9 @@ import (
 	"net/http/httptest"
 	"strings"
 	"testing"
+	"time"
+
+	"github.com/99designs/gqlgen/graphql"
 
 	"github.com/99designs/gqlgen/graphql/handler/apollotracing"
 	"github.com/99designs/gqlgen/graphql/handler/extension"
@@ -18,6 +21,15 @@ import (
 )
 
 func TestApolloTracing(t *testing.T) {
+	now := time.Unix(0, 0)
+
+	graphql.Now = func() time.Time {
+		defer func() {
+			now = now.Add(100 * time.Nanosecond)
+		}()
+		return now
+	}
+
 	h := testserver.New()
 	h.AddTransport(transport.POST{})
 	h.Use(apollotracing.Tracer{})
@@ -36,16 +48,16 @@ func TestApolloTracing(t *testing.T) {
 	require.EqualValues(t, 1, tracing.Version)
 
 	require.EqualValues(t, 0, tracing.StartTime.UnixNano())
-	require.EqualValues(t, 700, tracing.EndTime.UnixNano())
-	require.EqualValues(t, 700, tracing.Duration)
+	require.EqualValues(t, 900, tracing.EndTime.UnixNano())
+	require.EqualValues(t, 900, tracing.Duration)
 
-	require.EqualValues(t, 100, tracing.Parsing.StartOffset)
+	require.EqualValues(t, 300, tracing.Parsing.StartOffset)
 	require.EqualValues(t, 100, tracing.Parsing.Duration)
 
-	require.EqualValues(t, 300, tracing.Validation.StartOffset)
+	require.EqualValues(t, 500, tracing.Validation.StartOffset)
 	require.EqualValues(t, 100, tracing.Validation.Duration)
 
-	require.EqualValues(t, 500, tracing.Execution.Resolvers[0].StartOffset)
+	require.EqualValues(t, 700, tracing.Execution.Resolvers[0].StartOffset)
 	require.EqualValues(t, 100, tracing.Execution.Resolvers[0].Duration)
 	require.EqualValues(t, []interface{}{"name"}, tracing.Execution.Resolvers[0].Path)
 	require.EqualValues(t, "Query", tracing.Execution.Resolvers[0].ParentType)
@@ -54,6 +66,15 @@ func TestApolloTracing(t *testing.T) {
 }
 
 func TestApolloTracing_withFail(t *testing.T) {
+	now := time.Unix(0, 0)
+
+	graphql.Now = func() time.Time {
+		defer func() {
+			now = now.Add(100 * time.Nanosecond)
+		}()
+		return now
+	}
+
 	h := testserver.New()
 	h.AddTransport(transport.POST{})
 	h.Use(extension.AutomaticPersistedQuery{Cache: lru.New(100)})

graphql/handler/executor.go

@@ -121,7 +121,10 @@ func (e executor) CreateOperationContext(ctx context.Context, params *graphql.Ra
 		DisableIntrospection: true,
 		Recover:              graphql.DefaultRecover,
 		ResolverMiddleware:   e.fieldMiddleware,
-		Stats:                graphql.Stats{OperationStart: graphql.GetStartTime(ctx)},
+		Stats: graphql.Stats{
+			Read:           params.ReadTime,
+			OperationStart: graphql.GetStartTime(ctx),
+		},
 	}
 	ctx = graphql.WithOperationContext(ctx, rc)
 

graphql/handler/testserver/testserver.go

@@ -15,14 +15,6 @@ import (
 // a generated server, but it aims to be good enough to test the handler package without relying on codegen.
 func New() *TestServer {
 	next := make(chan struct{})
-	now := time.Unix(0, 0)
-
-	graphql.Now = func() time.Time {
-		defer func() {
-			now = now.Add(100 * time.Nanosecond)
-		}()
-		return now
-	}
 
 	schema := gqlparser.MustLoadSchema(&ast.Source{Input: `
 		type Query {

graphql/handler/transport/http_form.go

@@ -56,6 +56,8 @@ func (f MultipartForm) maxMemory() int64 {
 func (f MultipartForm) Do(w http.ResponseWriter, r *http.Request, exec graphql.GraphExecutor) {
 	w.Header().Set("Content-Type", "application/json")
 
+	start := graphql.Now()
+
 	var err error
 	if r.ContentLength > f.maxUploadSize() {
 		writeJsonError(w, "failed to parse multipart form, request body too large")
@@ -186,6 +188,11 @@ func (f MultipartForm) Do(w http.ResponseWriter, r *http.Request, exec graphql.G
 		}
 	}
 
+	params.ReadTime = graphql.TraceTiming{
+		Start: start,
+		End:   graphql.Now(),
+	}
+
 	rc, gerr := exec.CreateOperationContext(r.Context(), &params)
 	if gerr != nil {
 		resp := exec.DispatchError(graphql.WithOperationContext(r.Context(), rc), gerr)

graphql/handler/transport/http_get.go

@@ -31,6 +31,7 @@ func (h GET) Do(w http.ResponseWriter, r *http.Request, exec graphql.GraphExecut
 		Query:         r.URL.Query().Get("query"),
 		OperationName: r.URL.Query().Get("operationName"),
 	}
+	raw.ReadTime.Start = graphql.Now()
 
 	if variables := r.URL.Query().Get("variables"); variables != "" {
 		if err := jsonDecode(strings.NewReader(variables), &raw.Variables); err != nil {
@@ -48,6 +49,8 @@ func (h GET) Do(w http.ResponseWriter, r *http.Request, exec graphql.GraphExecut
 		}
 	}
 
+	raw.ReadTime.End = graphql.Now()
+
 	rc, err := exec.CreateOperationContext(r.Context(), raw)
 	if err != nil {
 		w.WriteHeader(statusFor(err))

graphql/handler/transport/http_post.go

@@ -30,11 +30,16 @@ func (h POST) Do(w http.ResponseWriter, r *http.Request, exec graphql.GraphExecu
 	w.Header().Set("Content-Type", "application/json")
 
 	var params *graphql.RawParams
+	start := graphql.Now()
 	if err := jsonDecode(r.Body, &params); err != nil {
 		w.WriteHeader(http.StatusBadRequest)
 		writeJsonErrorf(w, "json body could not be decoded: "+err.Error())
 		return
 	}
+	params.ReadTime = graphql.TraceTiming{
+		Start: start,
+		End:   graphql.Now(),
+	}
 
 	rc, err := exec.CreateOperationContext(r.Context(), params)
 	if err != nil {

graphql/handler/transport/websocket.go

@@ -148,14 +148,15 @@ func (c *wsConnection) run() {
 	}
 
 	for {
+		start := graphql.Now()
 		message := c.readOp()
 		if message == nil {
 			return
 		}
 
 		switch message.Type {
 		case startMsg:
-			c.subscribe(message)
+			c.subscribe(start, message)
 		case stopMsg:
 			c.mu.Lock()
 			closer := c.active[message.ID]
@@ -186,7 +187,7 @@ func (c *wsConnection) keepAlive(ctx context.Context) {
 	}
 }
 
-func (c *wsConnection) subscribe(message *operationMessage) {
+func (c *wsConnection) subscribe(start time.Time, message *operationMessage) {
 	ctx := graphql.StartOperationTrace(c.ctx)
 	var params *graphql.RawParams
 	if err := jsonDecode(bytes.NewReader(message.Payload), &params); err != nil {
@@ -195,6 +196,11 @@ func (c *wsConnection) subscribe(message *operationMessage) {
 		return
 	}
 
+	params.ReadTime = graphql.TraceTiming{
+		Start: start,
+		End:   graphql.Now(),
+	}
+
 	rc, err := c.exec.CreateOperationContext(ctx, params)
 	if err != nil {
 		resp := c.exec.DispatchError(graphql.WithOperationContext(ctx, rc), err)

graphql/stats.go

@@ -8,6 +8,7 @@ import (
 
 type Stats struct {
 	OperationStart time.Time
+	Read           TraceTiming
 	Parsing        TraceTiming
 	Validation     TraceTiming