Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Lacinia hangs on parallel batching and non-batching queries #12

Closed
bday2009 opened this issue Sep 29, 2020 · 28 comments · Fixed by #17
Closed

Lacinia hangs on parallel batching and non-batching queries #12

bday2009 opened this issue Sep 29, 2020 · 28 comments · Fixed by #17

Comments

@bday2009
Copy link

bday2009 commented Sep 29, 2020

Hello there. First of all, thank you for this awesome library, its the only one I could find that does what I need and supports lacinia out of the box. I'm having some issues using it for a SQL-backed GraphQL API. It's based on the pet example in this repo, I added one more query to fetch a single record. It's a very naive implementation as I'm not sure how to approach this. Ultimately I'd like to have different mechanisms of resolving customer addresses for single non-batching (customer_by_id) and batching (customers) cases. I haven't achieved this, in the example below, both cases use the same query select * from addresses where customer_id in, and the API hangs inconsistently when I send parallel queries. Hope to get some guidance on this. Thank you in advanced.

This is an excerpt of my schema:

 :objects
 { :Customer
  {:fields {:id          {:type (non-null UUID)}
            :external_id {:type (non-null String)}
            :full_name   {:type (non-null String)}
            :updated_at  {:type (non-null Timestamp)}
            :created_at  {:type (non-null Timestamp)}
            :addresses   {:type    (list Address)
                                  :resolve :get-customer-addresses}}}

  :Address
  {:fields {:id           {:type (non-null UUID)}
                ...
               :created_at   {:type (non-null Timestamp)}
               :updated_at   {:type (non-null Timestamp)}}}}

:queries
{
  :customers      {:type    (list Customer)
                            :resolve :get-customers}
  :customer_by_id {:type    Customer
                               :args    {:id {:type UUID}}
                               :resolve :get-customer-by-id}}

My resolvers:


(s/def-fetcher GetCustomers []
  (fn [_this {:keys [db]}]
    (cdb/get-all-customers db)))

(defn get-customers [ctx _ _]
  (with-superlifter ctx
    (-> (s/enqueue! (->GetCustomers))
        (s/add-bucket! :customer-addresses
                       (fn [customers]
                         {:triggers {:queue-size {:threshold (count customers)}}})))))

(s/def-superfetcher GetCustomerAddresses
  [id]
  (fn [many {:keys [db]}]
    (println (str "Combining " (count many) " requests"))
    (let [customer-ids (map :id many)
          addresses    (adb/by-customer-ids db customer-ids)]
      (as-> addresses $
        (group-by :customer-id $)
        (map $ customer-ids)
        (vec $)))))

(defn get-customer-addresses
  [ctx _ parent]
  (with-superlifter ctx
    (s/enqueue! :customer-addresses (->GetCustomerAddresses (:id parent))))

;; My naive implementation of single record fetch. I'm not entirely sure about this
(defn get-customer-by-id
  [{:keys [db]} {:keys [id]} _]
  (cdb/by-id db id))

I go to graphiql and do send this combined query:

query {
  customers {
    id
    addresses {
      id
    }
  }
  
  customer_by_id(id: "a1f5dab8-7e2c-4aec-be23-7b5ce1c5a486") {
    id
    addresses {
      id
    }
  }
}

Half of the times, it resolves just fine (when the second query resolves first). Other half, the request hangs with pending status. If I do the queries separately, they resolve fine.

INFO  io.pedestal.http  - {:msg "POST /api", :line 80}
Combining 1 requests
Combining 4 requests
INFO  io.pedestal.http  - {:msg "POST /api", :line 80}
Combining 1 requests
Combining 4 requests
INFO  io.pedestal.http  - {:msg "POST /api", :line 80}
Combining 4 requests <------ HANG
@bday2009 bday2009 changed the title Inconsistent behaviors in parallel lacinia queries Lacinia hangs on parallel batching and non-batching queries Sep 29, 2020
@oliyh
Copy link
Owner

oliyh commented Sep 29, 2020

Hi,

Thanks for the detailed report. I'll have to look into it closely, but my first instinct is that the pedestal interceptor is starting a superlifter instance per request, but as you have two queries in your request it would be shared between them, possibly in parallel, and I suspect that to be the cause of the issues. Perhaps it should create an instance per query - this should be possible by inspecting the lacinia payload.

@bday2009
Copy link
Author

bday2009 commented Oct 1, 2020

I wasn't sure if that was the case as I couldn't replicate the issue on your pet example, also my knowledge of dataloader & urania is limited. But now that I have more time to think about it, sharing the same superlifter via multiple parallel queries would probably cause other subtle problems (i.e two parallel resolvers sharing the same bucket). So perhaps separating them is the way to go no matter what?

I found out you can get the query info via ::com.walmartlabs.lacinia.constants/parsed-query in the context map passed to the lacinia resolver. I don't know how to bind all of the required superlifter instances to pedestal context map just yet. Then we can probably give the query name to pedestal's with-superlifter macro so that it gets the correct instance:

  (with-superlifter ctx :get-customers
    (-> (s/enqueue! (->GetCustomers))
        (s/add-bucket! :customer-addresses
                       (fn [customers]
                         {:triggers {:queue-size {:threshold (count customers)}}})))))

