Memory leak when using file, postgres backends

[filipesilva]

At https://github.com/athensresearch/athens we started noticing a memory leak when using Datahike 0.3.7-SNAPSHOT and 0.3.2.

Below is a reproduction that only uses a single unindexed schema attribute:

(ns repro
  (:require
    [datahike.api :as d])
  (:import
    (java.util.concurrent
      TimeUnit)
    (java.util
     UUID)))

(defn used-memory
  []
  (quot (- (.. Runtime getRuntime totalMemory)
           (.. Runtime getRuntime freeMemory))
        (* 1024 1024)))

(defn run-gc
  []
  (.. Runtime getRuntime gc))

(defn sleep
  [n]
  (.. TimeUnit -SECONDS (sleep n)))

(defn remove-enclosing-quotes-and-newline
  [s]
  (subs s 1 (- (count s) 2)))

(defn step
  [iteration f]
  (when (and (not= iteration 0)
             (= (rem iteration 50) 0))
    (println "Sleeping 5 seconds every 50 iterations to allow for GC")
    (sleep 5))
  (run-gc)
  (println "Iteration:" iteration "-"
           "Used memory:" (used-memory) "-"
           (remove-enclosing-quotes-and-newline
             (with-out-str (time
                             ;; ignore printed output from f
                             (with-out-str (f)))))))

(defn repro
  []
  (let [uuid-str (fn [] (subs (.toString (UUID/randomUUID)) 27))
        config   {:store {:backend :file
                          :path    (str "/tmp/repro-" (uuid-str))}}
        schema   [{:db/ident       :block/string
                   :db/valueType   :db.type/string
                   :db/cardinality :db.cardinality/one}]
        _        (d/create-database config)
        conn     (d/connect config)]

    (d/transact conn schema)

    (let [iterations 500]
      (dotimes [n iterations]
        (step n (fn []
                  (let [tx [{:block/string "random string"}]]
                    (d/transact conn tx))))))

    (d/release conn)
    (d/delete-database config)))

(comment
  (repro))

Eval'ing (repro) inside a REPL will yield output similar to this for the first time:

