Tracing

The Pathom tracer works as an event stream; you can inject log events at any time, events might have duration or not (even for events with start and finish, they are recorded as separated events and are combined in a post-processing operation).

This enables detailed logs which are helpful in understanding (and debugging) what happens during the processing of a query and pathom core already has some system level tracing logs which are added automatically; you can, of course, add yours as well.

To enable the tracing mechanism, you must add the plugin p/trace-plugin to your parser plugins vector.

Logging custom events

To log custom events you use the functions pt/trace, pc/trace-enter, pt/trace-leave or the pt/tracing macro.

Here is an example parser with some interesting tracing details, run the query to have a look:

(ns com.wsscode.pathom.book.tracing.demo
  (:require [com.wsscode.pathom.core :as p]
            [com.wsscode.pathom.connect :as pc]
            [com.wsscode.pathom.trace :as pt]
            [clojure.core.async :as async]
            [com.wsscode.common.async-cljs :refer [go-catch <?]]))

(pc/defresolver slow-root [env _]
  {::pc/output [::slow-root]}
  (go-catch
    ; here we use the tracing macro to compute the time for the timeout
    (pt/tracing env {::pt/event ::my-event
                     ::pt/style {:fill "rgba(255, 255, 0, 0.5)"}}
      (<? (async/timeout 200)))
    {::slow-root "foo"}))

(pc/defresolver slow-root-dep [env _]
  {::pc/input #{::slow-root}
   ::pc/output [::root-dep]}
  (go-catch
    (pt/tracing env {::pt/event ::my-event}
      (<? (async/timeout 200)))
    {::root-dep "nah"}))

(pc/defresolver error-root-dep [env _]
  {::pc/input #{::slow-root}
   ::pc/output [::root-dep-err]}
  (go-catch
    (pt/tracing env {::pt/event ::my-event
                     ::pt/style {:fill "rgba(255, 0, 0, 0.5)"}
                     ::data     "Error message"}
      (<? (async/timeout 200)))
    (throw (ex-info "Meh" {}))))

(def app-registry [slow-root slow-root-dep error-root-dep])

; to display the tracing with the results you must register the event type
(defmethod pt/trace-tree-collect ::my-event [x row]
  (-> row
      ; the sequence at the end is a list with the keys to display in the trace when
      ; user mouses over the event
      (pt/tree-assoc-detail x [::data])))

(def parser
  (p/parallel-parser
    {::p/env     {::p/reader               [p/map-reader
                                            pc/parallel-reader
                                            pc/open-ident-reader
                                            p/env-placeholder-reader]
                  ::p/placeholder-prefixes #{">"}}
     ::p/mutate  pc/mutate-async
     ::p/plugins [(pc/connect-plugin {::pc/register app-registry})
                  p/error-handler-plugin
                  p/trace-plugin]}))

; to get raw tracing results, include the :com.wsscode.pathom/trace key in your query
(parser {} [:a :b
            :com.wsscode.pathom/trace])

;=>
;{:com.wsscode.pathom/trace
; {:start 0,
;  :path [],
;  :duration 5049,
;  :details [{:event "process-pending",
;             :duration 0,
;             :start 1,
;             :provides #{:com.wsscode.pathom/trace},
;             :merge-result? false}
;            {:event "flush-watchers-loop", :duration 0, :start 1}
;            {:event "reset-loop",
;             :duration 0,
;             :start 1,
;             :loop-keys [:com.wsscode.pathom/trace]}
; ...
[:com.wsscode.pathom.book.tracing.demo/root-dep :com.wsscode.pathom.book.tracing.demo/root-dep-err]

Trace process pipeline