Being a clojure newbie, I would love to hear what you think. Thanks!

@bday2009
Copy link
Author

bday2009 commented Oct 1, 2020

Looking closer at lacinia API, I found out you can write to the context map in a way so that only nested resolvers have access to the added keys: resolve/with-context https://github.com/walmartlabs/lacinia/blob/master/src/com/walmartlabs/lacinia/resolve.clj#L66

I feel this is the better way to inject superlifter.

@oliyh
Copy link
Owner

oliyh commented Oct 7, 2020

I've looked into this a bit and I found I could get inconsistent results when running multiple queries at the same time, but it didn't lock up for me.

I started to look into how to create a superlifter per query but it's not as straightforward as I'd hoped. My plan was to create a superlifter per query at the pedestal interceptor layer with a key that could then be derived from the lacinia context inside the resolvers, meaning that the with-superlifter api wouldn't have to change. The alternative is that no superlifter instances are created up-front and instead the first call to with-superlifter would create it on demand for the lacinia context and then bind it using with-context or similar as you suggest, but that may lose the shutdown hook that we need to stop them afterwards.

@oliyh
Copy link
Owner

oliyh commented Oct 13, 2020

One more thing to mention in the meantime is I would generally recommend a time trigger just as a way of avoiding hanging indefinitely in unexpected scenarios. It could be a big interval, like 500ms.

@bday2009
Copy link
Author

bday2009 commented Oct 23, 2020

I have been busy at my job and haven't got the time to work on my side project for the past two weeks.
Yesterday I tried adding 1 sec interval as you suggested and it did cut off the hanging after 1 second. To my surprise, I got the correct number of records back.
I also found out that if one of my parallel resolver results in an error, the parallel queries hang consistently (it just hangs without letting me know what the error is). I wonder if this is related.

These only happen in cases where my parallel resolvers trigger buckets with the same ID (in the above case, its :customer-addresses)

@oliyh
Copy link
Owner

oliyh commented Oct 23, 2020

Hi,

Could you try 0.1.2-SNAPSHOT? (Something weird has happened with the version numbers, but this is the latest). You will hopefully see a warning "Overwriting bucket" which was added in #15 and is what I think was happening to you. Similarly the discussion in #13 also seems to be related, meaning that this is in the general case related to reusing buckets.

While #15, or having a separate superlifter per query would probably solve your issue here, it's not the most elegant and would also make it slightly less efficient. I'm going to have a think about how to solve #13 which I hope will fix your use case too.

The hanging on error I think is probably a different issue - the promise should be rejected and it should be able to continue in the normal way. I'll check this separately.

Thanks

@bday2009
Copy link
Author

bday2009 commented Oct 24, 2020

I upgraded to 0.1.2-SNAPSHOT, enable debug logging for superlifter in logback, and strangely the bug was gone.
So I reverted to the old version, trying to reproduce it again and I could no longer trigger the error case.

After a few hours, I found out that the change in logging config was the reason why the bug went away. I can reproduce the bug consistenly now with my old logging config (default level = info, debug on my application namespace). No bugs on the new config (default level = info, debug on my application namespace + superlifter).

I'm using unilog now but I don't think that matters, because the bug was there long before I added unilog dependency.

@oliyh
Copy link
Owner

oliyh commented Oct 24, 2020

Hi @bday2009

If I understand correctly, it does not hang when you log superlifter at debug with 0.1.2? And that with 0.1.2-SNAPSHOT it does not hang regardless of logging levels?

Are you seeing 'overwriting bucket' in your logs? And does that happen just before a hang?

Thanks for helping me get to the bottom of all this.

@bday2009
Copy link
Author

Hi there,

It hangs on both versions when I changed the logging level for superlifter. I should have written "After a few hours, I found out that the change in logging config was the sole reason why the bug went away, not the change in version" :)

When I was on 0.1.2-SNAPSHOT with superlifter log level = debug, I didn't see 'overwriting bucket' and there was no hang up at all (bugs gone).
When I was on 0.1.2-SNAPSHOT with superlifter log level = info, the bug surfaces again. But I couldn't see 'overwriting bucket' anyway because of the log level.

@oliyh
Copy link
Owner

oliyh commented Oct 27, 2020

I think I was able to reproduce this with parallel queries and just a size trigger on the bucket. I have some ideas about the cause too so I think I can make some progress on this.

Thanks again for your input

