diff --git a/dgraph/cmd/alpha/run.go b/dgraph/cmd/alpha/run.go index 470bff21116..4daa94c11a1 100644 --- a/dgraph/cmd/alpha/run.go +++ b/dgraph/cmd/alpha/run.go @@ -46,7 +46,6 @@ import ( "github.com/dgraph-io/dgraph/tok" "github.com/dgraph-io/dgraph/worker" "github.com/dgraph-io/dgraph/x" - "github.com/golang/glog" "github.com/pkg/errors" "github.com/spf13/cast" @@ -196,6 +195,7 @@ they form a Raft group and provide synchronous replication. flag.Bool("graphql_introspection", true, "Set to false for no GraphQL schema introspection") flag.Bool("ludicrous_mode", false, "Run alpha in ludicrous mode") + flag.Bool("graphql_extensions", true, "Set to false if extensions not required in GraphQL response body") flag.Duration("graphql_poll_interval", time.Second, "polling interval for graphql subscription.") } @@ -636,6 +636,7 @@ func run() { x.Config.QueryEdgeLimit = cast.ToUint64(Alpha.Conf.GetString("query_edge_limit")) x.Config.NormalizeNodeLimit = cast.ToInt(Alpha.Conf.GetString("normalize_node_limit")) x.Config.PollInterval = Alpha.Conf.GetDuration("graphql_poll_interval") + x.Config.GraphqlExtension = Alpha.Conf.GetBool("graphql_extensions") x.PrintVersion() glog.Infof("x.Config: %+v", x.Config) diff --git a/graphql/resolve/extensions_test.go b/graphql/resolve/extensions_test.go new file mode 100644 index 00000000000..c06881a5057 --- /dev/null +++ b/graphql/resolve/extensions_test.go @@ -0,0 +1,228 @@ +/* + * Copyright 2020 Dgraph Labs, Inc. and Contributors + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package resolve + +import ( + "testing" + "time" + + "github.com/dgraph-io/dgraph/graphql/test" + "github.com/stretchr/testify/require" +) + +func TestQueriesPropagateExtensions(t *testing.T) { + gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) + query := ` + query { + getAuthor(id: "0x1") { + name + } + }` + + resp := resolveWithClient(gqlSchema, query, nil, + &executor{ + queryTouched: 2, + mutationTouched: 5, + }) + + require.NotNil(t, resp) + require.Nil(t, resp.Errors) + require.NotNil(t, resp.Extensions) + + require.Equal(t, uint64(2), resp.Extensions.TouchedUids) + require.NotNil(t, resp.Extensions.Tracing) + + require.Equal(t, resp.Extensions.Tracing.Version, 1) + _, err := time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.StartTime) + require.NoError(t, err) + _, err = time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.EndTime) + require.NoError(t, err) + require.True(t, resp.Extensions.Tracing.Duration > 0) + require.NotNil(t, resp.Extensions.Tracing.Execution) + + require.Len(t, resp.Extensions.Tracing.Execution.Resolvers, 1) + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].Path, []interface{}{"getAuthor"}) + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].ParentType, "Query") + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].FieldName, "getAuthor") + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].ReturnType, "Author") + require.True(t, resp.Extensions.Tracing.Execution.Resolvers[0].StartOffset > 0) + require.True(t, resp.Extensions.Tracing.Execution.Resolvers[0].Duration > 0) + + require.Len(t, resp.Extensions.Tracing.Execution.Resolvers[0].Dgraph, 1) + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].Dgraph[0].Label, "query") + require.True(t, resp.Extensions.Tracing.Execution.Resolvers[0].Dgraph[0].StartOffset > 0) + require.True(t, resp.Extensions.Tracing.Execution.Resolvers[0].Dgraph[0].Duration > 0) + +} + +func TestMultipleQueriesPropagateExtensionsCorrectly(t *testing.T) { + gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) + query := ` + query { + a: getAuthor(id: "0x1") { + name + } + b: getAuthor(id: "0x2") { + name + } + c: getAuthor(id: "0x3") { + name + } + }` + + resp := resolveWithClient(gqlSchema, query, nil, + &executor{ + queryTouched: 2, + mutationTouched: 5, + }) + + require.NotNil(t, resp) + require.Nil(t, resp.Errors) + require.NotNil(t, resp.Extensions) + + require.Equal(t, uint64(6), resp.Extensions.TouchedUids) + require.NotNil(t, resp.Extensions.Tracing) + + require.Equal(t, resp.Extensions.Tracing.Version, 1) + _, err := time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.StartTime) + require.NoError(t, err) + _, err = time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.EndTime) + require.NoError(t, err) + require.True(t, resp.Extensions.Tracing.Duration > 0) + require.NotNil(t, resp.Extensions.Tracing.Execution) + + require.Len(t, resp.Extensions.Tracing.Execution.Resolvers, 3) + aliases := []string{"a", "b", "c"} + for i, resolver := range resp.Extensions.Tracing.Execution.Resolvers { + require.Equal(t, resolver.Path, []interface{}{aliases[i]}) + require.Equal(t, resolver.ParentType, "Query") + require.Equal(t, resolver.FieldName, aliases[i]) + require.Equal(t, resolver.ReturnType, "Author") + require.True(t, resolver.StartOffset > 0) + require.True(t, resolver.Duration > 0) + require.Len(t, resolver.Dgraph, 1) + require.Equal(t, resolver.Dgraph[0].Label, "query") + require.True(t, resolver.Dgraph[0].StartOffset > 0) + require.True(t, resolver.Dgraph[0].Duration > 0) + } +} + +func TestMutationsPropagateExtensions(t *testing.T) { + gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) + mutation := `mutation { + addPost(input: [{title: "A Post", author: {id: "0x1"}}]) { + post { + title + } + } + }` + + resp := resolveWithClient(gqlSchema, mutation, nil, + &executor{ + queryTouched: 2, + mutationTouched: 5, + }) + + require.NotNil(t, resp) + require.Nil(t, resp.Errors) + require.NotNil(t, resp.Extensions) + + // as both .Mutate() and .Query() should get called, so we should get their merged result + require.Equal(t, uint64(7), resp.Extensions.TouchedUids) + require.NotNil(t, resp.Extensions.Tracing) + + require.Equal(t, resp.Extensions.Tracing.Version, 1) + _, err := time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.StartTime) + require.NoError(t, err) + _, err = time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.EndTime) + require.NoError(t, err) + require.True(t, resp.Extensions.Tracing.Duration > 0) + require.NotNil(t, resp.Extensions.Tracing.Execution) + + require.Len(t, resp.Extensions.Tracing.Execution.Resolvers, 1) + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].Path, []interface{}{"addPost"}) + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].ParentType, "Mutation") + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].FieldName, "addPost") + require.Equal(t, resp.Extensions.Tracing.Execution.Resolvers[0].ReturnType, "AddPostPayload") + require.True(t, resp.Extensions.Tracing.Execution.Resolvers[0].StartOffset > 0) + require.True(t, resp.Extensions.Tracing.Execution.Resolvers[0].Duration > 0) + + require.Len(t, resp.Extensions.Tracing.Execution.Resolvers[0].Dgraph, 2) + labels := []string{"mutation", "query"} + for i, dgraphTrace := range resp.Extensions.Tracing.Execution.Resolvers[0].Dgraph { + require.Equal(t, dgraphTrace.Label, labels[i]) + require.True(t, dgraphTrace.StartOffset > 0) + require.True(t, dgraphTrace.Duration > 0) + } +} + +func TestMultipleMutationsPropagateExtensionsCorrectly(t *testing.T) { + gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) + mutation := `mutation { + a: addPost(input: [{title: "A Post", author: {id: "0x1"}}]) { + post { + title + } + } + b: addPost(input: [{title: "A Post", author: {id: "0x2"}}]) { + post { + title + } + } + }` + + resp := resolveWithClient(gqlSchema, mutation, nil, + &executor{ + queryTouched: 2, + mutationTouched: 5, + }) + + require.NotNil(t, resp) + require.Nil(t, resp.Errors) + require.NotNil(t, resp.Extensions) + + // as both .Mutate() and .Query() should get called, so we should get their merged result + require.Equal(t, uint64(14), resp.Extensions.TouchedUids) + require.NotNil(t, resp.Extensions.Tracing) + + require.Equal(t, resp.Extensions.Tracing.Version, 1) + _, err := time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.StartTime) + require.NoError(t, err) + _, err = time.Parse(time.RFC3339Nano, resp.Extensions.Tracing.EndTime) + require.NoError(t, err) + require.True(t, resp.Extensions.Tracing.Duration > 0) + require.NotNil(t, resp.Extensions.Tracing.Execution) + + require.Len(t, resp.Extensions.Tracing.Execution.Resolvers, 2) + aliases := []string{"a", "b"} + for i, resolver := range resp.Extensions.Tracing.Execution.Resolvers { + require.Equal(t, resolver.Path, []interface{}{aliases[i]}) + require.Equal(t, resolver.ParentType, "Mutation") + require.Equal(t, resolver.FieldName, aliases[i]) + require.Equal(t, resolver.ReturnType, "AddPostPayload") + require.True(t, resolver.StartOffset > 0) + require.True(t, resolver.Duration > 0) + + require.Len(t, resolver.Dgraph, 2) + labels := []string{"mutation", "query"} + for j, dgraphTrace := range resolver.Dgraph { + require.Equal(t, dgraphTrace.Label, labels[j]) + require.True(t, dgraphTrace.StartOffset > 0) + require.True(t, dgraphTrace.Duration > 0) + } + } +} diff --git a/graphql/resolve/mutation.go b/graphql/resolve/mutation.go index a5f7066a25d..c05fa531b40 100644 --- a/graphql/resolve/mutation.go +++ b/graphql/resolve/mutation.go @@ -172,8 +172,20 @@ func (mr *dgraphResolver) Resolve(ctx context.Context, m schema.Mutation) (*Reso span.Annotatef(nil, "mutation alias: [%s] type: [%s]", m.Alias(), m.MutationType()) } + resolverTrace := &schema.ResolverTrace{ + Path: []interface{}{m.ResponseName()}, + ParentType: "Mutation", + FieldName: m.ResponseName(), + ReturnType: m.Type().String(), + } + timer := newtimer(ctx, &resolverTrace.OffsetDuration) + timer.Start() + defer timer.Stop() + resolved, success := mr.rewriteAndExecute(ctx, m) mr.resultCompleter.Complete(ctx, resolved) + resolverTrace.Dgraph = resolved.Extensions.Tracing.Execution.Resolvers[0].Dgraph + resolved.Extensions.Tracing.Execution.Resolvers[0] = resolverTrace return resolved, success } @@ -187,8 +199,7 @@ func getNumUids(m schema.Mutation, a map[string]string, r map[string]interface{} } } -func (mr *dgraphResolver) rewriteAndExecute( - ctx context.Context, +func (mr *dgraphResolver) rewriteAndExecute(ctx context.Context, mutation schema.Mutation) (*Resolved, bool) { var mutResp *dgoapi.Response commit := false @@ -203,11 +214,29 @@ func (mr *dgraphResolver) rewriteAndExecute( } }() + dgraphMutationDuration := &schema.LabeledOffsetDuration{Label: "mutation"} + dgraphQueryDuration := &schema.LabeledOffsetDuration{Label: "query"} + ext := &schema.Extensions{ + Tracing: &schema.Trace{ + Execution: &schema.ExecutionTrace{ + Resolvers: []*schema.ResolverTrace{ + { + Dgraph: []*schema.LabeledOffsetDuration{ + dgraphMutationDuration, + dgraphQueryDuration, + }, + }, + }, + }, + }, + } + emptyResult := func(err error) *Resolved { return &Resolved{ - Data: map[string]interface{}{mutation.Name(): nil}, - Field: mutation, - Err: err, + Data: map[string]interface{}{mutation.Name(): nil}, + Field: mutation, + Err: err, + Extensions: ext, } } @@ -217,16 +246,16 @@ func (mr *dgraphResolver) rewriteAndExecute( resolverFailed } - extM := &schema.Extensions{} - result := make(map[string]interface{}) req := &dgoapi.Request{} newNodes := make(map[string]schema.Type) + mutationTimer := newtimer(ctx, &dgraphMutationDuration.OffsetDuration) + mutationTimer.Start() + for _, upsert := range upserts { req.Query = dgraph.AsString(upsert.Query) req.Mutations = upsert.Mutations - mutResp, err = mr.executor.Execute(ctx, req) if err != nil { gqlErr := schema.GQLWrapLocationf( @@ -235,9 +264,7 @@ func (mr *dgraphResolver) rewriteAndExecute( } - ext := &schema.Extensions{TouchedUids: mutResp.GetMetrics().GetNumUids()[touchedUidsKey]} - extM.Merge(ext) - + ext.TouchedUids += mutResp.GetMetrics().GetNumUids()[touchedUidsKey] if req.Query != "" && len(mutResp.GetJson()) != 0 { if err := json.Unmarshal(mutResp.GetJson(), &result); err != nil { return emptyResult( @@ -248,6 +275,7 @@ func (mr *dgraphResolver) rewriteAndExecute( copyTypeMap(upsert.NewNodes, newNodes) } + mutationTimer.Stop() authErr := authorizeNewNodes(ctx, mutResp.Uids, newNodes, mr.executor, mutResp.Txn) if authErr != nil { @@ -270,19 +298,16 @@ func (mr *dgraphResolver) rewriteAndExecute( } commit = true - qryResp, err := mr.executor.Execute(ctx, - &dgoapi.Request{ - Query: dgraph.AsString(dgQuery), - ReadOnly: true, - }) + queryTimer := newtimer(ctx, &dgraphQueryDuration.OffsetDuration) + queryTimer.Start() + qryResp, err := mr.executor.Execute(ctx, &dgoapi.Request{Query: dgraph.AsString(dgQuery), + ReadOnly: true}) + queryTimer.Stop() + errs = schema.AppendGQLErrs(errs, schema.GQLWrapf(err, "couldn't rewrite query for mutation %s", mutation.Name())) - extQ := &schema.Extensions{TouchedUids: qryResp.GetMetrics().GetNumUids()[touchedUidsKey]} - - // merge the extensions we got from Mutate and Query into extM - extM.Merge(extQ) - + ext.TouchedUids += qryResp.GetMetrics().GetNumUids()[touchedUidsKey] numUids := getNumUids(mutation, mutResp.Uids, result) resolved := completeDgraphResult(ctx, mutation.QueryField(), qryResp.GetJson(), errs) @@ -295,7 +320,7 @@ func (mr *dgraphResolver) rewriteAndExecute( }}, Field: mutation, Err: err, - Extensions: extM, + Extensions: ext, }, resolverSucceeded } @@ -307,7 +332,7 @@ func (mr *dgraphResolver) rewriteAndExecute( dgRes[schema.NumUid] = numUids resolved.Data = map[string]interface{}{mutation.Name(): dgRes} resolved.Field = mutation - resolved.Extensions = extM + resolved.Extensions = ext return resolved, resolverSucceeded } diff --git a/graphql/resolve/query.go b/graphql/resolve/query.go index 0082cee562a..39b89cc3578 100644 --- a/graphql/resolve/query.go +++ b/graphql/resolve/query.go @@ -69,22 +69,45 @@ func (qr *queryResolver) Resolve(ctx context.Context, query schema.Query) *Resol stop := x.SpanTimer(span, "resolveQuery") defer stop() + resolverTrace := &schema.ResolverTrace{ + Path: []interface{}{query.ResponseName()}, + ParentType: "Query", + FieldName: query.ResponseName(), + ReturnType: query.Type().String(), + } + timer := newtimer(ctx, &resolverTrace.OffsetDuration) + timer.Start() + defer timer.Stop() + resolved := qr.rewriteAndExecute(ctx, query) if resolved.Data == nil { resolved.Data = map[string]interface{}{query.Name(): nil} } qr.resultCompleter.Complete(ctx, resolved) + resolverTrace.Dgraph = resolved.Extensions.Tracing.Execution.Resolvers[0].Dgraph + resolved.Extensions.Tracing.Execution.Resolvers[0] = resolverTrace return resolved } func (qr *queryResolver) rewriteAndExecute(ctx context.Context, query schema.Query) *Resolved { + dgraphQueryDuration := &schema.LabeledOffsetDuration{Label: "query"} + ext := &schema.Extensions{ + Tracing: &schema.Trace{ + Execution: &schema.ExecutionTrace{ + Resolvers: []*schema.ResolverTrace{ + {Dgraph: []*schema.LabeledOffsetDuration{dgraphQueryDuration}}, + }, + }, + }, + } emptyResult := func(err error) *Resolved { return &Resolved{ - Data: map[string]interface{}{query.Name(): nil}, - Field: query, - Err: err, + Data: map[string]interface{}{query.Name(): nil}, + Field: query, + Err: err, + Extensions: ext, } } @@ -94,16 +117,20 @@ func (qr *queryResolver) rewriteAndExecute(ctx context.Context, query schema.Que query.ResponseName())) } - resp, err := qr.executor.Execute(ctx, - &dgoapi.Request{Query: dgraph.AsString(dgQuery), ReadOnly: true}) + queryTimer := newtimer(ctx, &dgraphQueryDuration.OffsetDuration) + queryTimer.Start() + resp, err := qr.executor.Execute(ctx, &dgoapi.Request{Query: dgraph.AsString(dgQuery), + ReadOnly: true}) + queryTimer.Stop() + if err != nil { glog.Infof("Dgraph query execution failed : %s", err) return emptyResult(schema.GQLWrapf(err, "Dgraph query failed")) } + ext.TouchedUids = resp.GetMetrics().GetNumUids()[touchedUidsKey] resolved := completeDgraphResult(ctx, query, resp.GetJson(), err) - resolved.Extensions = - &schema.Extensions{TouchedUids: resp.GetMetrics().GetNumUids()[touchedUidsKey]} + resolved.Extensions = ext return resolved } diff --git a/graphql/resolve/resolver.go b/graphql/resolve/resolver.go index 2809e645c68..e66a974c0cb 100644 --- a/graphql/resolve/resolver.go +++ b/graphql/resolve/resolver.go @@ -45,9 +45,13 @@ import ( "github.com/dgraph-io/dgraph/graphql/schema" ) +type resolveCtxKey string + const ( methodResolve = "RequestResolver.Resolve" + resolveStartTime resolveCtxKey = "resolveStartTime" + resolverFailed = false resolverSucceeded = true @@ -379,13 +383,27 @@ func (r *RequestResolver) Resolve(ctx context.Context, gqlReq *schema.Request) * return schema.ErrorResponse(errors.New("Internal error")) } + startTime := time.Now() + resp := &schema.Response{ + Extensions: &schema.Extensions{ + Tracing: &schema.Trace{ + Version: 1, + StartTime: startTime.Format(time.RFC3339Nano), + }, + }, + } + defer func() { + endTime := time.Now() + resp.Extensions.Tracing.EndTime = endTime.Format(time.RFC3339Nano) + resp.Extensions.Tracing.Duration = endTime.Sub(startTime).Nanoseconds() + }() + ctx = context.WithValue(ctx, resolveStartTime, startTime) + op, err := r.schema.Operation(gqlReq) if err != nil { return schema.ErrorResponse(err) } - resp := &schema.Response{} - if glog.V(3) { // don't log the introspection queries they are sent too frequently // by GraphQL dev tools @@ -418,7 +436,8 @@ func (r *RequestResolver) Resolve(ctx context.Context, gqlReq *schema.Request) * allResolved[storeAt] = &Resolved{ Data: nil, Field: q, - Err: err} + Err: err, + } }) allResolved[storeAt] = r.resolvers.queryResolverFor(q).Resolve(ctx, q) @@ -432,6 +451,7 @@ func (r *RequestResolver) Resolve(ctx context.Context, gqlReq *schema.Request) * // Errors and data in the same response is valid. Both WithError and // AddData handle nil cases. addResult(resp, res) + } } // A single request can contain either queries or mutations - not both. @@ -1820,3 +1840,9 @@ func EmptyResult(f schema.Field, err error) *Resolved { Err: schema.GQLWrapLocationf(err, f.Location(), "resolving %s failed", f.Name()), } } + +func newtimer(ctx context.Context, Duration *schema.OffsetDuration) schema.OffsetTimer { + resolveStartTime, _ := ctx.Value(resolveStartTime).(time.Time) + tf := schema.NewOffsetTimerFactory(resolveStartTime) + return tf.NewOffsetTimer(Duration) +} diff --git a/graphql/resolve/resolver_error_test.go b/graphql/resolve/resolver_error_test.go index 9c22f832c53..6ceffbd68c1 100644 --- a/graphql/resolve/resolver_error_test.go +++ b/graphql/resolve/resolver_error_test.go @@ -399,109 +399,6 @@ func TestManyMutationsWithError(t *testing.T) { } } -func TestQueriesPropagateExtensions(t *testing.T) { - gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) - query := ` - query { - getAuthor(id: "0x1") { - name - } - }` - - resp := resolveWithClient(gqlSchema, query, nil, - &executor{ - queryTouched: 2, - mutationTouched: 5, - }) - - expectedExtensions := &schema.Extensions{TouchedUids: 2} - - require.NotNil(t, resp) - require.Nil(t, resp.Errors) - require.Equal(t, expectedExtensions, resp.Extensions) -} - -func TestMultipleQueriesPropagateExtensionsCorrectly(t *testing.T) { - gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) - query := ` - query { - a: getAuthor(id: "0x1") { - name - } - b: getAuthor(id: "0x2") { - name - } - c: getAuthor(id: "0x3") { - name - } - }` - - resp := resolveWithClient(gqlSchema, query, nil, - &executor{ - queryTouched: 2, - mutationTouched: 5, - }) - - expectedExtensions := &schema.Extensions{TouchedUids: 6} - - require.NotNil(t, resp) - require.Nil(t, resp.Errors) - require.Equal(t, expectedExtensions, resp.Extensions) -} - -func TestMutationsPropagateExtensions(t *testing.T) { - gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) - mutation := `mutation { - addPost(input: [{title: "A Post", author: {id: "0x1"}}]) { - post { - title - } - } - }` - - resp := resolveWithClient(gqlSchema, mutation, nil, - &executor{ - queryTouched: 2, - mutationTouched: 5, - }) - - // as both .Mutate() and .Query() should get called, so we should get their merged result - expectedExtensions := &schema.Extensions{TouchedUids: 7} - - require.NotNil(t, resp) - require.Nil(t, resp.Errors) - require.Equal(t, expectedExtensions, resp.Extensions) -} - -func TestMultipleMutationsPropagateExtensionsCorrectly(t *testing.T) { - gqlSchema := test.LoadSchemaFromString(t, testGQLSchema) - mutation := `mutation { - a: addPost(input: [{title: "A Post", author: {id: "0x1"}}]) { - post { - title - } - } - b: addPost(input: [{title: "A Post", author: {id: "0x2"}}]) { - post { - title - } - } - }` - - resp := resolveWithClient(gqlSchema, mutation, nil, - &executor{ - queryTouched: 2, - mutationTouched: 5, - }) - - // as both .Mutate() and .Query() should get called, so we should get their merged result - expectedExtensions := &schema.Extensions{TouchedUids: 14} - - require.NotNil(t, resp) - require.Nil(t, resp.Errors) - require.Equal(t, expectedExtensions, resp.Extensions) -} - func resolve(gqlSchema schema.Schema, gqlQuery string, dgResponse string) *schema.Response { return resolveWithClient(gqlSchema, gqlQuery, nil, &executor{resp: dgResponse}) } diff --git a/graphql/schema/response.go b/graphql/schema/response.go index 2b583c1414b..418ca925a59 100644 --- a/graphql/schema/response.go +++ b/graphql/schema/response.go @@ -21,33 +21,13 @@ import ( "encoding/json" "fmt" "io" + "time" - "github.com/dgraph-io/dgraph/x" "github.com/golang/glog" "github.com/pkg/errors" -) - -// Extensions represents GraphQL extensions -type Extensions struct { - TouchedUids uint64 `json:"touched_uids,omitempty"` -} -// GetTouchedUids returns TouchedUids -func (e *Extensions) GetTouchedUids() uint64 { - if e == nil { - return 0 - } - return e.TouchedUids -} - -// Merge merges ext with e -func (e *Extensions) Merge(ext *Extensions) { - if e == nil || ext == nil { - return - } - - e.TouchedUids += ext.TouchedUids -} + "github.com/dgraph-io/dgraph/x" +) // GraphQL spec on response is here: // https://graphql.github.io/graphql-spec/June2018/#sec-Response @@ -155,13 +135,197 @@ func (r *Response) Output() interface{} { Data: []byte("null"), } } - return struct { + + res := struct { Errors []*x.GqlError `json:"errors,omitempty"` Data json.RawMessage `json:"data,omitempty"` Extensions *Extensions `json:"extensions,omitempty"` }{ - Errors: r.Errors, - Data: r.Data.Bytes(), - Extensions: r.Extensions, + Errors: r.Errors, + Data: r.Data.Bytes(), + } + + if x.Config.GraphqlExtension { + res.Extensions = r.Extensions + } + return res +} + +// Extensions represents GraphQL extensions +type Extensions struct { + TouchedUids uint64 `json:"touched_uids,omitempty"` + Tracing *Trace `json:"tracing,omitempty"` +} + +// GetTouchedUids returns TouchedUids +func (e *Extensions) GetTouchedUids() uint64 { + if e == nil { + return 0 + } + return e.TouchedUids +} + +// Merge merges ext with e +func (e *Extensions) Merge(ext *Extensions) { + if e == nil || ext == nil { + return + } + + e.TouchedUids += ext.TouchedUids + + if e.Tracing == nil { + e.Tracing = ext.Tracing + } else { + e.Tracing.Merge(ext.Tracing) + } +} + +// Trace : Apollo Tracing is a GraphQL extension for tracing resolver performance.Response +// https://github.com/apollographql/apollo-tracing +// Not part of the standard itself, it gets reported in GraphQL "extensions". +// It's for reporting tracing data through all the resolvers in a GraphQL query. +// Our results aren't as 'deep' as a traditional GraphQL server in that the Dgraph +// layer resolves in a single step, rather than iteratively. So we'll report on +// all the top level queries/mutations. +// +// Currently, only reporting in the GraphQL result, but also planning to allow +// exposing to Apollo Engine as per: +// https://www.apollographql.com/docs/references/setup-analytics/#engine-reporting-endpoint +type Trace struct { + // (comments from Apollo Tracing spec) + + // Apollo Tracing Spec version + Version int `json:"version"` + + // Timestamps in RFC 3339 nano format. + StartTime string `json:"startTime,"` + EndTime string `json:"endTime"` + + // Duration in nanoseconds, relative to the request start, as an integer. + Duration int64 `json:"duration"` + + // Parsing and Validation not required at the moment. + //Parsing *OffsetDuration `json:"parsing,omitempty"` + //Validation *OffsetDuration `json:"validation,omitempty"` + Execution *ExecutionTrace `json:"execution,omitempty"` +} + +func (t *Trace) Merge(other *Trace) { + if t == nil || other == nil { + return + } + + if t.Execution == nil { + t.Execution = other.Execution + } else { + t.Execution.Merge(other.Execution) + } +} + +//ExecutionTrace records all the resolvers +type ExecutionTrace struct { + Resolvers []*ResolverTrace `json:"resolvers"` +} + +func (e *ExecutionTrace) Merge(other *ExecutionTrace) { + if e == nil || other == nil { + return + } + + if len(other.Resolvers) != 0 { + e.Resolvers = append(e.Resolvers, other.Resolvers...) + } +} + +// A ResolverTrace is a trace of one resolver. In a traditional GraphQL server, +// resolving say a query, would result in a ResolverTrace for the query itself +// (with duration spanning the time to resolve the entire query) and traces for +// every field in the query (with duration for just that field). +// +// Dgraph GraphQL layer resolves Queries in a single step, so each query has only +// one associated ResolverTrace. Mutations require two steps - the mutation itself +// and the following query. So mutations will have a ResolverTrace with duration +// spanning the entire mutation (including the query part), and a trace of the query. +// To give insight into what's actually happening there, the Dgraph time is also +// recorded. So for a mutation you can see total duration, mutation duration, +// query duration and also amount of time spent by the API orchestrating the +// mutation/query. +type ResolverTrace struct { + // (comments from Apollo Tracing spec) + + // the response path of the current resolver - same format as path in error + // result format specified in the GraphQL specification + Path []interface{} `json:"path"` + ParentType string `json:"parentType"` + FieldName string `json:"fieldName"` + ReturnType string `json:"returnType"` + + // Offset relative to request start and total duration or resolving + OffsetDuration + + // Dgraph isn't in Apollo tracing. It records the offsets and times + // of Dgraph operations for the query/mutation (including network latency) + // in nanoseconds. + Dgraph []*LabeledOffsetDuration `json:"dgraph"` +} + +// An OffsetDuration records the offset start and duration of GraphQL parsing/validation. +type OffsetDuration struct { + // (comments from Apollo Tracing spec) + + // Offset in nanoseconds, relative to the request start, as an integer + StartOffset int64 `json:"startOffset"` + + // Duration in nanoseconds, relative to start of operation, as an integer. + Duration int64 `json:"duration"` +} + +// LabeledOffsetDuration is an OffsetDuration with a string label. +type LabeledOffsetDuration struct { + Label string `json:"label"` + OffsetDuration +} + +// A TimerFactory makes offset timers that can be used to fill out an OffsetDuration. +type TimerFactory interface { + NewOffsetTimer(storeTo *OffsetDuration) OffsetTimer +} + +// An OffsetTimer is used to fill out an OffsetDuration. Start starts the timer +// and calculates the offset. Stop calculates the duration. +type OffsetTimer interface { + Start() + Stop() +} + +type timerFactory struct { + offsetFrom time.Time +} + +type offsetTimer struct { + offsetFrom time.Time + start time.Time + backing *OffsetDuration +} + +// NewOffsetTimerFactory creates a new TimerFactory given offsetFrom as the +// reference time to calculate the OffsetDuration.StartOffset from. +func NewOffsetTimerFactory(offsetFrom time.Time) TimerFactory { + return &timerFactory{offsetFrom: offsetFrom} +} + +func (tf *timerFactory) NewOffsetTimer(storeTo *OffsetDuration) OffsetTimer { + return &offsetTimer{ + offsetFrom: tf.offsetFrom, + backing: storeTo, } } + +func (ot *offsetTimer) Start() { + ot.start = time.Now() + ot.backing.StartOffset = ot.start.Sub(ot.offsetFrom).Nanoseconds() +} + +func (ot *offsetTimer) Stop() { + ot.backing.Duration = time.Since(ot.start).Nanoseconds() +} diff --git a/systest/loader/loader_test.go b/systest/loader/loader_test.go index 20567bc6eb6..980e3f6ce55 100644 --- a/systest/loader/loader_test.go +++ b/systest/loader/loader_test.go @@ -79,24 +79,23 @@ func TestLoaderXidmap(t *testing.T) { } b, err := json.Marshal(params) require.NoError(t, err) - resp, err := http.Post(adminUrl, "application/json", bytes.NewBuffer(b)) require.NoError(t, err) defer resp.Body.Close() - b, err = ioutil.ReadAll(resp.Body) require.NoError(t, err) expected := `{ - "data": { "export": { "response": { "code": "Success", "message": "Export completed." } } - } - }` - require.JSONEq(t, expected, string(b)) + }` + res1 := &testutil.GraphQLResponse{} + err=json.Unmarshal(b,res1) + require.NoError(t, err) + require.JSONEq(t, expected, string(res1.Data)) require.NoError(t, copyExportFiles(tmpDir)) diff --git a/x/config.go b/x/config.go index f8daad383fb..b5ddd2416e5 100644 --- a/x/config.go +++ b/x/config.go @@ -32,6 +32,8 @@ type Options struct { NormalizeNodeLimit int // PollInterval is the polling interval for graphql subscription. PollInterval time.Duration + //GraphqlExtension wiil be set to see extensions in graphql results + GraphqlExtension bool } // Config stores the global instance of this package's options.