Fork me on GitHub
#pathom
<
2020-12-17
>
tony.kay19:12:32

I’ve got a pathom performance problem. I’m hitting a resolver like this:

(defresolver all-products-resolver
  [{:keys [conn ast] :as env} _]
  {::pc/output [{:product/all-products [:product/id
                                        :product/sku
                                        :product/description
                                        :product/precise-price
                                        {:taxable/taxes [:tax/rate :tax/category]}
                                        {:product/tax [:tax/rate :tax/category]}
                                        :product/inventory-tracked?]}]}
  (let [db         (d/db conn)
        company-id (env->effective-company-id env)]
    {:product/all-products (get-all-products db company-id)}))
and the query function on the last line returns exactly what the query asks for. The incoming query is exactly what this resolver outputs. When I measure this the get-all-products takes 680ms, and Pathom takes another 6s to process the result…and it invokes readers 10000 times (I have 10000 products) for every attribute…though those calls are instantly satisfied by map-reader they still consume about 3s of CPU. How do I optimize this to stop abusing Pathom (this is version 2.2.30. I tried 2.3.0 and it was much much much worse for some reason)

tony.kay19:12:50

I was hoping that satisfying the exact query would make pathom just return the result

tony.kay19:12:39

Perhaps this is the kind of thing you’re restructuring in Pathom 3 😄

tvaughan19:12:59

A total shot in the dark, but would it help just to specify :product/all-products in the output, like ::pc/output [:product/all-products]? We have a query that has an output that is a map and we don't specify any of the sub-keys. We only query for the top-level key.

wilkerlucio20:12:15

@tony.kay there is a escape feature for this situation, add the metadata ::p/final true to the list (when returning from the resolver), by doing so Pathom will skip processing it completly

👍 3
🔖 3
tony.kay21:12:16

thanks, I had a vague memory there was an escape hatch, but could not remember

tony.kay22:12:09

no go. Does it matter what order the readers are installed?

tony.kay22:12:12

I added debug breakpts in pathom, and only saw lots of calls to nested resolution..never saw that part of the program ever get the top-level list…

tony.kay22:12:01

Map reader’s where I found that ::p/final, and when I watch what it does, I only ever see the individual nested entities. It never sees the list, so never skips it

tony.kay23:12:26

Yeah, I’m getting into here in connect:

(defn- process-simple-reader-response [{:keys [query] :as env} response]
  (let [key (-> env :ast :key)
        x   (get response key)]
    (cond
      (and query (sequential? x))
      (->> (mapv atom x) (p/join-seq env))

      (nil? x)
      (if (contains? response key)
        nil
        ::p/continue)

      :else
      (p/join (atom x) env))))

tony.kay23:12:39

key is :products/all-products, and x is my list of 10,000 things, but it ignore metadata here and just processes them all anyway…unless, the query is nil

wilkerlucio23:12:57

the thing that takes care of it is the map-reader

tony.kay23:12:28

I’m tracing code with breakpoints

tony.kay23:12:41

that is where I land, and then it does all 10000

wilkerlucio23:12:00

I can't find process-simple-reader-response in pathom, isn't this in your codebase?

tony.kay23:12:16

connect.cljc

wilkerlucio23:12:05

did you tried bumping to 2.3.0? I think that fn got removed

tony.kay23:12:25

no, but 2.3.0 was waaaaay slower

tony.kay23:12:28

can’t risk that in prod

tony.kay23:12:58

I guess I could try and diagnose that, but I’ve already spent 5 hours on what should have been easy optimizations 😄

wilkerlucio00:12:01

ok, let me check on older version to understand

tony.kay00:12:38

I’ll try 2.3 and see if there was something weird

tony.kay00:12:49

pathom 2.3 seems faster

tony.kay00:12:59

let me eval this

tony.kay00:12:19

Yeah, I got one call this time

tony.kay00:12:32

I wonder if it was slower earlire for some other reason

tony.kay00:12:40

I’ll measure some more. Thanks for the help 🙂

wilkerlucio00:12:53