oliyh added a commit that referenced this issue Nov 10, 2020
@oliyh
Copy link
Owner

oliyh commented Nov 10, 2020

Starting bucket :default
Starting 1 triggers
Starting trigger :queue-size {:threshold 1}
Enqueing (#example.server.FetchPets{})
Watching queue size 1 1 {:triggers {:queue-size {:threshold 1}}, :queue #atom[[#object[urania.core.Map 0x426d89a1 urania.core.Map@426d89a1]] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Going to fetch {:triggers {:queue-size {:threshold 1}}, :queue #atom[[#object[urania.core.Map 0x426d89a1 urania.core.Map@426d89a1]] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching bucket {:triggers {:queue-size {:threshold 1}}, :queue #atom[[#object[urania.core.Map 0x426d89a1 urania.core.Map@426d89a1]] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Watching queue size 1 0 {:triggers {:queue-size {:threshold 1}}, :queue #atom[[] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching 1 muses
FetchPets top level returned 3 ({:id abc-123} {:id def-234} {:id ghi-345})
Starting 1 triggers
Starting trigger :queue-size {:threshold 3}
Enqueing (:pet-details #example.server.FetchPet{:id abc-123})
Watching queue size 3 1 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x946b4b8 urania.core.Map@946b4b8]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id abc-123})
Watching queue size 3 2 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x946b4b8 urania.core.Map@946b4b8] #object[urania.core.Map 0x43cb09a8 urania.core.Map@43cb09a8]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id def-234})
Watching queue size 3 3 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x946b4b8 urania.core.Map@946b4b8] #object[urania.core.Map 0x43cb09a8 urania.core.Map@43cb09a8] #object[urania.core.Map 0x6d45b0f1 urania.core.Map@6d45b0f1]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Going to fetch {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x946b4b8 urania.core.Map@946b4b8] #object[urania.core.Map 0x43cb09a8 urania.core.Map@43cb09a8] #object[urania.core.Map 0x6d45b0f1 urania.core.Map@6d45b0f1]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id def-234})
Watching queue size 3 4 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x946b4b8 urania.core.Map@946b4b8] #object[urania.core.Map 0x43cb09a8 urania.core.Map@43cb09a8] #object[urania.core.Map 0x6d45b0f1 urania.core.Map@6d45b0f1] #object[urania.core.Map 0x511a2a95 urania.core.Map@511a2a95]] 0x7fd976fe], :id :pet-details, :urania-opts Fetching bucket {{:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x946b4b8 urania.core.Map@946b4b8] #object[urania.core.Map 0x43cb09a8 urania.core.Map@43cb09a8] #object[urania.core.Map 0x6d45b0f1 urania.core.Map@6d45b0f1] #object[urania.core.Map 0x511a2a95 urania.core.Map@511a2a95]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Watching queue size 3 0 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}Fetching 4 muses
INFO  example.server - Combining request for 2 pets (abc-123 def-234)
}}
Going to fetch {:triggers {:queue-size {:threshold 3}}, :queue #atom[[] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching bucket {:triggers {:queue-size {:threshold 3}}, :queue #atom[[] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Watching queue size 3 0 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id ghi-345})
Watching queue size 3 1 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x65c0d8ce urania.core.Map@65c0d8ce]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id ghi-345})
Watching queue size 3 2 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x65c0d8ce urania.core.Map@65c0d8ce] #object[urania.core.Map 0x7edd1b97 urania.core.Map@7edd1b97]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (#example.server.FetchPets{})
Watching queue size 1 1 {:triggers {:queue-size {:threshold 1}}, :queue #atom[[#object[urania.core.Map 0x3e5ffe85 urania.core.Map@3e5ffe85]] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Going to fetch {:triggers {:queue-size {:threshold 1}}, :queue #atom[[#object[urania.core.Map 0x3e5ffe85 urania.core.Map@3e5ffe85]] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching bucket {:triggers {:queue-size {:threshold 1}}, :queue #atom[[#object[urania.core.Map 0x3e5ffe85 urania.core.Map@3e5ffe85]] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Watching queue size 1 0 {:triggers {:queue-size {:threshold 1}}, :queue #atom[[] 0x3a2b5f98], :id :default, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching 1 muses
FetchPets top level returned 3 ({:id abc-123} {:id def-234} {:id ghi-345})
Starting 1 triggers
Starting trigger :queue-size {:threshold 3}
Fetching bucket {:triggers {:queue-size {:threshold 3, :stop-fn #function[superlifter.core/eval34537/fn--34538/fn--34543]}}, :queue #atom[[#object[urania.core.Map 0x65c0d8ce urania.core.Map@65c0d8ce] #object[urania.core.Map 0x7edd1b97 urania.core.Map@7edd1b97]] 0x7fd976fe], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching 2 muses
Overwriting bucket  :pet-details containing []
Enqueing (:pet-details #example.server.FetchPet{:id abc-123})
Watching queue size 3 1 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id abc-123})
Watching queue size 3 2 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{:id def-234})
Watching queue size 3 3 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9] #object[urania.core.Map 0x1550a51d urania.core.Map@1550a51d]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Going to fetch {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9] #object[urania.core.Map 0x1550a51d urania.core.Map@1550a51d]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Enqueing (:pet-details #example.server.FetchPet{Fetching bucket :id def-234})
Watching queue size 3 4 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9] #object[urania.core.Map 0x1550a51d urania.core.Map@1550a51d] #object[urania.core.Map 0x3ed0893f urania.core.Map@3ed0893f]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9] #object[urania.core.Map 0x1550a51d urania.core.Map@1550a51d] #object[urania.core.Map 0x3ed0893f urania.core.Map@3ed0893f]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name:age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Going to fetch  Lyra, :age{:triggers  11}, def-234 {:name Pantalaimon, {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9] #object[urania.core.Map 0x1550a51d urania.core.Map@1550a51d] #object[urania.core.Map 0x3ed0893f urania.core.Map@3ed0893f]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
:ageFetching bucket {:triggers {:queue-size Enqueing ( {:threshold 3}}, :queue #atom[:pet-details #example.server.FetchPet{:id ghi-34511[#object[urania.core.Map 0x10476d8d urania.core.Map@10476d8d] #object[urania.core.Map 0x4ad047d9 urania.core.Map@4ad047d9] #object[urania.core.Map 0x1550a51d urania.core.Map@1550a51d] #object[urania.core.Map 0x3ed0893f urania.core.Map@3ed0893f]]})} 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Watching queue size 3 0 {:triggers 
{:queue-size {Watching queue size 3 1 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x1cf562bb urania.core.Map@1cf562bb]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
, ghi-345 {:name Iorek, :age 41}}}}}
:thresholdEnqueingWatching queue size 3}}, :queue #atom[[] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11},  (:pet-details #example.server.FetchPet{:id ghi-345})
Watching queue size 3 1 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x54531073 urania.core.Map@54531073]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
 3 0 {:triggers {:queue-size {:threshold 3}}, :queue #atom[[#object[urania.core.Map 0x54531073 urania.core.Map@54531073]] 0x749ad3a5], :id :pet-details, :urania-opts {:env {:db {abc-123 {:name Lyra, :age 11}, def-234ghi-345 {:name Iorek, :age 41}}}}}
Fetching 4 muses
 {:name Pantalaimon, :age 11}, ghi-345 {:name Iorek, :age 41}}}}}
