Instrumenting graphql-js for Query Timing
One of my dreams is to write a short blog post. I have high hopes this will be one!
In the reactiflux discord chat I noticed some talk about instrumenting GraphQL to get timing information on query execution. This sounded neat so I gave it a shot in
A gist of the code snippets is here and the output it produces looks like such:
When GraphQL executes it walks the query executing the schema resolve functions along the way. The information we are interested in is how long each resolve function takes to execute. This can be accomplished by wrapping the resolve function.
Viewer#todos is resolved a new timing entry will be added to
timings. Adding it to an array is not very exciting but imagine logging it or putting it in some stats / metrics system. You get the idea!
But what if we want this for every field? It would be annoying to manually add this on every entry. Instead we can walk the schema and wrap resolve functions along the way.
graphql-js schema maintains a map of name to type of all of its types. This can be accessed via
Schema#getTypeMap. Each object type then has a map of name to fields for all of its fields. This can be accessed via
Type#getFields. Using these two methods we can walk over every single field of our schema and wrap resolve functions along the way.
Since we wrap every resolve function we can no longer rely on
graphql-js to handle
null resolve functions with a default for us. Instead we explicitly add the
defaultResolveFn if the resolve is
Also, since you have the type and field information handy you could filter down even further which fields you want to get timing information on. For example if all of your resolve functions which return scalars are just fields on the parent object you could exclude them from your timing.
The schema being data you can work with opens this up. Just be careful that you only wrap the schema once. You are mutating the schema in place – not returning a new schema.
At the end of the day all we are doing is function composition. This means we don’t have to stop at a single resolve wrapper.
In this case we are getting timing information, adding a random delay, logging resolves, and wrapping the result in a promise (simplifies other functions if they can assume promise).
Exposing in Response
GraphQL allows adding keys to the response beyond
errors. We can add one for timing if we wanted to expose this information in the response.
This is a bit hacky in that we need some kind of per-request context that is both accessible to the resolve functions as well as the
graphql-js has an execution context that is per request and provided to every resolve function (its part of the third argument to resolve). Unfortunately I’m not aware of a way for the
graphql caller to get this information.
But that same third argument includes the
rootValue which the caller most definitely has access to. So we’ll use that.
And then in our resolve function we’ll push timing information into this part of the
Our graphql result now includes a third key:
So the two key ideas here are:
graphql-jsschema is data you can inspect and work with
- resolve functions are just functions and you can compose them
The composition stuff is equally useful for authorization – another frequent GraphQL how-do-I question.
Finally – should you do this? GraphQL is a thin abstraction over your data store. Maybe you should be timing your data store instead? For instance am I better off knowing how long
db.getTodos takes instead of my
User.todos resolve function? I don’t know, but you can’t go wrong timing both! And even if you only time one the fact that GraphQL makes it so easy to time everything makes it pretty attractive as a starting point.