Resolver Timing

Caution

This feature is experimental, and subject to change. Feedback is encouraged!

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 start and finish timestamps, and elapsed time, for each resolver function that is invoked during execution of the query.

Timing collection is enabled using the key, :com.walmartlabs.lacinia/enable-timing?, in the application context:

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

(lacinia/execute
  star-wars-schema "
  {
    luke: human(id: \"1000\") { friends { name }}
    leia: human(id: \"1003\") { name }
  }"
  nil
  {::lacinia/enable-timing? true})
=>
{:data {:luke {:friends [{:name "Han Solo"}
                         {:name "Leia Organa"}
                         {:name "C-3PO"}
                         {:name "R2-D2"}]}
        :leia {:name "Leia Organa"}}
 :extensions
 {:timings
  [{:start "1493245557504" :finish "1493245557514" :elapsed 10 :path [:luke]}
   {:start "1493245557507" :finish "1493245557519" :elapsed 12 :path [:leia]}
   [:start "1493245557515" :finish "1493245557555" :elapsed 40 :path [:luke :friends]]]}}

The :timings extension key is a list of timing records.

When the field resolvers are asynchronous, you’ll often see start and finish times for each invocation overlap. The finish time is calculated not when the resolver function returns, but when it produces a value (that is, when the ResolverResult is realized).

By carefully looking at the start and end times, we can see that the luke and leia fields ran simultaneously, and that the friends field (under luke) executed only after luke completed.

Although the total elapsed time across the three fields was 62 ms, some of that time overlapped, and the overall request processing time was approximately 51ms.

Timing information is only collected for fields with an explicit field resolver, and when the elapsed time is less than 2ms, the tracking data is discarded. This allows you to focus on non-trivial resolvers.

The start and finish times are in a standard format, milliseconds since the epoch.

As with errors and warnings, the path reflects the query path, using aliases provided by the client query when appropriate.

Generally, timing records are added to the list in order of completion, but the exact order is not guaranteed.