Surprising timeout chan interactions in Clojure's core.async

note that this behavior applies to core.async 0.1.338.0-5c5012-alpha

The issue distilled

Let’s measure the time it takes to create two timeout chans, close one, and read from the other.

(let [a (timeout 100)
      b (timeout 100)
      t0 (System/currentTimeMillis)]
  (close! a)
  (<!! b)
  (- (System/currentTimeMillis) t0))
;; => 0

What happened? Why don’t we see a value ~100ms corresponding to b’s timeout?

What’s going on?

Let’s dive into the code! The relevant bit’s in timers.clj

(defn timeout
  "returns a channel that will close after msecs"
  [^long msecs]
  (let [timeout (+ (System/currentTimeMillis) msecs)
        me (.ceilingEntry timeouts-map timeout)]
    (or (when (and me (< (.getKey me) (+ timeout TIMEOUT_RESOLUTION_MS)))
          (.channel ^TimeoutQueueEntry (.getValue me)))
        (let [timeout-channel (channels/chan nil)
              timeout-entry (TimeoutQueueEntry. timeout-channel timeout)]
          (.put timeouts-map timeout timeout-entry)
          (.put timeouts-queue timeout-entry)
          timeout-channel))))

Bells are probably going off when you see TIMEOUT_RESOLUTION_MS (defined above: (def ^:const TIMEOUT_RESOLUTION_MS 10)). Let’s unpack the surrounding code. First in our let block, we have timeout, which converts the relative msecs into a clock time to expire. We then set me to (.ceilingEntry timeouts-map timeout).

timeouts-map is a java.util.concurrent.ConcurrentSkipListMap and its method ceilingEntry “Returns a key-value mapping associated with the least key greater than or equal to the given key, or null if there is no such entry”. So me will be the entry (if present) in timeouts-map with the first value that’s greater than timeout.

The unexpected behavior comes from the next line

(when (and me (< (.getKey me) (+ timeout TIMEOUT_RESOLUTION_MS)))
          (.channel ^TimeoutQueueEntry (.getValue me)))

So, if we found an me, and its key is within the tolerance of TIMEOUT_RESOLUTION_MS, we return an existing channel rather than creating a new one! This explains the behavior at the top: a and b share a channel, so closing a immediately closed b, allowing the entire block to evaluate almost instantly.

Thanks!

A huge thanks to Brian Rowe