Seeing odd resolver timing in Pathom Viz

[telekid]

I'm experimenting with Pathom to determine whether it might be appropriate for an upcoming project.

I've created a query that calls a resolver 4 times, and am noticing that Pathom Viz is reporting that the final trace of a resolver is taking ~200ms. (The first three times it is called, it only takes ~2ms.) I don't think this has anything to do with the resolver itself. Have you run across this elsewhere?

[wilkerlucio]

Hello, I haven't seen this kind of problem, that purple time is really around the resolver call, you can try to measure yourself with other tools, but not any known issue.

[wilkerlucio]

Have you ran this multiple times? is this consistent? if it is could be something related to the specific data that somehow is taking more time. This can vary widely depending on the implementation code.

[telekid]

It is consistent across ~20 simulated requests. I'll manually instrument the resolvers to see if there is a difference between the times reported by pathom and the times I record.

(Also, thanks for such an amazing project! I've enjoyed working with it so far.)

[wilkerlucio]

Sure, if you find something, please send a reproducing example.

[telekid]

After wrapping all of my resolvers in (time ...):

Running query :cis-by-fids
"Elapsed time: 1.365581 msecs"
Running query :cis-by-fids
"Elapsed time: 0.977427 msecs"
Tue Aug 31 17:35:44 EDT 2021 WARN :com.wsscode.pathom3.connect.runner/event-batch-unsupported - {:com.wsscode.pathom3.path/path [:root/cis-by-fids 0 :ci/line-items 0], :com.wsscode.pathom3.connect.operation/op-name resolver/commercial-invoice-line-item}
Running query :ci-line-items-by-fids
"Elapsed time: 0.848828 msecs"
Tue Aug 31 17:35:44 EDT 2021 WARN :com.wsscode.pathom3.connect.runner/event-batch-unsupported - {:com.wsscode.pathom3.path/path [:root/cis-by-fids 0 :ci/line-items 1], :com.wsscode.pathom3.connect.operation/op-name resolver/commercial-invoice-line-item}
Running query :ci-line-items-by-fids
"Elapsed time: 0.947896 msecs"
Tue Aug 31 17:35:44 EDT 2021 WARN :com.wsscode.pathom3.connect.runner/event-batch-unsupported - {:com.wsscode.pathom3.path/path [:root/cis-by-fids 1 :ci/line-items 0], :com.wsscode.pathom3.connect.operation/op-name resolver/commercial-invoice-line-item}
Running query :ci-line-items-by-fids
"Elapsed time: 0.869188 msecs"
Tue Aug 31 17:35:45 EDT 2021 WARN :com.wsscode.pathom3.connect.runner/event-batch-unsupported - {:com.wsscode.pathom3.path/path [:root/cis-by-fids 1 :ci/line-items 1], :com.wsscode.pathom3.connect.operation/op-name resolver/commercial-invoice-line-item}
Running query :ci-line-items-by-fids
"Elapsed time: 1.054728 msecs"
repl> 

Note that no resolver took longer than ~1ms.

Perhaps it has something to do with nested batch queries?

If I have time, I'll see if I can create a small reproducable version. In the meantime, these are my resolvers:

(pco/defresolver eos-by-fids
  [env m]
  {::pco/input []
   ::pco/output [{:root/eos-by-fids [:eo/fid]}]}
  (time
   (let [fids (:fids (pco/params env))
         query-results ((:run-query env) :eos-by-fids fids)]
     {:root/eos-by-fids query-results})))

(pco/defresolver eo
   [env ms]
   {::pco/input [:eo/fid]
    ::pco/output [:eo/created-at :eo/shipment-flex-id]
    ::pco/batch? true}
  (time
   (let [fids (map :eo/fid ms)
         query-results ((:run-query env) :eos-by-fids fids)]
     query-results)))

(pco/defresolver cis-by-fids
  [env m]
  {::pco/input []
   ::pco/output [{:root/cis-by-fids [:ci/fid]}]}
  (time
   (let [fids (:fids (pco/params env))
         query-results ((:run-query env) :cis-by-fids fids)]
     {:root/cis-by-fids query-results})))

(pco/defresolver ci
  [env ms]
  {::pco/input [:ci/fid]
   ::pco/output [:ci/fid :ci/total-price :ci/line-items]
   ::pco/batch? true}
  (time
   (let [fids (map :ci/fid ms)
         query-results ((:run-query env) :cis-by-fids fids)
         cis (map (fn [query-result]
                    (merge (select-keys query-result [:ci/fid :ci/total-price])
                           {:ci/line-items (map (fn [fid] {:ci-line-item/fid fid})
                                                (:ci/line-item-fids query-result))}))
                  query-results)]
     cis)))

(pco/defresolver ci-line-item
  [env ms]
  {::pco/input [:ci-line-item/fid]
   ::pco/output [:ci-line-item/desc :ci-line-item/fid :ci-line-item/price]
   ::pco/batch? true}
  (time
   ((:run-query env) :ci-line-items-by-fids (map :ci-line-item/fid ms))))

and this is the query:

[{(:root/cis-by-fids {:fids ["fid::core:commercial_invoice:1"
                             "fid::core:commercial_invoice:2"]})
  [:ci/fid
   :ci/total-price
   {:ci/line-items [:ci-line-item/desc :ci-line-item/fid]}]}]

[wilkerlucio]

I see you are using some lazy sequences in the process, those can make the performance reporting inaccurate, because they will process later, try replacing every map with mapv. Also, batch requires vectors to be efficient, a batch using lists won't actually work (and you should be seeing some warning on the REPL about those).

Edit: I see they are showing up, like: Tue Aug 31 17:35:45 EDT 2021 WARN :com.wsscode.pathom3.connect.runner/event-batch-unsupported - {:com.wsscode.pathom3.path/path [:root/cis-by-fids 1 :ci/line-items 1], :com.wsscode.pathom3.connect.operation/op-name resolver/commercial-invoice-line-item} R

[wilkerlucio]

Using lazy seqs, your time is measuring the time just to build the lazy sequence, not to process its items.

[wilkerlucio]

Also, I see your batch things are just doing standard computation, I recommend using batch only when you can really leverage the multiple values at once (calling an external API with multiple inputs for example), if you are just mapping over internally, its better to let Pathom do it, because there are extra costs associated with batch, and they will diminish performance compared to leaving Pathom to map over them.

Edit: Ah, sorry, I misread your code, seems like you are using all the ids for a query, in that case it makes sense for batch 👍

[telekid]

Using lazy seqs, your time is measuring the time just to build the lazy sequence, not to process its items.

Ah, thanks, of course. Oldest footgun in the book. I'll take another stab at it.

[telekid]

Haven't gotten to the bottom of this, but I'll close the issue for now.