if that gets to a hard problem I can release a hotfix for 2.3.x with a fix for that fn you pointed out

tony.kay00:12:56

I didn’t have the metadata on there earlier

tony.kay00:12:16

so, I do think 2.3 is possibly slower without it. Let me check that

wilkerlucio00:12:50

yeah, if you learn what it is, I would be glad to address, I don't remember any big change that could cause noticeable performance degradation

tony.kay00:12:12

yeah…it’s waaaaaay worse

wilkerlucio00:12:19

but maybe was this change, from moving to inline re-processing to the reader engine

tony.kay00:12:25

I was getting 8s

tony.kay00:12:35

it’s been running for 50s so far

tony.kay00:12:48

and I was getting 2.5s with 2.2.30 with the metadata

tony.kay00:12:04

still running!

tony.kay00:12:20

q: :taxable/taxes                     536   504.60μs    30.54ms    54.41ms    57.27ms    60.14ms    65.60ms    30.09ms  ±50%    16.13s     71%
q: :product/tax                       535   188.04μs    11.61ms    21.51ms    22.96ms    25.35ms    29.50ms    12.01ms  ±51%     6.43s     28%
q: :entity/company                    536    34.74μs    52.49μs    72.69μs    96.27μs   128.20μs   359.06μs    56.05μs  ±23%    30.04ms     0%
q: :tax/category                      535    18.01μs    35.83μs    45.29μs    55.18μs    85.55μs   214.91μs    36.65μs  ±23%    19.61ms     0%
q: :product/precise-price             535    14.47μs    24.50μs    38.12μs    42.49μs    86.47μs   414.02μs    28.26μs  ±31%    15.12ms     0%
q: :tax/rate                          535    13.50μs    20.57μs    38.35μs    44.99μs    71.57μs   106.56μs    25.30μs  ±35%    13.53ms     0%
q: :product/inventory-tracked?        536    12.16μs    20.13μs    36.27μs    41.60μs    77.72μs   103.24μs    23.69μs  ±35%    12.70ms     0%
q: :product/description               535    12.71μs    19.32μs    35.91μs    38.43μs    74.16μs   102.37μs    23.24μs  ±35%    12.43ms     0%
q: :product/id                        536    11.15μs    18.36μs    35.35μs    41.61μs    76.47μs   127.77μs    22.69μs  ±38%    12.16ms     0%
q: :product/sku                       535    11.39μs    19.33μs    35.35μs    38.69μs    77.51μs   104.34μs    22.38μs  ±36%    11.98ms     0%

tony.kay00:12:28

I have minute-by-minute timing in a plugin

tony.kay00:12:41

measuring every call to the reader

tony.kay00:12:00

It can normally do 10,000 of those in a few ms…but with 2.3 it is 10x that

tony.kay00:12:21

I’m seeing 11ms for 500 calls

wilkerlucio00:12:22

I think the reason may be on the switch from inline processing to reader engine, but I wouldn't expect to be that much

tony.kay00:12:31

still running

tony.kay00:12:49

I think it may be 100 to 1000x slower

tony.kay00:12:16

yeah, I def cannot risk that one in prod 😕

tony.kay00:12:23

this would kill us

wilkerlucio00:12:28

if you need I can do a hotfix for that 2.2 to add support for final there

tony.kay00:12:40

yes please 🙂

tony.kay00:12:59

repro case is easy

tony.kay00:12:14

(defresolver all-products-resolver
  [{:keys [conn] :as env} _]
  {::pc/output [{:product/all-products [:product/id
                                        :product/sku
                                        :product/description
                                        :product/precise-price
                                        :taxable/taxes
                                        :product/tax
                                        :product/inventory-tracked?]}]}
  (let [db         (d/db conn)
        company-id (env->effective-company-id env)]
    {:product/all-products (get-all-products db company-id)}))

tony.kay00:12:23

and make get-all-products return 1000 (complete) things

wilkerlucio00:12:38

please try 2.2.31-SNAPSHOT

tony.kay00:12:06

(it’s still running btw)

wilkerlucio00:12:29