Fetching 1 muses
INFO  example.server - Combining request for 1 pets (ghi-345)
INFO  example.server - Combining request for 1 pets (ghi-345)
INFO  example.server - Combining request for 2 pets (abc-123 def-234)

Note here that we have 3*2 fetches. The first 3 are enqueued and a fetch is triggered, but another muse is enqueued before the fetch can take place. The fetch therefore fetches 4 muses in one go. The remaining 2 muses when enqueued are not enough to reach the trigger's threshold so they sit in limbo.

@oliyh
Copy link
Owner

oliyh commented Nov 10, 2020

https://github.com/oliyh/superlifter/blob/master/src/superlifter/core.cljc#L86

Possible fix 1: instead of enqueue calling swap! and letting the triggers watch the atom, it should do a swap-vals and then call any triggers that register themselves as callbacks to be given old state / new state. This still leaves open the possibility that before we can do anything about fetching muses that reach the trigger threshold, more things will have been enqueued.

Possible fix 2: The swap function needs to be composed with triggers that fire based on the state of the queue. The queue should be composed of :queued and :fetchable and items should be removed from :queued and placed into :fetchable in the atomic swap operation of enqueuing a new muse. Then the :fetchable items can be safely fetched without being affected by further enqueing mechanisms.

Also, the :queue-size trigger should only fire when the number of muses is equal to the threshold, not equal or more than.

@oliyh
Copy link
Owner

oliyh commented Nov 11, 2020

A further problem related to overwriting buckets - if the overwritten bucket has 1 item in it, it will be fetched when that bucket is shut down. That might mean that when its two siblings are added into the successor bucket that it never reaches its threshold. I think we need to make overwritten buckets combine their queue with the new one, by enqueuing everything into the new bucket.

@oliyh
Copy link
Owner

oliyh commented Nov 11, 2020

Buckets are contained in an atom and themselves contain an atom for the queue. I think perhaps the queue atom should be removed and instead the bucket should be an immutable data structure, that way we don't have two atom boundaries to think about.

This seems to be a problem already with overwriting buckets, that the old bucket can be cleaned out but it's possible that another thread still has a reference to it's queue and can enqueue items even while it is being shut down. Instead we need fully atomic operations on buckets.

