Resolver Tracing

When scaling a service, it is invaluable to know where queries are spending their execution time; Lacinia can help you here; when enabled, Lacinia will collect performance tracing information compatible with Apollo GraphQL.

Timing collection is enabled by passing the context through the com.walmartlabs.lacinia.tracing/enable-tracing function:

(require '[com.walmartlabs.lacinia :as lacinia]
          [com.walmartlabs.lacinia.tracing :as tracing])

(def start-wars-schema ...)

(lacinia/execute
  star-wars-schema "
  {
    luke: human(id: \"1000\") { friends { name }}
    leia: human(id: \"1003\") { name }
  }"
  nil
  (tracing/enable-tracing nil))
=>
{:data {:luke {:friends [{:name "Han Solo"}
                         {:name "Leia Organa"}
                         {:name "C-3PO"}
                         {:name "R2-D2"}]},
        :leia {:name "Leia Organa"}},
 :extensions {:tracing {:version 1,
                        :startTime "2020-08-31T22:14:25.401Z",
                        :endTime "2020-08-31T22:14:25.449Z",
                        :duration 47430231,
                        :parsing {:startOffset 68824, :duration 38932608},
                        :validation {:startOffset 39099642, :duration 1941960},
                        :execution {:resolvers [{:path [:luke],
                                                 :parentType :Query,
                                                 :fieldName :human,
                                                 :returnType "Human!",
                                                 :startOffset 42476480,
                                                 :duration 303264}
                                                {:path [:luke :friends],
                                                 :parentType :Human,
                                                 :fieldName :friends,
                                                 :returnType "[Character]",
                                                 :startOffset 43183550,
                                                 :duration 185802}
                                                {:path [:luke :friends 0 :name],
                                                 :parentType :Human,
                                                 :fieldName :name,
                                                 :returnType "String",
                                                 :startOffset 43669784,
                                                 :duration 16145}
                                                {:path [:luke :friends 1 :name],
                                                 :parentType :Human,
                                                 :fieldName :name,
                                                 :returnType "String",
                                                 :startOffset 44205401,
                                                 :duration 4629}
                                                {:path [:luke :friends 2 :name],
                                                 :parentType :Droid,
                                                 :fieldName :name,
                                                 :returnType "String",
                                                 :startOffset 44346489,
                                                 :duration 4563}
                                                {:path [:luke :friends 3 :name],
                                                 :parentType :Droid,
                                                 :fieldName :name,
                                                 :returnType "String",
                                                 :startOffset 44477160,
                                                 :duration 3971}
                                                {:path [:leia],
                                                 :parentType :Query,
                                                 :fieldName :human,
                                                 :returnType "Human!",
                                                 :startOffset 46609256,
                                                 :duration 130413}
                                                {:path [:leia :name],
                                                 :parentType :Human,
                                                 :fieldName :name,
                                                 :returnType "String",
                                                 :startOffset 46866059,
                                                 :duration 7833}]}}}}

Extensions key?

GraphQL supports a third result key, extensions, as described in the spec. It exists just for this kind of extra information in the response.

Note that tracing is an execution option, not a schema compilation option; it’s just a matter of setting up the application context (via enable-tracing) before parsing and executing the query.

When the field resolvers are asynchronous, you’ll often see that the startOffset and duration of multiple fields represent overlapping time periods, which is exactly what you want.

Generally, resolver tracing maps are added to the list in order of completion, but the exact order is not guaranteed.

Enabling tracing adds a lot of overhead to execution and parsing, both for the essential overhead of collecting the tracing information, but also because certain optimizations are disabled when tracing is enabled; for example default field resolvers (where no explicit resolver is provided) are heavily optimized normally, to avoid unecessary function calls and object creation.

Warning

Tracing should never be enabled in production. This can be accomplished by removing the com.walmartlabs.lacinia.pedestal2/enable-tracing-interceptor interceptor from the pipeline (when using lacinia-pedestal).