this is running on CLJ, right?

wilkerlucio00:12:39

because I wanna do some measurements later, k

tony.kay00:12:17

Intel CPU model

tony.kay00:12:31

not the latest, but no slouch

wilkerlucio00:12:44

ah, ok, just wanted to make sure I'm doing the tests in the same env (clj vs cljs)

wilkerlucio00:12:59

please let me know if that works, if so I'll release 2.2.31

tony.kay00:12:54

I had to restart, and this thing is rather large…takes a min

wilkerlucio00:12:26

no worries and no rush 🙂

tony.kay00:12:29

cognitect.transit/write              transit.clj:  167
                 com.cognitect.transit.impl.WriterFactory$1.write       WriterFactory.java:   62
                      com.cognitect.transit.impl.JsonEmitter.emit         JsonEmitter.java:   41
            com.cognitect.transit.impl.AbstractEmitter.marshalTop     AbstractEmitter.java:  211
               com.cognitect.transit.impl.AbstractEmitter.marshal     AbstractEmitter.java:  184
               com.cognitect.transit.impl.AbstractEmitter.emitMap     AbstractEmitter.java:   85
                   com.cognitect.transit.impl.JsonEmitter.emitMap         JsonEmitter.java:  171
               com.cognitect.transit.impl.AbstractEmitter.marshal     AbstractEmitter.java:  194
       java.lang.Exception: Not supported: class clojure.lang.Atom
java.lang.RuntimeException: java.lang.Exception: Not supported: class clojure.lang.Atom

tony.kay00:12:44

atom flowed through

wilkerlucio00:12:06

ah, I know what is

wilkerlucio00:12:21

sorry, minor mistake, releasing again

tony.kay00:12:29

I should have cloned and run local/root so I could pull and jsut refresh instead of restarting 😕

wilkerlucio00:12:42

its on this branch if you wanna pull local

tony.kay00:12:35

did u push?

tony.kay00:12:35

k…just a min

wilkerlucio00:12:39

arg, it trigerred reformat, messy diff, going to fix, but the code should be correct

tony.kay00:12:46

that got it

tony.kay00:12:19

network request now 800ms

tony.kay00:12:30

including data transfer

wilkerlucio00:12:36

I'm doing a few changes because I'm afraid the current impl may try to call meta in values it shouldn't

tony.kay00:12:53

ok, I’m running local/root so much faster to test now

wilkerlucio00:12:07

oh, I think its fine, I though (meta nil) would break, but it works

wilkerlucio00:12:21

unless you find some issue, I'm ok to release the 2.2.31

tony.kay00:12:53

your branch name is weird

wilkerlucio00:12:05

yeah... its wrong

tony.kay00:12:17

so as long as the code is right, it should be ok

tony.kay00:12:23

I mean version *

wilkerlucio00:12:49

its fine, I'll just remove it after

wilkerlucio00:12:55

and has the tag to get back to this version if needed

tony.kay00:12:04

I clicked around a bit

tony.kay00:12:11

and other stuff seems to be slower now

tony.kay00:12:37

any idea why that might be?

tony.kay00:12:22

basically it looks like similar queries that don’t have the metadata are slower now

tony.kay00:12:27

by a noticeable amount

tony.kay00:12:40

are you making a bunch of new atoms to fix this?

tony.kay00:12:58

or rather, without the metadata would it have new overhead?

wilkerlucio00:12:15

nope, it should be simple

wilkerlucio00:12:23

I just made another version, with an even simpler change

wilkerlucio00:12:49

try the current on that branch

tony.kay00:12:12

ok, yeah, looks good. I bounced back to .31 and that page was just as slow, so false alarm

wilkerlucio00:12:38

hey, I just did a comparison between 2.2 and 2.3 processing a 10k size list

wilkerlucio00:12:52

(ns com.wsscode.demos.perf
  (:require [com.wsscode.pathom.connect :as pc]
            [criterium.core :as c]
            [com.wsscode.pathom.core :as p]))