@oliyh
Copy link
Owner

oliyh commented Nov 12, 2020

Hi @bday2009

I have spent quite a bit of time on this and found several issues. I believe them all to be resolved now - could you try the latest 0.1.3-SNAPSHOT and let me know?

Thanks

@bday2009
Copy link
Author

bday2009 commented Nov 12, 2020

Thank you for your efforts. I quickly tried the new version and still ran into the problem.

Query

query {
  customers {
    id
    addresses {
      id
    }
  }

  customerById(id: "9c8c97f3-d285-4dd3-8830-e19b1361b130") {
    id
    addresses {
      id
    }
  }
}
;; => :initiated00:04:05.093 [qtp1961372816-44] INFO  io.pedestal.http - {:msg "POST /api", :line 80}
00:04:05.138 [qtp1961372816-44] DEBUG superlifter.core - Starting bucket :default
00:04:05.143 [qtp1961372816-44] DEBUG superlifter.core - Starting 1 triggers
00:04:05.146 [qtp1961372816-44] DEBUG superlifter.core - Starting trigger :queue-size {:threshold 1}
00:04:05.319 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Enqueuing muse into :default nil
00:04:05.322 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Bucket :default queue-size trigger( 1 ): ready: 0, waiting: 1
00:04:05.323 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Update bucket called: :default ready: 0, waiting: 0 -> ready: 1, waiting: 0
00:04:05.324 [clojure-agent-send-off-pool-6] INFO  superlifter.core - Fetching 1 muses from bucket :default
00:04:05.359 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Starting 1 triggers
00:04:05.361 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Starting trigger :queue-size {:threshold 3}
00:04:05.363 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
00:04:05.365 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 1
00:04:05.365 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 0 -> ready: 0, waiting: 1
00:04:05.366 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
00:04:05.367 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9107075e-721a-4c3b-b5eb-bdf5ecb7755a"
00:04:05.368 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 2
00:04:05.369 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 1 -> ready: 0, waiting: 2
00:04:05.370 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
00:04:05.370 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
00:04:05.371 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 3
00:04:05.371 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 2 -> ready: 3, waiting: 0
00:04:05.372 [ForkJoinPool.commonPool-worker-3] INFO  superlifter.core - Fetching 3 muses from bucket :customer-addresses
00:04:05.374 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "53fd8795-f82e-4282-982d-bb69754d351c"
00:04:05.376 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 1
00:04:05.376 [ForkJoinPool.commonPool-worker-5] DEBUG myapp.graphql.helpers - Combining 2 fetches
00:04:05.377 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 3, waiting: 0 -> ready: 0, waiting: 1
00:04:05.378 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses

Query

query {
  customerById(id: "9c8c97f3-d285-4dd3-8830-e19b1361b130") {
    id
    addresses {
      id
    }
  }

  customers {
    id
    addresses {
      id
    }
  }

}
00:00:13.146 [qtp976713646-54] INFO  io.pedestal.http - {:msg "POST /api", :line 80}
00:00:13.162 [qtp976713646-54] DEBUG superlifter.core - Starting bucket :default
00:00:13.163 [qtp976713646-54] DEBUG superlifter.core - Starting 1 triggers
00:00:13.163 [qtp976713646-54] DEBUG superlifter.core - Starting trigger :queue-size {:threshold 1}
00:00:13.224 [clojure-agent-send-off-pool-8] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
00:00:13.225 [clojure-agent-send-off-pool-8] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 0 -> ready: 0, waiting: 1
00:00:13.226 [clojure-agent-send-off-pool-8] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
00:00:13.227 [clojure-agent-send-off-pool-8] DEBUG superlifter.core - Enqueuing muse into :default nil
00:00:13.228 [clojure-agent-send-off-pool-8] DEBUG superlifter.core - Bucket :default queue-size trigger( 1 ): ready: 0, waiting: 1
00:00:13.229 [clojure-agent-send-off-pool-8] DEBUG superlifter.core - Update bucket called: :default ready: 0, waiting: 0 -> ready: 1, waiting: 0
00:00:13.229 [clojure-agent-send-off-pool-8] INFO  superlifter.core - Fetching 1 muses from bucket :default
00:00:13.242 [ForkJoinPool.commonPool-worker-3] WARN  superlifter.core - Bucket :customer-addresses already exists
00:00:13.248 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9107075e-721a-4c3b-b5eb-bdf5ecb7755a"
00:00:13.249 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 1 -> ready: 0, waiting: 2
00:00:13.250 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
00:00:13.252 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
00:00:13.254 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 2 -> ready: 0, waiting: 3
00:00:13.255 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
00:00:13.259 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "53fd8795-f82e-4282-982d-bb69754d351c"
00:00:13.261 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 3 -> ready: 0, waiting: 4
00:00:13.262 [ForkJoinPool.commonPool-worker-3] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses

