Capture the time spent reading requests from the client

99designs · Jan 15, 2020 · 8dbce3c · 8dbce3c
1 parent c6b3e2a
commit 8dbce3c
Show file tree

Hide file tree

Showing 8 changed files with 35 additions and 8 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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)

diff --git 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
@@ -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 {

diff --git a/graphql/handler/transport/websocket.go b/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)

diff --git 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