Forem: dpsutton

Logging in Clojure: jar tidiness

dpsutton — Sat, 06 Aug 2022 06:23:00 +0000

This article will work through an easy to encounter yet easy to avoid pitfall that can occur with clojure.core.logging, the de facto logging facade for Clojure projects. I'll build up an example project that will mimic a real world scenario brought down to just its basics.

The gist is that logging time (even below the active threshold of logging) will be increased by two orders of magnitude, causing a form that takes 379 ms to evaluate to take over 19.5 seconds just by adding a jar to the classpath. The form is a bit contrived, but it does simulate arbitrary "work" and how logging could tremendously slow down your code if you forget how your logger was configured (perhaps several years ago).

tl;dr

specify your clojure.tools.logging implementation. It might drift over time from what you originally thought it was
watch your deps. It is very easy to accumulate more than you think

The setup

Let's setup a basic project that includes a logger. I think the nicest way to get a new project up is with one of the tools that Borkdude has created, called neil. If you have this installed, just run the following in an empty directory:

neil add build

This gives us a great template to start our example. If you don't have neil installed (and you should), just create the following deps.edn:

{:deps {}
 :aliases {
 :build ;; added by neil
 {:deps {io.github.clojure/tools.build {:git/tag "v0.8.3" :git/sha "0d20256"}}
  :ns-default build}}}

Find a log4j2 tutorial or copy the config from your last project, and we have the following state:

{:deps {org.clojure/tools.logging           {:mvn/version "1.2.4"}
        org.apache.logging.log4j/log4j-api  {:mvn/version "2.18.0"}
        org.apache.logging.log4j/log4j-core {:mvn/version "2.18.0"}}
 :aliases {
           :build ;; added by neil
           {:deps       {io.github.clojure/tools.build {:git/tag "v0.8.3" :git/sha "0d20256"}}
            :ns-default build}}}

Make a src directory and paste the following in src/log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <Appenders>
    <Console name="Console">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="WARN">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>
</Configuration>

Creating a jar

Let's create a jar:

$ clj -T:build uber
$ cp target/lib1-1.2.1-standalone.jar log4j2-uber.jar

I'm going to leave tooling out of this and run everything through a repl on the command line right from the jar. One other thing I want to do is include the incredible criterium library so we can profile. I'm deliberately including criterium separately like this because you shouldn't have a dev-time tool like criterium in an uberjar. And knowing how to easily combine other jars with your real production jar can be very helpful. I grabbed the jar from my .m2 cache.

$ java -cp log4j2-uber.jar:criterium.jar clojure.main
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
"Elapsed time: 447.684167 msecs"
49999995000000
user=>

And now we've simulated some work that takes about half a second on this run.

The change

Now suppose work requirements come up and we need to deal with sparksql. It's not particularly relevant, but you can imagine any particularly large jar, or maybe just the accumulation of jars over time. Let's add org.apache.hive/hive-jdbc {:mvn/version "3.1.3"} to our :deps map.

;; deps.edn with the hive-jdbc driver
{:deps {org.clojure/tools.logging           {:mvn/version "1.2.4"}
        org.apache.logging.log4j/log4j-api  {:mvn/version "2.18.0"}
        org.apache.logging.log4j/log4j-core {:mvn/version "2.18.0"}

        org.apache.hive/hive-jdbc {:mvn/version "3.1.3"}}
 :aliases {
           :build ;; added by neil
           {:deps       {io.github.clojure/tools.build {:git/tag "v0.8.3" :git/sha "0d20256"}}
            :ns-default build}}}

Changes required to build

This isn't particularly relevant to our build but we do have to work around the way tools.build works. The lib tools.build is outstanding and quite helpful. It takes a bit of boiler plate but we get simple programs that make our jars. The way it creates jars is by copying all of the classfiles from the jars we depend on to make the one uberjar. I'm writing this post on OSx which is not case sensitive. Jar files are zip files which are case sensitive. And this leads to a problem: a jar file can easily include foo/bar.txt and a file FOO; but my case insensitive filesystem cannot have these two things coexist. From its perspective, I want to have a file named foo, and a folder also named foo (regardless that we know its uppercase). We need to exclude these files so we don't get into this unrepresentable state.