The request hangs in both cases. There are 3 customers, the queried customer has 6 addresses.

@bday2009
Copy link
Author

bday2009 commented Nov 12, 2020

Querying a single customer also fails now, it was working in 0.1.2:

query {
  customerById(id: "9c8c97f3-d285-4dd3-8830-e19b1361b130") {
    id
    addresses {
      id
    }
  }
}
23:56:25.079 [qtp976713646-43] INFO  io.pedestal.http - {:msg "POST /api", :line 80}
23:56:25.080 [qtp976713646-43] DEBUG superlifter.core - Starting bucket :default
23:56:25.080 [qtp976713646-43] DEBUG superlifter.core - Starting 1 triggers
23:56:25.081 [qtp976713646-43] DEBUG superlifter.core - Starting trigger :queue-size {:threshold 1}
23:56:25.096 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
23:56:25.100 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 0 -> ready: 0, waiting: 1
23:56:25.106 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses

@oliyh
Copy link
Owner

oliyh commented Nov 12, 2020

Hi,

I think I understand what's going on with your first example - you are creating a bucket of size 3 for :customer-addresses, the three customers are enqueued in it, fetched, and then your single customer resolver is also enqueued in it but because there is only one it never reaches the threshold of 3 to be fetched and so hangs. I believe in this case it should be possible for the bucket to expand to size 4, but that will require a bit more thought and work.

Your second and third examples are confusing, they seem to indicate that there is no trigger for the :customer-addresses bucket. I have done another build with more logging - 0.1.3-SNAPSHOT again (0.1.3-20201112.205819-2 to be precise) I'd be really grateful if you could run the above again with the new build.

@bday2009
Copy link
Author

First query now starts working but it still hangs sometimes.
When it works:

04:40:22.534 [qtp1722375608-42] INFO  io.pedestal.http - {:msg "POST /api", :line 80}
04:40:22.535 [qtp1722375608-42] DEBUG superlifter.core - Starting bucket :default
04:40:22.535 [qtp1722375608-42] DEBUG superlifter.core - Starting 1 triggers for bucket :default
04:40:22.536 [qtp1722375608-42] DEBUG superlifter.core - Starting trigger :queue-size for bucket :default {:threshold 1}
04:40:22.538 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Enqueuing muse into :default nil
04:40:22.538 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Bucket :default queue-size trigger( 1 ): ready: 0, waiting: 1
04:40:22.539 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Update bucket called: :default ready: 0, waiting: 0 -> ready: 1, waiting: 0
04:40:22.539 [clojure-agent-send-off-pool-6] INFO  superlifter.core - Fetching 1 muses from bucket :default
04:40:22.546 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Adding bucket :customer-addresses {:triggers {:queue-size {:threshold 3}}}
04:40:22.547 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Starting bucket :customer-addresses
04:40:22.548 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Starting 1 triggers for bucket :customer-addresses
04:40:22.547 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
04:40:22.549 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Starting trigger :queue-size for bucket :customer-addresses {:threshold 3}
04:40:22.550 [clojure-agent-send-off-pool-6] WARN  superlifter.core - Bucket :customer-addresses does not exist, using default bucket
04:40:22.551 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Bucket :default queue-size trigger( 1 ): ready: 0, waiting: 1
04:40:22.552 [clojure-agent-send-off-pool-6] DEBUG superlifter.core - Update bucket called: :default ready: 1, waiting: 0 -> ready: 1, waiting: 0
04:40:22.552 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9107075e-721a-4c3b-b5eb-bdf5ecb7755a"
04:40:22.552 [clojure-agent-send-off-pool-6] INFO  superlifter.core - Fetching 1 muses from bucket :default
04:40:22.552 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 1
04:40:22.553 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 0 -> ready: 0, waiting: 1
04:40:22.554 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
04:40:22.555 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
04:40:22.555 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 2
04:40:22.555 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 1 -> ready: 0, waiting: 2
04:40:22.556 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
04:40:22.557 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "53fd8795-f82e-4282-982d-bb69754d351c"
04:40:22.557 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 3
04:40:22.558 [ForkJoinPool.commonPool-worker-7] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 2 -> ready: 3, waiting: 0
04:40:22.558 [ForkJoinPool.commonPool-worker-7] INFO  superlifter.core - Fetching 3 muses from bucket :customer-addresses
04:40:22.559 [ForkJoinPool.commonPool-worker-5] DEBUG myapp.graphql.helpers - Combining 3 fetches

When it hangs:

