From 8dbce3cf161f19c132d3cf29aa95851732c7f922 Mon Sep 17 00:00:00 2001 From: Adam Date: Tue, 7 Jan 2020 16:29:15 +1100 Subject: [PATCH] Capture the time spent reading requests from the client --- graphql/handler.go | 2 ++ graphql/handler/apollotracing/tracer_test.go | 10 +++++----- graphql/handler/executor.go | 5 ++++- graphql/handler/transport/http_form.go | 7 +++++++ graphql/handler/transport/http_get.go | 3 +++ graphql/handler/transport/http_post.go | 5 +++++ graphql/handler/transport/websocket.go | 10 ++++++++-- graphql/stats.go | 1 + 8 files changed, 35 insertions(+), 8 deletions(-) diff --git a/graphql/handler.go b/graphql/handler.go index e9c95b442ff..077701cc42b 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 fa26024d2e1..c3f628f0235 100644 --- a/graphql/handler/apollotracing/tracer_test.go +++ b/graphql/handler/apollotracing/tracer_test.go @@ -36,16 +36,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) diff --git a/graphql/handler/executor.go b/graphql/handler/executor.go index 057c134ba65..b2f69593282 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/transport/http_form.go b/graphql/handler/transport/http_form.go index a2c7d8d778a..63f8e9fb68d 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 8e29826b2b4..8cec6a62135 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 ebe024e4095..deefeb38d00 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 5a53623183d..57552afb80f 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 f607f25a1e9..a52e143ebe4 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