We update the build.clj file that neil created for us by adding some :exclude entries to prevent us from getting into this situation. See the doc-string of b/uber for more documentation.

(defn uber [_]
  (clean nil)
  (b/copy-dir {:src-dirs ["src" "resources"]
               :target-dir class-dir})
  (b/compile-clj {:basis basis
                  :src-dirs ["src"]
                  :class-dir class-dir})
  (b/uber {:class-dir class-dir
           :exclude ["META-INF/license/.*" "license/LICENSE.*" "license.*"]
           :uber-file uber-file
           :basis basis
           :main 'clojure.main}))

New jar with hive

Again, it's not particularly important that the jar is the hive-jdbc jar, but its representative of state that can accumulate over time in a project, and even from a single jar. Let's build the jar and run the same form we did earlier.

$ clj -T:build uber # this can take a little bit, its a big jar
$ cp target/lib1-1.2.1-standalone.jar with-hive.jar
$ java "$(socket-repl 6001)" -cp with-hive.jar:criterium.jar clojure.main
Clojure 1.11.1
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
"Elapsed time: 19681.165584 msecs"
49999995000000

And there's our bug: we have done nothing to the existing code. We have not changed our log4j2.xml file. We haven't adjusted anything except added a jar to our classpath but now our simulated "work" (adding up a few numbers) just took over 19 seconds instead of half of a second.

Diagnosing

Since we have criterium on our classpath, we can benchmark from each repl.

user=> (require '[clojure.tools.logging :as log]
                '[clojure.tools.logging.impl :as log.impl]
                '[criterium.core :refer [bench]])
nil
user=> (bench (log/trace "no-op"))

This will print out some stats but the numbers we care about are the second line

log4j2-uber:   21.209608 ns
with-hive.jar:  1.911062 µs (1911 ns!)

There is our two orders of magnitude. And one more clue as to what is going on can be found by checking the clojure.tools.logging/*logger-factory* for each repl:

;; log4j2-uber.jar:
user=> (log.impl/name log/*logger-factory*)
"org.apache.logging.log4j"

;; with-hive.jar
user=> (log.impl/name log/*logger-factory*)
"org.slf4j"

Explanation

The de facto logging facade for Clojure is clojure.tools.logging. It tries to present a unified interface to interacting with the java logging ecosystem at large. It does this by knowing how to ensure (log/trace "no-op") get matched up to the trace classes and logger for your particular logger.

It accomplishes this by checking for the presence of classes which indicate that particular logger is on the classpath, and uses the first one it fines.

(defn find-factory
  "Returns the first non-nil value from slf4j-factory, cl-factory,
   log4j2-factory, log4j-factory, and jul-factory."
  []
  (or (slf4j-factory)
      (cl-factory)
      (log4j2-factory)
      (log4j-factory)
      (jul-factory)
      (throw ; this should never happen in 1.5+
        (RuntimeException.
          "Valid logging implementation could not be found."))))

We were previously falling through to the (log4j2-factory) but jar accretion now means that the first (slf4j-factory) is registered as our logger factory.

Fixing

The readme has a nice section about choosing a logging implementation. I have learned my lesson that this is way more important than I had originally thought. This was an afterthought at best, and usually completely ignored. But leaving it alone can leave you at the mercy of some very serious performance penalties.

From the README:

The above approach is problematic given that applications often inadvertently pull in multiple logging implementations as transitive dependencies. As such, it is strongly advised that you set the system property.

$ java -Dclojure.tools.logging.factory=clojure.tools.logging.impl/log4j2-factory -cp with-hive.jar:criterium.jar clojure.main
Clojure 1.11.1
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
"Elapsed time: 373.54025 msecs"
49999995000000

So with the same with-hive.jar, if we set our logger implementation we are back down to 373 ms instead of 19 seconds.

Lessons:

I hope this is helpful for people. It is a bit of a contrived example, but I hope a germ of real world experience is present. The tight loop in here makes it quite obvious that something has gone wrong. But in real life, these performance lapses might be spread out in time in your code, never adding enough microseconds enough for you to feel, but always sapping your throughput.

I also think that this scenario isn't as far-fetched to encounter in real life. When's the last time you audited your deps to see how many loggers you actually have? Have you explicitly set your logger-factory for your uberjar? The answer for me was "it's been a while" and "no".

A good guess is to consider what you think your logger is and then evaluate the form (log.impl/name log/*logger-factory*) and see if you got it right. Check clj -Stree | grep log in this sample repo. It includes our log4j2, slf4j, logback, commons-logging, and I think log4j. It's easy to accumulate these.

Postscript

There's actually an extra wrinkle to this, but it isn't necessary to get the general gist of this. But this bit us at work and it hit us when we didn't add a new logger to classpath but silenced a warning.

We were seeing a logged message on startup:

WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.

Some googling showed us that this warning pops up when you have a multi-release jar but you don't have the Multi-Release: true properties in your manifest file. So we made sure our manifest was correctly added and forgot about it. Then we had issues come in reporting queries had gotten much slower. It had been a while, and it took a while for a colleague to track the regression down to finding loggers when logging and we confusedly reverted the change.

You can verify this for yourself by editing with-hive.jar's manifest to remove the multi-release. Remembering that the simulated work took 19 seconds with the slf4j logger

$ java -cp with-hive-not-multirelease.jar:criterium.jar clojure.main
Clojure 1.11.1
user=> (require '[clojure.tools.logging :as log])
nil
user=> (time (reduce (fn [acc x] (log/info "accumulating") (+ acc x)) 0 (range 10000000)))
WARNING: sun.reflect.Reflection.getCallerClass is not supported. This will impact performance.
"Elapsed time: 3615.623583 msecs"
49999995000000

It's 3.6 seconds (instead of the 0.3 seconds we know is possible). But this is that performance penalty that can easily be smeared around your codebase.

Post Post Script

Often it's nice to let uberjars go off and do their thing rather start them up with clojure.main. Socket repls make it incredibly nice to be able to repl into an uberjar while it uses its main entrypoint to serve web requests or whatever it does. If your profiling needs some setup this is often a great way to ensure that it initializes the way it needs and you have a repl right into a good working state.

Clojure allows for some system properties to easily start up a repl, but it can be a little verbose. The following is a handy shell function I use constantly:

# huge props to p-himik on the Clojurians slack for this
# sample usage: clj -J"$(socket-repl 6000)" ... or java "$(socket-repl 6000) -jar ...
socket-repl()
{
 echo -n "-Dclojure.server.repl={:port $1 :accept clojure.core.server/repl}"
}

Then you can easily startup repls like the following:

$ java "$(socket-repl 6000)" -cp log4j2-uber.jar:criterium.jar clojure.main
Clojure 1.11.1
user=>

## or with `clj` or `clojure` command line tools:
$ clj -J"$(socket-repl 6009)" -A:build

Then just netcat localhost <port> and you have a repl into any running jar.

A really nice dev experience is if your editor can connect to socket repls. Doing this makes running a repl from a jar or from your regular "dev" setup almost indistinguishable. I can easily repl from a prod jar as from a branch in Clojure and my workflow is exactly the same because I use inf-clojure

Exploring the core.cache api

dpsutton — Mon, 20 Jul 2020 01:28:26 +0000

Exploring the core.cache api

I was reading through the code of core.cache and wanted to figure out the "correct" way to use it. The protocol for it is a bit large so I wasn't sure what the best way to check/hit/miss was.

(defprotocol CacheProtocol
  "This is the protocol describing the basic cache capability."
  (lookup [cache e]
          [cache e not-found]
   "Retrieve the value associated with `e` if it exists, else `nil` in
   the 2-arg case.  Retrieve the value associated with `e` if it exists,
   else `not-found` in the 3-arg case.")
  (has?    [cache e]
   "Checks if the cache contains a value associated with `e`")
  (hit     [cache e]
   "Is meant to be called if the cache is determined to contain a value
   associated with `e`")
  (miss    [cache e ret]
   "Is meant to be called if the cache is determined to **not** contain a
   value associated with `e`")
  (evict  [cache e]
   "Removes an entry from the cache")
  (seed    [cache base]
   "Is used to signal that the cache should be created with a seed.
   The contract is that said cache should return an instance of its
   own type."))

The docs in core.cache mention the common usage pattern:

(if (cache/has? C :c)     ;; has? checks that the cache contains an item
  (cache/hit C :c)        ;; hit returns a cache with any relevant internal information updated
  (cache/miss C :c 42))   ;; miss returns a new cache with the new item and without evicted entries

;=> {:a 1, :b 2, :c 42}

Using the has?/hit/miss\ pattern ensures that the thresholding and eviction logic for each implementation works properly. It is built into the through\ and through-cache\ functions, as well as clojure.core.cache.wrapped/lookup-or-miss\. *Avoid this pattern at your own risk.*

This usage shows using a cache value but most usage in the wild will be based on some storage, usually an atom (although there are examples using mongo, sqlite, etc). It also shows hitting and missing but not the best way to do all of this and also get the value out.

I'm using the grep.app webapp to find usages in the wild. Search for usages of core.cache with https://grep.app/search?q=clojure.core.cache. The site grep.app is awesome and I want to contribute to the creator. You should use it to search for code if you don't already.

Examples

Stencil

Stencil is a mustache templating library using cache which is what metabase uses for its email templates in the search results from grep.app. It uses an api of get-in and assoc-in, notably never calling hit (miss is called by assoc under the hood). This means that any caches which depend on hit for stats won't work: notably LRUCache, LUCache.

(defn cache
  "Given a template name (string), variant key (string), template source
   (string), and optionally a parsed AST, and stores that entry in the
   template cache. Returns the parsed template."
  ([template-name template-variant template-src]
     (cache template-name template-variant template-src (parse template-src)))
  ([template-name template-variant template-src parsed-template]
     (swap! parsed-template-cache
            assoc-in [template-name template-variant]
            (template-cache-entry template-src
                                  parsed-template))
     parsed-template))

,,,

(defn cache-get
  "Given a template name, attempts to fetch the template with that
   name from the template cache. If it is not in the cache, nil will
   be returned. Single argument version gets the default variant."
  ([template-name]
     (cache-get template-name :default))
  ([template-name template-variant]
     (get-in @parsed-template-cache [template-name template-variant])))

A couple things stand out here. One, this uses get-in and assoc-in but the cache's don't seem to work that way. Second, by only using these two functions, hit and miss are not called so LU and LRU cache's can't compute frequency of use. This is especially bad since the default cache for stencil is an LRU cache:

;; The parsed template cache maps a template name to its parsed versions.
(def ^{:private true} parsed-template-cache
  (atom (try
          (require 'clojure.core.cache)
          ((resolve 'clojure.core.cache/lru-cache-factory) {})
          (catch ExceptionInInitializerError _
            (CoreCacheUnavailableStub_SeeReadme.))
          (catch FileNotFoundException _
            (CoreCacheUnavailableStub_SeeReadme.)))))

Some examples of how this caching strategy disobeys the eviction strategies:

(let [cache (atom (cache/lru-cache-factory {} :threshold 2))]
  (swap! cache assoc-in [:a :b] 1)
  (swap! cache assoc-in [:c :d] 2)
  ;; make [:a :b] the most recently used entry
  (get-in @cache [:a :b])
  (swap! cache assoc-in [:e :f] 3)
  ;; the [:a :b] value is not present
  (get-in @cache [:a :b])
  )
;; nil

(let [cache (atom (cache/lu-cache-factory {} :threshold 2))]
  (swap! cache assoc-in [:a :b] 1)
  (swap! cache assoc-in [:c :d] 2)
  (get-in @cache [:a :b])
  (get-in @cache [:c :d])
  (get-in @cache [:c :d])
  (get-in @cache [:c :d])
  ;; the cache now should only have :c and :e based on least used stats
  (swap! cache assoc-in [:e :f] 3)
  )

;; {:a {:b 1}, :e {:f 3}}

(let [cache (atom (cache/ttl-cache-factory {} :ttl 400))]
  (swap! cache assoc-in [:a :b] 1)
  (swap! cache assoc-in [:c :d] 2)
  (swap! cache assoc-in [:e :f] 3)
  (Thread/sleep 300)
  (swap! cache assoc-in [:a :new-key] :should-last-500)
  (Thread/sleep 300)
  ;; the [:a :b] key should be expired, the [:a :new-key] should be present
  ;; but the cache key is actualy just `:a`
  (prn [(get-in @cache [:c :d]) (get-in @cache [:a :b]) (get-in @cache [:a :new-key])])
  )

;; [nil 1 :should-last-500]

Rieman

Rieman uses a cache in the following way:

(def fun-cache
  "Speeds up the compilation of queries by caching map of ASTs to corresponding
  functions."
  (atom (cache/lru-cache-factory {} :threshold 64)))

(defn fun
  [ast]
  (if-let [fun (cache/lookup @fun-cache ast)]
    ; Cache hit
    (do (swap! fun-cache cache/hit ast)
        fun)

    ; Cache miss
    (let [fun (eval (list 'fn ['event] (clj-ast ast)))]
      (swap! fun-cache cache/miss ast fun)
      fun)))

This works well with the lru cache but actually NPEs on the lu cache. The problem is that the cache/hit function for the lu cache expects that the result is in the cache if hit is called and increments the hit count. But with the pattern above, there's no way to guarantee that. The following should npe spectacularly in a repl:

(let [lu-cache (atom (c/lu-cache-factory {} :threshold 4))
       thread-count 200
       loop-count 20000
       latch (java.util.concurrent.CountDownLatch. thread-count)]
   (doseq [i (range thread-count)]
     (.start (Thread. (fn []
                        (loop [c 0]
                          (if (< c loop-count)
                            (do
                              (if-let [v (c/lookup @lu-cache i)]
                                (swap! lu-cache c/hit i)
                                (swap! lu-cache c/miss i i))
                              (recur (inc c)))
                            (.countDown latch)))))))
   (.await latch))

Exception in thread "Thread-1664" Exception in thread "Thread-1682" Exception in thread "Thread-1690" java.lang.NullPointerException
        at clojure.lang.Numbers.ops(Numbers.java:1068)
        at clojure.lang.Numbers.inc(Numbers.java:137)
        at clojure.core$inc.invokeStatic(core.clj:927)
        at clojure.core$inc.invoke(core.clj:922)
        at clojure.lang.AFn.applyToHelper(AFn.java:154)
        at clojure.lang.AFn.applyTo(AFn.java:144)
        at clojure.core$apply.invokeStatic(core.clj:667)
        at clojure.core$update_in$up__6853.invoke(core.clj:6185)
        at clojure.core$update_in.invokeStatic(core.clj:6186)

...
Exception in thread "Thread-1851" Exception in thread "Thread-1792" java.lang.NullPointerException
Exception in thread "Thread-1739" java.lang.NullPointerException
Exception in thread "Thread-1863" java.lang.NullPointerException
Exception in thread "Thread-1840" java.lang.NullPointerException
Exception in thread "Thread-1850" java.lang.NullPointerException
Exception in thread "Thread-1825" java.lang.NullPointerException
Exception in thread "Thread-1859" java.lang.NullPointerException
Exception in thread "Thread-1740" java.lang.NullPointerException
Exception in thread "Thread-1743" java.lang.NullPointerException
Exception in thread "Thread-1741" java.lang.NullPointerException
Exception in thread "Thread-1849" Exception in thread "Thread-1742" java.lang.NullPointerException
Exception in thread "Thread-1839" Exception in thread "Thread-1729" java.lang.NullPointerException
Exception in thread "Thread-1862" java.lang.NullPointerException
Exception in thread "Thread-1845" java.lang.NullPointerException
...

This example also dereferences the cache twice, once to check if the value is present with lookup, and then again when doing the hit or miss functionality. This NPEs on the LU cache and seems less than optimal with the other caches.

clj-http

This repo includes an example of a caching middleware

(defn- cached-response
  ([client req]
   (let [cache-key (str (:server-name req) (:uri req) "?" (:query-string req))]
     (if (cache/has? @http-cache cache-key)
       (do
         (println "CACHE HIT")
         (reset! http-cache (cache/hit @http-cache cache-key)) ; update cache stats
         (cache/lookup @http-cache cache-key)) ; return cached value
         ; do not invoke further middleware
       (do
         (println "CACHE MISS")
         (let [resp (update (client req) :body slurp-bytes)] ; middleware chain invoked
           (when (and (http/success? resp) (= (:request-method req) :get))
             (reset! http-cache (cache/miss @http-cache cache-key resp)) ; update cache value
             resp)))))))

;; in essence
(if (cache/has? @cache k)
  (do (swap! cache cache/hit k)
      (cache/lookup @cache k))
  (do (let [value (compute k)]
        (swap! cache cache/miss k value)
        value)))

This has a good aspect on the miss branch and a bad example on the hit branch. I'm omitting the reset! usage as that's not great usage of the Atom api. The good aspect in the miss branch is that the value is computed, put into the cache, and then returned without looking the value up in the cache container. It is not guaranteed to be there. This error avoided in the miss branch is exemplified in the hit branch. The fact that one derefed cache value cache/has?\ an entry does not guarantee that lookup will succeed. This is seemingly true of all of the cache's besides the basic cache. And the LU bug should NPE here when hit is called and the cache doesn't have the value.

(doseq [[cache-type cache'] [#_[:lu (c/lu-cache-factory {} :threshold 4)]
                             [:lru (c/lru-cache-factory {} :threshold 4)]
                             [:ttl (c/ttl-cache-factory {} :ttl 20)]]]
  (let [cache (atom cache')
        thread-count 20
        loop-count 20000
        latch (java.util.concurrent.CountDownLatch. thread-count)
        has-but-missing (atom 0)]
    (doseq [i (range thread-count)]
      (.start (Thread. (fn []
                         (loop [c 0]
                           (if (< c loop-count)
                             (do (if (c/has? @cache i)
                                   (do (swap! cache c/hit i)
                                       (if-let [v (c/lookup @cache i)]
                                         ::good
                                         (swap! has-but-missing inc)))
                                   (swap! cache c/miss i i))
                                 (recur (inc c)))
                             (.countDown latch)))))))
    (.await latch)
    (println cache-type " has? but missing" @has-but-missing)))
:lru  has? but missing 74
:ttl  has? but missing 89
nil

Each of these is an example where the cache reported that it had a value and then subsequent access came back empty. This is a classic race condition. Using this pattern allows for the scenario where no value to computed and no value is retrieved from the cache.

Other examples of this:

metamorpohsis: https://github.com/killme2008/Metamorphosis/blob/master/metamorphosis-dashboard/src/main/clojure/com/github/killme2008/metamorphosis/dashboard/stats.clj#L48

A good example

https://github.com/datacrypt-project/hitchhiker-tree/blob/master/src/hitchhiker/redis.clj

(let [cache (-> {}
                (cache/lru-cache-factory :threshold 10000)
                atom)]
  (defn totally-fetch
    [redis-key]
    (let [run (delay
                (loop [i 0]
                  (if (= i 1000)
                    (do (println "total fail") (throw (ex-info "total fail" {:key redis-key})))
                    (let [x (wcar {} (car/get redis-key))]
                      (if x
                        x
                        (do (Thread/sleep 25) (recur (inc i))))))))
          cs (swap! cache (fn [c]
                            (if (cache/has? c redis-key)
                              (cache/hit c redis-key)
                              (cache/miss c redis-key run))))
          val (cache/lookup cs redis-key)]
      (if val (<?? val) @run))))

The important part is separating when the cache is a value and when the cache is a mutable location. The hit and has?/miss is inside of the the swap! function. The cache returned from the swap is the one used to get the value. There's a nice function that encapsulates this:

(defn through-cache
  "The basic hit/miss logic for the cache system.  Like through but always has
  the cache argument in the first position for easier use with swap! etc."
  ([cache item] (through-cache cache item default-wrapper-fn identity))
  ([cache item value-fn] (through-cache cache item default-wrapper-fn value-fn))
  ([cache item wrap-fn value-fn]
   (if (clojure.core.cache/has? cache item)
     (clojure.core.cache/hit cache item)
     (clojure.core.cache/miss cache item (wrap-fn #(value-fn %) item)))))

I think this is the proper api of core.cache. Use through-cache to get a new cache value and use that exclusively. The resulting cache mutable container is not guaranteed to have the value and cannot be relied on for lookup. This is of course standard interaction with an atom where multiple dereferences are bad. And of course the lookup-or-miss function in clojure.core.cache.wrapped is probably what should always be used:

(defn lookup-or-miss
  "Retrieve the value associated with `e` if it exists, else compute the
  value (using value-fn, and optionally wrap-fn), update the cache for `e`
  and then perform the lookup again.

  value-fn (and wrap-fn) will only be called (at most) once even in the
  case of retries, so there is no risk of cache stampede.

  Since lookup can cause invalidation in some caches (such as TTL), we
  trap that case and retry (a maximum of ten times)."
  ([cache-atom e value-fn]
   (lookup-or-miss cache-atom e default-wrapper-fn value-fn))
  ([cache-atom e wrap-fn value-fn]
   (let [d-new-value (delay (wrap-fn value-fn e))]
     (loop [n 0
            v (c/lookup (swap! cache-atom
                               c/through-cache
                               e
                               default-wrapper-fn
                               (fn [_] @d-new-value))
                        e
                        ::expired)]
       (when (< n 10)
         (if (= ::expired v)
           (recur (inc n)
                  (c/lookup (swap! cache-atom
                                   c/through-cache
                                   e
                                   default-wrapper-fn
                                   (fn [_] @d-new-value))
                            e
                            ::expired))
           v))))))

It seems to me that lookup-or-miss is by far the best way to interact with an atom backed cache and is basically the only function that should be called. The CacheProtocol is useful but invites the caller to do too much outside of a swap function.

clojure.core.cache.wrapped

The namespace clojure.core.cache.wrapped provides some helper functions for when operating on an atom stored cache. It provides dereferencing functions for has?, hit, miss, evict, and seed. I think these functions are footguns and should almost never be used as they invite checking the cache and operating on a cache which doesn't have the value.

Operating on just a cache value (not an atom)

The protocol even invites using has? and friends on a cache value rather than an atom, but even this is isn't safe. In the above examples, most of the bugs came from other threads hammering a cache in between a has? check and then lookup. However, even a value isn't safe in all cases. Most of the caches either have a value or don't so they are safe. But the TTL cache has a temporal aspect that can cause a has? check to return true and then the subsequent lookup to fail.

(doseq [[cache-type init] [[:lu (c/lu-cache-factory {} :threshold 4)]
                           [:ttl (c/ttl-cache-factory {} :ttl 50)]]]
  (let [cache-atom (atom init)
        thread-count 200
        loop-count 20000
        latch (java.util.concurrent.CountDownLatch. thread-count)
        has-but-no-value (atom 0)]
    (doseq [i (range thread-count)]
      (.start (Thread. (fn []
                         (loop [c 0]
                           (if (< c loop-count)
                             (do
                               (let [cache-value @cache-atom]
                                 (if (c/has? cache-value i)
                                   ;; this is just a value, so if it has, we can lookup?
                                   (if-let [v (c/lookup cache-value i)]
                                     ::good
                                     (swap! has-but-no-value inc))
                                   (swap! cache-atom c/miss i i)))
                               (recur (inc c)))
                             (.countDown latch)))))))
    (.await latch)
    (println "has? but no value: " @has-but-no-value)))
has? but no value:  0
has? but no value:  224
nil

The lu cache always had a value when has? returns true. But the ttl expired inbetween the has? and lookup checks on the value 224 times. Therefore, just using the CacheProtocol on an arbitrary cache isn't safe.

So what if we adjust this and use the through-cache function which uses the helpful logic that the resulting cache has the value?

(doseq [[cache-type init] [[:lu (c/lu-cache-factory {} :threshold 4)]
                           [:ttl (c/ttl-cache-factory {} :ttl 50)]]]
  (let [cache-atom (atom init)
        thread-count 200
        loop-count 20000
        latch (java.util.concurrent.CountDownLatch. thread-count)
        has-but-no-value (atom 0)]
    (doseq [i (range thread-count)]
      (.start (Thread. (fn []
                         (loop [c 0]
                           (if (< c loop-count)
                             (do
                               (let [cache-value (swap! cache-atom c/through-cache i (constantly i))]
                                 (if-let [v (c/lookup cache-value i)]
                                   ::good
                                   (swap! has-but-no-value inc)))
                               (recur (inc c)))
                             (.countDown latch)))))))
    (.await latch)
    (println "has? but no value: " @has-but-no-value)))
has? but no value:  0
has? but no value:  50
nil

When using the lu, we of course always have a value. But the ttl cache is still susceptible to returning a cache that doesn't have the value. It would seem that the only good way to interact with the cache is with clojure.core.cache.wrapped/lookup-or-miss.

As an addendum, when running the above comparisons and tracking the computations involved, we get the following numbers:

:lu
has? but no value: 0
computations: 19,566,746
:ttl
has? but no value: 45
computations: 565

and when run with the lookup-or-miss:

:lu
has? but no value: 0
computations: 7549
:ttl
has? but no value: 0
computations: 515

When we used the through-cache function we computed our value 19 million times, but had we not cached we would only have computed it (* 20 20000) = 400,000 times!. The contention to save the cached value dwarfed the number of times we even needed to check the value. The lookup-or-miss has a helpful strategy to just give up after 10 times and return the value. I also saw this same story when using core.memoize which uses core.cache with some major modifications under the hood.

The moral of the story

A couple points:

a core.cache is either a value or a mutable place which can give you a value. Use clojure.core.cache.wrapped/lookup-or-miss on an atom and be done with it. This should be the only function you use in most cases.
don't deref a cache (or in general, an atom) more than once. If you are, figure out how to use lookup-or-miss or through-cache instead.
the api kinda invites this. I think the functions in clojure.core.cache.wrapped for has?, hit, miss, and evict are foot guns and should never be used. The has?, hit, and miss, functions in clojure.core.cache should only be used inside of a single swap! function. However the protocol invites usage like this and the bugs are subtle.

Most of the bugs explored above arise only under high contention on the cache. Most caches probably aren't under this load and the bugs won't manifest. However, as things scale or caching code goes untouched for a while, this source of bugs could be quite nasty to track down and might only occur under production loads.

The above bugs in stencil, rieman, and the clj-http example should be fixed and I'm going to suubmit PRs for them soon. I want to raise an issue about the LU cache NPE but I'm not sure if its a bug or not. The docstring states that it should be called when the cache is known to have the key, but as discussed this is simply not possible. Most caches handle a missing key just find but the LU cache expects the key there and it to have a usage count.

I don't write often so I hope that the tone of this is exploration and thinking, not pointing at bugs. I wrote this on a Sunday when I was reading the core.cache library. Special thanks to Sean Corfield who writes so much amazing software and even more docs.