diff --git a/graphql/handler.go b/graphql/handler.go index e9c95b442f..077701cc42 100644 --- a/graphql/handler.go +++ b/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 { diff --git a/graphql/handler/apollotracing/tracer_test.go b/graphql/handler/apollotracing/tracer_test.go index fa26024d2e..d78d61c47c 100644 --- a/graphql/handler/apollotracing/tracer_test.go +++ b/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)}) diff --git a/graphql/handler/executor.go b/graphql/handler/executor.go index 057c134ba6..b2f6959328 100644 --- a/graphql/handler/executor.go +++ b/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) diff --git a/graphql/handler/testserver/testserver.go b/graphql/handler/testserver/testserver.go index 0a1d91b420..a434091474 100644 --- a/graphql/handler/testserver/testserver.go +++ b/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 { diff --git a/graphql/handler/transport/http_form.go b/graphql/handler/transport/http_form.go index a2c7d8d778..63f8e9fb68 100644 --- a/graphql/handler/transport/http_form.go +++ b/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(), ¶ms) if gerr != nil { resp := exec.DispatchError(graphql.WithOperationContext(r.Context(), rc), gerr) diff --git a/graphql/handler/transport/http_get.go b/graphql/handler/transport/http_get.go index 8e29826b2b..8cec6a6213 100644 --- a/graphql/handler/transport/http_get.go +++ b/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)) diff --git a/graphql/handler/transport/http_post.go b/graphql/handler/transport/http_post.go index ebe024e409..deefeb38d0 100644 --- a/graphql/handler/transport/http_post.go +++ b/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, ¶ms); 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 { diff --git a/graphql/handler/transport/websocket.go b/graphql/handler/transport/websocket.go index 5a53623183..57552afb80 100644 --- a/graphql/handler/transport/websocket.go +++ b/graphql/handler/transport/websocket.go @@ -148,6 +148,7 @@ func (c *wsConnection) run() { } for { + start := graphql.Now() message := c.readOp() if message == nil { return @@ -155,7 +156,7 @@ func (c *wsConnection) run() { 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), ¶ms); 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) diff --git a/graphql/stats.go b/graphql/stats.go index f607f25a1e..a52e143ebe 100644 --- a/graphql/stats.go +++ b/graphql/stats.go @@ -8,6 +8,7 @@ import ( type Stats struct { OperationStart time.Time + Read TraceTiming Parsing TraceTiming Validation TraceTiming