Fork me on GitHub
#pathom
<
2021-02-12
>
kenny16:02:46

We are running into some serious pathom2 performance issues. We're running 2.3.0. I have APM enabled and can see a crazy amount of request time is eaten up by p/map-reader. It's getting called 40k+ times for a single request. This resolver is returning ~1.5k maps, each with 10+ attributes in them, so I imagine that is what's causing Pathom to spin its wheels. From my resolver, I am adding (with-meta x {::p/final true}) since I remember reading that is how you can force Pathom to not loop through every result attribute. It, however, does not seem to have any impact. This particular query will actually hit 2 resolvers, which could be important. The first returns a list of relevant IDs and the second is a batch? true that returns the 10+ attributes I mentioned earlier. The latter is also the one that wraps its result in ::p/final. Does anyone have an idea on how to fix this?

wilkerlucio17:02:50

hello Kenny, p/map-reader is what reads the data from the entity and places in the final map, 1.5k maps is a lot of maps, if you let Pathom do the sequence processing its likely to add that kind of overhead. How long is the request taking?

wilkerlucio17:02:34

the cases in which I had to deal with large sequences in Pathom 2 was to make the list itself final, so Pathom doenst have to traverse the items, but that would involve pulling the logic out of internal resolvers and manually doing it when you generate the collection, then you make that collection final

kenny17:02:18

That's what I thought I was doing here with p/final.

wilkerlucio17:02:55

since you told me you are using hte batch, so that means pathom still has to process each entry, the final means "dont process futher", but in this case you already in the items of the collection

kenny17:02:07

Not sure I'm following ๐Ÿ™‚ I essentially have this:

(pc/defresolver my-foo-list-resolver
  [env _]
  {::pc/input  #{}
   ::pc/output {:foos [:foo/id]}}
  (let [id-list (get-id-list)]
    {:foos id-list}))

(pc/defresolver my-resolver
  [env xs]
  {::pc/input     #{:foo/id}
   ::pc/output    (get-output-pattern)
   ::pc/transform pc/transform-batch-resolver}
  (let [long-list (get-long-list xs)]
    (with-meta long-list {::p/final true})))

kenny17:02:59

This request will first hit a resolver with returns a list of :foo/ids. Pathom will then call my-resolver in batch mode.

kenny17:02:48

Did you mean pc/batch? and ::p/final won't work together?

wilkerlucio17:02:49

lets think about how pathom does the process, the resolver first returns a list with ids (like you said), then it runs the batch, in this sense, we can see we are allowing pathom to process the sequence items

โœ”๏ธ 1
wilkerlucio17:02:59

and when the sequence is large, you can see a lot of process going on

โœ”๏ธ 1
wilkerlucio17:02:18

the way in which ::p/final can help you, is to avoid process the list, completly

wilkerlucio17:02:59

my-foo-list-resolver is the one who needs to get the final list ready (and with a final meta), this way pathom is cut out, and you can optimize there

wilkerlucio17:02:31

returning ::p/final as the meta in a standard resolver response will never work, because that data is merged "sideways" (pathom gets the resolver response, and merges it in the current entity)

kenny17:02:41

Ohhh. In this case, I cannot use the pathom resolver "graph" at all.

wilkerlucio17:02:01

in this "sideways" process, its already a pathom thing, so there is nothing to "stop" there

wilkerlucio17:02:47

the ::p/final must always comes as part of meta of some sub-data (a map or sequence), because them pathom is still going to start process that path, and if it finds ::p/final, it stops at that point

wilkerlucio17:02:28

examples of valid ways to use ::p/final (writing just the resolver response map for illustration):

; don't process nested list
{:some-large-list ^::p/final [{:col 1} {:col "of"} {:col "items"}]}

; don't process nested map
{:some-large-map ^::p/final {:im "a" :really "long" :map "that" :already "has" :all "the" :data "here"}}

kenny17:02:13

Right. It sounds like they key is that I can't have Pathom call any nested resolvers though.

wilkerlucio17:02:17

I hope Pathom 3 does better (and benchmarks tell so, but still to see a real app improvement from future portings)

wilkerlucio17:02:14

yup, the final is a scape hatch, but then its up to you to make that part faster, this is usually more useful for simple long maps, where you already have the data upfront and pathom is just filtering the result (than you cut the filtering part)

kenny17:02:29

I've been following Pathom 3 ๐Ÿ™‚ Been itching to switch to it but it doesn't sound like it is production ready yet.

wilkerlucio17:02:51

my plan is to announce as a beta soon

wilkerlucio17:02:12