04:42:48.020 [qtp1722375608-38] INFO  io.pedestal.http - {:msg "POST /api", :line 80}
04:42:48.021 [qtp1722375608-38] DEBUG superlifter.core - Starting bucket :default
04:42:48.022 [qtp1722375608-38] DEBUG superlifter.core - Starting 1 triggers for bucket :default
04:42:48.022 [qtp1722375608-38] DEBUG superlifter.core - Starting trigger :queue-size for bucket :default {:threshold 1}
04:42:48.024 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Enqueuing muse into :default nil
04:42:48.025 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Bucket :default queue-size trigger( 1 ): ready: 0, waiting: 1
04:42:48.025 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Update bucket called: :default ready: 0, waiting: 0 -> ready: 1, waiting: 0
04:42:48.025 [clojure-agent-send-off-pool-7] INFO  superlifter.core - Fetching 1 muses from bucket :default
04:42:48.032 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Adding bucket :customer-addresses {:triggers {:queue-size {:threshold 3}}}
04:42:48.033 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Starting bucket :customer-addresses
04:42:48.033 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Starting 1 triggers for bucket :customer-addresses
04:42:48.034 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Starting trigger :queue-size for bucket :customer-addresses {:threshold 3}
04:42:48.034 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
04:42:48.034 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 1
04:42:48.035 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 0 -> ready: 0, waiting: 1
04:42:48.035 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9107075e-721a-4c3b-b5eb-bdf5ecb7755a"
04:42:48.035 [clojure-agent-send-off-pool-7] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
04:42:48.036 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 2
04:42:48.037 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 1 -> ready: 0, waiting: 2
04:42:48.037 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
04:42:48.038 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "9c8c97f3-d285-4dd3-8830-e19b1361b130"
04:42:48.038 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 3
04:42:48.039 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 0, waiting: 2 -> ready: 3, waiting: 0
04:42:48.039 [ForkJoinPool.commonPool-worker-9] INFO  superlifter.core - Fetching 3 muses from bucket :customer-addresses
04:42:48.040 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Enqueuing muse into :customer-addresses #uuid "53fd8795-f82e-4282-982d-bb69754d351c"
04:42:48.041 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Bucket :customer-addresses queue-size trigger( 3 ): ready: 0, waiting: 1
04:42:48.041 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Update bucket called: :customer-addresses ready: 3, waiting: 0 -> ready: 0, waiting: 1
04:42:48.041 [ForkJoinPool.commonPool-worker-9] DEBUG superlifter.core - Nothing ready to fetch for :customer-addresses
04:42:48.042 [ForkJoinPool.commonPool-worker-9] DEBUG myapp.graphql.helpers - Combining 2 fetches

Second and third queries seem to work now. If the only thing you did for 0.1.3-20201112.205819-2 was adding more logs then it's really weird that those works again, though it's not surprising because as I mentioned in a few posts ealier, as of 0.1.2, changing the log level seemed to have some effects as well.

@oliyh
Copy link
Owner

oliyh commented Nov 12, 2020

Hi,

Thanks once again for your quick feedback. I added some logging but I also ensured that muses go into the default bucket if the named bucket does not exist, as I suspected that your singular customerById does not create the customer-addresses bucket. This is proved by the following from your working example:

04:40:22.550 [clojure-agent-send-off-pool-6] WARN  superlifter.core - Bucket :customer-addresses does not exist, using default bucket

This one works because the singular one comes first, goes into the default bucket (with a threshold of 1) and is therefore fetched. The plural customers one comes after, creates the bucket of three and then filling it to the threshold and it's then fetched and all is good.

If they happen to be reversed, as in your second example, the plural one runs first, creates the bucket, fills it with three muses which are fetched, and then the singular one goes into that bucket but then sits there forever because the threshold is three.

What you 'should' be doing for consistency is calling add-bucket with a threshold of 1 in your getCustomerById resolver, and continuing to call add-bucket with a threshold of 3 for your plural customers. I have a test for this scenario that is not passing at the moment. What I would like it to do is increase the threshold to 4 and fetch them all together, but I'm not sure what to do if/when that bucket is re-used after those four have been fetched - if the threshold should be reset, or perhaps the entire bucket removed, or something else. One fix would be to set the threshold back to 1 after the bucket has been filled the first time - this would ensure it behaved if re-used at least. If it was to be reused the extra efficiency could be gained by forecasting the bucket size more accurately up front. I think I will try this, as I believe it will make all my tests pass, and think more about possible improvements to efficiency.

@oliyh
Copy link
Owner

oliyh commented Nov 12, 2020

I believe I have removed race conditions from superlifter so adding/removing logging should not affect it now, rather what remains is a deterministic issue depending on the order in which it is called by the resolvers (which itself is not deterministic, hence why the macro behaviour is not deterministic).

@oliyh
Copy link
Owner

oliyh commented Nov 16, 2020

Hi again @bday2009

