Reporting Slow Resolver

[sumanthakannantha]

What happened?

We are facing a performance issue with some of our resolvers. Is there any way to enable slow resolver reporting?
Example: I want to report/log all the resolvers which are taking more than 1 second in production.
Any suggestion to achieve this in gqlgen framework instead of explicit logic in the resolvers?

[fasibio]

What do you think about to use an own directive for this. Or a Middleware at general ? You could use a http middleware at general to check this ?

[pundliksarafdar]

I have a similar requirement to log slow resolver, Can you please elaborate this solution?

[sumanthakannantha]

@fasibio If I understand correctly, a directive will be called at starting the resolver execution. Not sure if we can use it for measuring resolver.
Do we get resolver execution feedback at the Middleware level?

[fasibio]

Give me some day until end of weekend I will try it and write a short example ok ?

[fasibio]

Soo now:
First of all I did not solved it completely.
The Problem i did not know the Context object at gqlgen and did not find the docs....

But How you can start:

1. add this to your schema file:

directive @trackTime on FIELD_DEFINITION

and add the directive to the Query

type Query {
  todos: [Todo!]! @trackTime
}

2. Generate
3. implements at server.go this function:

handler.NewDefaultServer(generated.NewExecutableSchema(generated.Config{
		Resolvers: &graph.Resolver{
			TodoSubscriber: toDoChan,
		},
		Directives: generated.DirectiveRoot{
			TrackTime: func(ctx context.Context, obj interface{}, next graphql.Resolver) (interface{}, error) {
// this is the function we are talking about
				start := time.Now()
                               // find out which reducer here (thats the point I am struggle at the moment) 
				defer func() {
					log.Println("your execution time", time.Since(start))
				}()
				return next(ctx)
			},
		},
	}))

Thats all.

At a workaround:

Change directive as follow:

directive @trackTime(name: String!) on FIELD_DEFINITION

use it like this:

type Query {
  todos: [Todo!]! @trackTime(name: "Get ToDOs")
}

Implementation at server.go:

			TrackTime: func(ctx context.Context, obj interface{}, next graphql.Resolver, name string) (res interface{}, err error) {
				start := time.Now()
				defer func() {
					log.Printf("Tracking time for %s time:  %v \n", name, time.Since(start))
				}()
				return next(ctx)
			},

Hope this helps.

And someone will make a documentation for Context for gqlgen special values....

[fasibio]

If someone explian the Context.
We can easy create a Solution at general:

But only with complete Query not by reolvers:

With a http middleware:

.Use(trackResponseTime)
func trackResponseTime(next http.Handler) http.Handler {
	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		start := time.Now()
		next.ServeHTTP(w, r)
		log.Printf("%s %s %s %s", r.Method, r.URL.Path, r.Proto, time.Since(start))
	})
}