the API is mostly stable (the external ones are, but I'm still reversing myself the right to rename some internals at this point)

kenny17:02:56

What if I call the parser from within my-foo-list-resolver? The ::p/final would apply, correct?

wilkerlucio17:02:15

it would, but if you do that you pretty much paying the same price, just in a different place

wilkerlucio17:02:40

(unless you do the calls in some more optimal way, cutting some corners)

kenny17:02:34

How so? e.g.,

(pc/defresolver my-foo-list-resolver
  [env _]
  {::pc/input  #{}
   ::pc/output {:foos [:foo/id]}}
  (let [id-list (get-id-list)
        long-list (parser env (my-query id-list))]
    {:foos (with-meta long-list {::p/final true})}))

(pc/defresolver my-resolver
  [env xs]
  {::pc/input     #{:foo/id}
   ::pc/output    (get-output-pattern)
   ::pc/transform pc/transform-batch-resolver}
  (let [long-list (get-long-list xs)]
    (with-meta long-list {::p/final true})))

wilkerlucio17:02:54

yeah, that code would pretty much do the same as just letting pathom do it

wilkerlucio17:02:32

because the parser is going to loop over your entities and process than

wilkerlucio17:02:37

that's the same that was happening before

kenny17:02:55

I guess I'm confused why ::p/final would apply then.

wilkerlucio17:02:45

lets come back, my suggestion to use ::p/final depends on you making your own processing for the nested items, that needs to be made faster than how Pathom can do it (which isn't that hard, since you don't have to care about many things that pathom does)

wilkerlucio17:02:05

but if you want to make it faster and optimized, you have to process your collection yourself (without resolvers help)

wilkerlucio17:02:32

that's how ::p/final can be faster, because you let go of using pathom for that portion where you need a faster loop to processa a long sequence (long sequences performance in Pathom 2 isn't that good, Pathom is optimized for complex requests with small output, large outputs pay cost)

wilkerlucio17:02:11

if you have the time, I would love to hear if Pathom 3 can do better, and by how much

wilkerlucio17:02:54

if you are not using many plugins or dynamic resolvers (like graphql stuff), the port to experiment (you can just port this specific part to try out) should be an easy setup to check the difference

wilkerlucio17:02:13

are you using the serial parser, right?

kenny17:02:46

This is our plugins list

[(p/env-plugin (merge {::p/process-error eql-error-handler}
                 base-env))
 (pc/connect-plugin {::pc/register (get-registry)})
 (p/env-wrap-plugin
   (fn [env]
     (merge env (eql-parameter-lookup (::p/root-query env)))))
 p/error-handler-plugin
 ;; removes ::p/not-found from outputs
 (p/post-process-parser-plugin p/elide-not-found)]

wilkerlucio17:02:43

cool, seems simple, just have to port the eql-parameter-lookup, but I guess for the perf testing you can just avoid it

wilkerlucio17:02:12

here you can see the latest benchmark comparisons I did with Pathom versions: https://blog.wsscode.com/pathom-updates-07/

wilkerlucio17:02:23

I really hope some of those can translate in real gains for user apps

kenny17:02:27

My guess it it'd "just work." It just adds some eql info to the env:

(defn eql-parameter-lookup
  [query]
  (let [ast (eql/query->ast query)
        params (into {}
                 (keep (fn [node]
                         (when (seq (:params node))
                           [(:key node) (:params node)])))
                 (:children ast))]
    {:cs.eql/root-query-ast ast
     :cs.eql/ident->params  params}))

wilkerlucio17:02:33

(specially in those cases where CPU gets intensive)

kenny17:02:10

Yeah, I read that and was excited to try it. Primary concern is breakage or any bugs with non-prod lib.

wilkerlucio17:02:00

yeah, I feel you, and I can't say Pathom 3 is prod ready yet, I hope that once the beta is out, we can start porting users to go though the "bug crunch" phase

kenny17:02:09

Someone has to go first... ๐Ÿ˜…

kenny17:02:16

So ultimately, for places where perf is critical, I cannot use Pathom list processing at all. I must "flatten" the resolvers such that all list data is outputted from a single resolver.

wilkerlucio17:02:29

yeah, if you have long lists, there is a lot going on to process details, and unfortunately the implementation for Pathom 2 ends up adding too much in these cases

wilkerlucio17:02:49

that was surely one of my biggest motivations to make Pathom 3, make it faster to extend the use cases where it can work:slightly_smiling_face:

kenny17:02:23

Yep. It looks so awesome. That & the nested map thing look great.

kenny17:02:12

I half inclined to just try 3 since I feel our Pathom setup is very vanilla. Sometimes the bugs can be quite nuanced though, so I am a bit concerned there.

wilkerlucio17:02:41

yeah, the change in processing algorithm is surely scary, because its trading the problem you know for one you don't, and its really hard to know which kind of problems may surface... that said, the only way to find them is trying it out

kenny17:02:24

Yep ๐Ÿ™‚ Did anything change with how errors are handled?

wilkerlucio17:02:57

yes, that's quite different actually, were you using the plugin to pull errors up? (you could be doing on the client), because the easy error path in Pathom 3 looks more like that

wilkerlucio17:02:23

here you can find information on Pathom 3 and errors: https://pathom3.wsscode.com/docs/debugging

kenny18:02:11

Ok. Thanks for the help with identifying the problem here. I have a clear path on how to fix it.

kenny18:02:18

Super excited to try Pathom 3!

๐Ÿ™ 1
nivekuil17:02:04

where do I catch mutation errors in p3? calling (mutation env ast) in wrap-mutate just returns timing stats

wilkerlucio17:02:49

mutation erros come as the mutation result, not sure if you are seeing a bug or missed expectation, can you send an example of what you trying to do?