(pc/defresolver long-list [env _]
  {::pc/output [:items]}
  {:items (mapv #(hash-map :id 1) (range 10000))})

(pc/defresolver x [env {:keys [id]}]
  {::pc/input #{:id}
   ::pc/output [:x]}
  {:x (* 10 id)})

(def registry [long-list x])

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

(comment
  (c/with-progress-reporting
    (c/quick-bench
      (parser {} [{:items [:x]}]))))

wilkerlucio00:12:08

Pathom 2.2: Execution time mean : 93.091257 µs

wilkerlucio00:12:24

Pathom 2.3: Execution time mean : 97.180679 µs

wilkerlucio00:12:52

so aparently its not just something about the reader process, I wonder if there is something around custom plugins or anything that got affected to make such difference in your case

tony.kay01:12:36

I think you need each item to have props

tony.kay01:12:54

mine has 3 levels of depth, but you’re right, it could be a plugin

tony.kay01:12:12

I did not actually measure real overhead

tony.kay01:12:27

(of every bit)

tony.kay01:12:09

should final work ok with siblings?

wilkerlucio01:12:50

ah, I think I had an error on the measure, got redo

wilkerlucio01:12:55

what you mean siblings?

tony.kay01:12:57

query [{:a […]} {:other […]}]..can both siblings say final?

tony.kay01:12:08

on their lists of return values

tony.kay01:12:23

i.e. resolver for :a and :other

wilkerlucio01:12:05

yeah, you can make any list or a map final

tony.kay01:12:47

ok, yeah, I think that is working…I’ve peppered it around and broke something, so was verifying I understood

tony.kay01:12:20

@wilkerlucio could you push that to clojars? (at least the snapshot)?

tony.kay01:12:30

I want to try on my staging server, and it won’t have local root

tony.kay01:12:56

the last one you did

tony.kay01:12:12

I’m at 58b3d629e6ef464199a06d7fcde627c403fa9d59

wilkerlucio01:12:54

pushed snapshot for you to try on staging

tony.kay01:12:58

Did you see phronmophobic on #fulcro getting Fulcro working with Swing (I think…maybe AWT) 🙂

tony.kay01:12:14

entertaining

wilkerlucio01:12:08

wow, didn't, that's cool!

wilkerlucio01:12:31

(snapshot ends in -3, if you need to confirm during some pipeline)

tony.kay01:12:53

yeah, not retrieving yet…clojars must be slow

tony.kay01:12:50

duh…should just use a frikkin sha

tony.kay16:12:54

This seems to be a problem in dev now. If I reload all nses for dev work, it pulls in pathom, which pulls in gen, which unfortunately pulls in Fulcro 2 stuff:

#error{:cause "Could not locate fulcro/client/primitives__init.class, fulcro/client/primitives.clj or fulcro/client/primitives.cljc on classpath.",
       :via [{:type clojure.lang.Compiler$CompilerException,
              :message "Syntax error compiling at (com/wsscode/pathom/gen.cljc:1:1).",
              :data #:clojure.error{:phase :compile-syntax-check,
                                    :line 1,
                                    :column 1,
                                    :source "com/wsscode/pathom/gen.cljc"},
              :at [clojure.lang.Compiler load "Compiler.java" 7647]}
             {:type java.io.FileNotFoundException,
              :message "Could not locate fulcro/client/primitives__init.class, fulcro/client/primitives.clj or fulcro/client/primitives.cljc on classpath.",

tony.kay16:12:39

but you didn’t change anything in this rev…

tony.kay16:12:50

hm, perhaps I’ll try 2.3.0 w/guardrails disabled 🙂

👍 3
wilkerlucio20:12:37

the reason is pathom don't know its exact data, so it has to scan anyway, doing a check for each data shape could have a similar cost, with the user declaration Pathom accepts that the user know more about it, and just skips processing

wilkerlucio20:12:43

@tvaughan better to always keep the nested on the output, it doesn't affect running in any way, but improves the intelisense of pathom viz for queries (better auto-complete)

tvaughan20:12:32

Good to know. Thanks @wilkerlucio