2021-09-08T11:55:20.627Z Filipes-Air DEBUG [datahike.connector:139] - Using config  {:keep-history? true, :index :datahike.index/hitchhiker-tree, :store {:path "/tmp/repro-0a6b42285", :backend :file}, :name "measly-west-european-hedgehog", :attribute-refs? false, :schema-flexibility :write, :index-config {:index-b-factor 17, :index-log-size 283, :index-data-node-size 300}, :cache-size 100000}
2021-09-08T11:55:20.633Z Filipes-Air DEBUG [datahike.connector:79] - Transacting with arguments:  {:tx-data [#:db{:ident :block/string, :valueType :db.type/string, :cardinality :db.cardinality/one}]}
Iteration: 0 - Used memory: 69 - Elapsed time: 47.388083 msecs
Iteration: 1 - Used memory: 68 - Elapsed time: 45.527541 msecs
Iteration: 2 - Used memory: 68 - Elapsed time: 45.743167 msecs
Iteration: 3 - Used memory: 68 - Elapsed time: 46.200833 msecs
... redacted for brevity ...
Iteration: 496 - Used memory: 226 - Elapsed time: 101.975208 msecs
Iteration: 497 - Used memory: 226 - Elapsed time: 100.68525 msecs
Iteration: 498 - Used memory: 226 - Elapsed time: 101.798125 msecs
Iteration: 499 - Used memory: 227 - Elapsed time: 103.071916 msecs
2021-09-08T11:57:11.268Z Filipes-Air DEBUG [datahike.transactor:42] - Transactor rx thread gracefully closed

Used memory is in MB. You can see here that it increases over time. A GC hint is provided every iteration, and every 50 iterations there's a 5s sleep call.

The repro function will release the conn and delete the database. If you eval the function multiple times you can also see that the used memory is not GC'd between evals.

2021-09-08T11:59:37.684Z Filipes-Air DEBUG [datahike.connector:139] - Using config  {:keep-history? true, :index :datahike.index/hitchhiker-tree, :store {:path "/tmp/repro-96337e007", :backend :file}, :name "tender-eurasian-water-shrew", :attribute-refs? false, :schema-flexibility :write, :index-config {:index-b-factor 17, :index-log-size 283, :index-data-node-size 300}, :cache-size 100000}
2021-09-08T11:59:38.074Z Filipes-Air DEBUG [datahike.connector:79] - Transacting with arguments:  {:tx-data [#:db{:ident :block/string, :valueType :db.type/string, :cardinality :db.cardinality/one}]}
Iteration: 0 - Used memory: 254 - Elapsed time: 44.377041 msecs
Iteration: 1 - Used memory: 253 - Elapsed time: 46.239875 msecs
Iteration: 2 - Used memory: 253 - Elapsed time: 45.156583 msecs
Iteration: 3 - Used memory: 253 - Elapsed time: 44.767375 msecs
Iteration: 4 - Used memory: 253 - Elapsed time: 45.815541 msecs
... redacted for brevity ...
Iteration: 496 - Used memory: 349 - Elapsed time: 97.971083 msecs
Iteration: 497 - Used memory: 349 - Elapsed time: 102.510625 msecs
Iteration: 498 - Used memory: 349 - Elapsed time: 104.935041 msecs
Iteration: 499 - Used memory: 349 - Elapsed time: 100.670583 msecs
2021-09-08T12:01:42.056Z Filipes-Air DEBUG [datahike.transactor:42] - Transactor rx thread gracefully closed

Also worth mentioning that the transaction time increases within the same eval, but resets between evals.

[filipesilva]

I tried with https://github.com/replikativ/datahike-postgres and saw the same increase in memory usage on transaction.

I used this command to start postgres with docker:

docker run -p 5432:5432 --name some-postgres -e POSTGRES_PASSWORD=mysecretpassword -d postgres

And this datahike config:

{:backend :pg
 :host "localhost"
 :port 5432
 :username "postgres"
 :password "mysecretpassword"
 :path "/postgres"}

This is not the default config in datahike-postgres' readme because of https://github.com/replikativ/datahike-postgres/issues/11, so I used the workaround in https://github.com/replikativ/datahike-postgres/pull/12.

[filipesilva]

Left the repro for 5000 iterations using datahike-postgres and saw transact time ebb up and down between 18 and 85 ms, which points towards it not increasing indefinitely.

Memory on the other hand mostly climbed up from the initial 413mb starting point, sometimes going down 20mb or so, but after the 5000 iterations it was at 615mb.

Docker lists the postgres container using the following resources at the end of the 5000 iterations:

CONTAINER ID   NAME            CPU %     MEM USAGE / LIMIT    MEM %     NET I/O         BLOCK I/O    PIDS
523ab6d2e865   some-postgres   0.00%     38.8MiB / 1.942GiB   1.95%     616MB / 1.2GB   0B / 316MB   7

[filipesilva]

Left the same process running against postgres again, and after 6000 txs it climbed from 613mb to 635mb. So if it's climbing further than that, it is slower than the climb up to 600mb.

[filipesilva]

Tried the local file system backend again on the same process where I had been trying the others.

After 1500 txs it went from 634mb to 570mb. Transactions started taking 44ms and went as high as 164ms, but started ebbing up and down around those values.

So it looks like there's no memory leak with either file or postgres backends, but that memory usage stabilizes around 600mb.

[whilo]

@filipesilva Thanks for taking the time to report! This is probably due to our cache of the actual tree fragments. At the moment we do not cap the size of Datoms (e.g. the string length of values), so there is no easy way to bound the memory in size of megabytes, but one can definitely decrease the cache size of konserve. The current value of is fairly aggressive with a thousand tree fragments, each containing approximately 300 Datoms: https://github.com/replikativ/datahike/blob/development/src/datahike/connector.cljc#L129. konserve also is being significantly upgraded at the moment including a bit more intelligent caching, but the total size is still configured from the outside. What expectations do you have and how can we get closer to what you need?

[filipesilva]

@whilo sorry for the delay in answering! Thank you for the context. We guessed it might be the cache because we saw a lot of memory being kept in some file-related things in superv.async on profiling.

I think our expectations would mostly be a way to distinguish between a real memory leak and just some reasonable minimum requirements. If we had known about the cache size in advance, and maybe had a way to manipulate it, it would have been very obvious that there was no leak. Some reasonable minimum system reqs would also be nice.

[whilo]

Thanks, we will expose the setting and be more explicit about the system requirements. To provide absolute upper bounds on the requirements we would need to bound Datom size. What would you expect as maximum string size? (we can make this configurable as well)

[filipesilva]

We thought about string size as well. We checked if we were saving something growing ever bigger. I wouldn't be surprised if I we needed ever larger amount of memory if I'm saving bigger and bigger strings. So we'd be happy enough just limiting string on our app.