nivekuil17:02:45

(pco/defmutation subscribe [_ _]        (throw  (ex-info "Error" {})))  ::pcr/wrap-mutate    (fn [mutation]      (fn [env {:keys [key] :as ast}]        (-> (mutation env ast)            (p/then' (fn [result]                       (log/spy result)                       (some-> (get result key)                               ::pcr/mutation-error                               #(u/log ::mutation-error                                       :exception %))                       result) ))))  result => {app.model.subscription/subscribe {:com.wsscode.pathom3.connect.runner/node-run-start-ms 7.5366440645885E7, :com.wsscode.pathom3.connect.runner/mutation-run-start-ms 7.5366440645885E7, :com.wsscode.pathom3.connect.runner/mutation-run-finish-ms 7.5366441060086E7, :com.wsscode.pathom3.connect.runner/node-run-finish-ms 7.5366441089373E7}}

nivekuil17:02:22

can I log the mutation error in that plugin, or should it be somewhere else? the error does appear in the final result returned from from eql/process

wilkerlucio18:02:46

had you tried using catch instead of then to find the error?

wilkerlucio18:02:24

thats an interesting example, I have no code testing async extensions on mutations errors, this may require code changes, or some new docs to explain

nivekuil18:02:30

I admit I actually didn't even try catch, but it still seems to be the same behavior: only the p/then path is taken

(-> (mutation env ast)              (p/then (fn [result]                        (log/spy result)))              (p/catch (fn [result]                         (log/spy result)) ))

wilkerlucio18:02:19

cool, I can't look in it right now, but I'll do later today

wilkerlucio23:02:24

@U797MAJ8M was a bug, fixed on master, here is an example to track and log errors for async runners:

(let [env (-> (pci/register
                (pco/mutation 'foo {} (fn [_ _] (throw (ex-info "Error" {})))))
              (p.plugin/register
                {::p.plugin/id
                 'log

                 ::pcr/wrap-mutate
                 (fn [mutation]
                   (fn [env ast]
                     ; running mutation inside p/do! allow us to use catch to capture both
                     ; sync and async errors
                     (-> (p/do! (mutation env ast))
                         (p/catch (fn [e]
                                    ; log error here, and make sure you return the
                                    ; error at the end
                                    e)))))}))]
  @(p.async.eql/process env ['(foo)]))

nivekuil00:02:57

nice! thanks for the example, didn't know about p/do

wilkerlucio00:02:09

glad to help, also check p/let, I find that super useful

nivekuil01:02:22

I think the last commit has a regression: ast only has the value map of`:params` in it. maybe this should be ast on this line? https://github.com/wilkerlucio/pathom3/blob/1da7457bf65dbcd57cc9a7e98bc7eeee7bf6705b/src/main/com/wsscode/pathom3/connect/runner/async.cljc#L348

nivekuil01:02:32

e.g.

::pcr/wrap-mutate    (fn [mutation]      (fn [env {:keys [key] :as ast}]        (log/info ast)        ...))
ast there is equivalent to the old (get ast :params), so key is nil

wilkerlucio03:02:13

oh, sorry, you are right, this was because I also wanted to enable the user to override the output, and for that I changed the place of invocation of it, fixing it now

mss18:02:07

struggling to get pathom resolvers to reload using tools.namespace.repl w/ pathom 2.3

mss18:02:26

per the fulcro book, Iโ€™ve got my user ns set up something like:

(tools-ns/set-refresh-dirs "src/my_dir")

(def system-atom (atom (server/system :dev)))

(defn start
  []
  (swap! system-atom component/start))

(defn restart
  []
  (swap! system-atom component/stop)
  (tools-ns/refresh :after 'user/start))

mss18:02:26

my parser creation seems p straightforward:

(defn make-parser [system-config env-entities]
  (pathom/parser
    {::pathom/env     (merge {::pathom/reader               [pathom/map-reader
                                                             pathom-connect/reader2
                                                             pathom-connect/open-ident-reader
                                                             pathom-connect/index-reader]
                              ::pathom/placeholder-prefixes #{">"}}
                             env-entities)
     ::pathom/mutate  pathom-connect/mutate
     ::pathom/plugins [(pathom-connect/connect-plugin {::pathom-connect/register (concat parser-mutations/mutations
                                                                                         parser-resolvers/resolvers)})
                       pathom/error-handler-plugin]}))

(defrecord Parser [datomic system-config]
  component/Lifecycle
  (start [component]
    (if-not (:parser component)
      (do
        (timbre/log :info {:message "Instantiating parser"})
        (assoc component :parser (make-parser system-config {:datomic-conn (:conn datomic)})))
      component))
  (stop [component]
    (if (:parser component)
      (do
        (timbre/log :info {:message "Destroying parser"})
        (assoc component :parser nil))
      component)))

mss18:02:31

a new parser is getting instantiated on each call to user/restart and yet if I edit an individual resolver and call user/restart, the resolvers donโ€™t seem to actually be updated with the new code

mss18:02:55

any ideas what I might be missing here? obv I might just be an idiot and this has nothing to do with pathom