I have added a new kind of trigger called :elastic. It has a threshold like a :queue-size trigger, but you can grow it and it snaps back to zero when a fetch occurs. I believe this encompasses the expectation of behaviour around requiring a dynamic bucket size depending on the results of parent resolvers, but fixes the hanging issues which occurred due to timing/ordering of the child resolvers.

It's usage can be seen in the example, which I have updated to remove the calls to add-bucket! and have replaced them with update-trigger!: https://github.com/oliyh/superlifter/blob/multi-fetch-hang/example/src/example/server.clj#L29-L34

Note that it now also specifies the :pet-details bucket up front: https://github.com/oliyh/superlifter/blob/multi-fetch-hang/example/src/example/server.clj#L65

I have updated the readme on that branch to describe the elastic trigger, and to suggest better use of the existing queue-size trigger.

This is now deployed as a new 0.1.3-SNAPSHOT.

Hope this makes sense and works for you!

@bday2009
Copy link
Author

bday2009 commented Nov 21, 2020

hi @oliyh, thank you for your hard work. I think I understand this, however I have a couple of questions I hope you can help clarify:

  1. so from now on, assuming we use superlifter as a dataloader for graphql, we'd want to use elastic instead of queue-size always since there's no way to know beforehand exactly how many muses in a bucket?

  2. we'd have to check the resolver context to look for the "batched" field and only do update-trigger! when it is found?

  3. if 2 is true, do you think it makes sense to introduce a helper function that would help with this, since there might be a large number of these batched field in a resolver?

@oliyh
Copy link
Owner

oliyh commented Nov 21, 2020

Hi,

  1. I would say the elastic trigger is suitable for when you want maximum efficiency i.e. grouping as many similar calls as possible and avoiding any time triggers. You can still use queue-size but I would recommend always combining it with a time trigger e.g. interval or denounced. This would be more suitable when you wanted to place an upper limit on bucket size (to do more smaller fetches). You can also of course use the time triggers on their own as well.

  2. In the example project I set up a pet-details bucket in the initial superlifter options. If you know in advance what buckets your resolvers will use (I can't think of a situation where you wouldn't) I think it's better to define them in the initial options rather than relying on calling add-bucket in your resolvers.

  3. You are right, calling update-trigger on a bucket that doesn't exist yet wouldn't do good things (I should add a check for the existence of the bucket in update trigger). That's why I would recommend the approach outlined in (2). Otherwise you should be able to chain the add-bucket (which is idempotent) and update trigger calls, but it's not very elegant.

I think there are ways to improve lacinia integration, I created #16 as one such way - if you have other suggestions I'd like to hear them.

Hope this helps. I may have misunderstood your question (2) please clarify if I have.

@bday2009
Copy link
Author

bday2009 commented Nov 21, 2020

I'd like to clarify (2) and (3):
For example:

(defn- resolve-pets [context _args _parent]
  (with-superlifter context
    (-> (s/enqueue! (->FetchPets))
        (s/update-trigger! :pet-details :elastic
                           (fn [trigger-opts pet-ids]
                             (update trigger-opts :threshold + (count pet-ids)))))))

This would update pet-details bucket threshold even when the user doesn't ask for details field. Here, the threshold increases but lacinia does not try to resolve for that field (user didn't ask for), so the threshold won't be met. I haven't tried it out and might be totally off base here. If I'm right though, we will need to check if the user ask for details and only run update-trigger! then. We might have several fields like that and need to implement checks & update-trigger! for all of them, that would be the job of the helper function I mentioned in question (3).

But yeah your (2) and (3) answers addressed another one of my concerns that I didn't mention in the earlier comment.

@oliyh
Copy link
Owner

oliyh commented Nov 21, 2020

Thanks for clarifying, I understand now. Yes I agree, I already ran into this issue with the example project test, which does the same query twice with different aliases. There are three pets, but the pet details resolver is called 6 times. By setting a bucket of 3 it filled it twice which isn't bad, but it would be better if it knew it was going to be 6 (or zero, as you mention). I am hoping that this information is available in the lacinia context and furthermore my idea in #16 was that the pet details resolver would declare its own bucket in the schema, that way superlifter could look ahead and set up the correct sized buckets for any child resolvers for you.

This all may or may not be possible, for now hopefully it's at least fully functional at this low/medium level and we can aspire for a more beautiful high level API for lacinia.

@oliyh
Copy link
Owner

oliyh commented Nov 21, 2020

Lacinia already has a helper to look ahead at the child selections, see selections-seq

So you could write it now like this pseudo code (selections-seq doesn't return a set, but a list you'd have to filter)

  (with-superlifter context
    (cond-> (prom/promise {:id (:id args)})
        (contains? (selections-seq context) :pet-details)
        (s/update-trigger! :pet-details :elastic
                           (fn [trigger-opts _pet-ids]
                             (update trigger-opts :threshold inc))))))

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants