clojure - Why does blocking cause a lock -

i using following code logging part of 1 handling of request. code has been seen many times everywhere. when make multiple parallel calls, deadlock because of code.

(defn log [msg & vals]   (let [line (apply format msg vals)]     (locking system/out (println line)))) 

anyone knows going wrong here.

thanks

summary

i'd conjecture deadlock due log's interactions other code; in particular, expected when testing @ repl, reasons demonstrate below. (meaning straight clojure repl, opposed lein repl, other nrepl-based repls etc.)

the key issue involved has synchronizing on system/out, illustrates broader point it not idea synchronize on objects provided jdk or clojure themselves, may interfere existing locking protocols involving objects (which in fact case clojure's *out* , system/out, we'll see shortly). point illustrates locks not compose.

the answer begins offering solution , goes details of locking protocols involved in clojure printing, latter discussion bit on long side , basic recommendation can stated quite succinctly.

proposed solution

one way @ situation that, mentioned above, doesn't tend idea synchronize on objects provided core jvm classes or clojure, may interfere locking protocols these objects part of. instead, 1 can introduce new sentinel objects 1 owns , synchronize on them:

(def ^:private log-sentinel (object.))  (defn log [msg & vals]   (let [line (apply format msg vals)]     (locking log-sentinel       (println line))) 

you still interference unrelated printouts in form of output interleaving, of time shouldn't have such printouts (except perhaps repl prompt printouts, being out of order shouldn't of problem; debug printouts can use log well, , anyway, off in production, right?), , otherwise may prefer print logging output different output stream.

additionally, reasons discussed shortly, in case not necessary use one's own lock, long 1 uses print in place of println; fact print call takes 1 argument here key:

(defn log [msg & vals]   (let [line (str (apply format msg vals) "\n")]     (print line))) 

you may add call flush @ end if want cause immediate printout. (it possible flush happen after thread's print, in case printouts happen promptly.)

this version of log 1 recommend. simplest solution; additionally, protects printouts interleaving other printouts going through clojure's printing functions.

the printing facilities' locking protocol

cautionary notice: behaviour describe below, far can tell, not mentioned anywhere in jdk documentation, reliance on @ own risk (though it's not terrible risk take.)

in particular case worth noting *out* has locking protocol in place guarantees individual bits of output print & friends (such representations of individual arguments, spaces added between them , newlines added in prn / println) not interleaved.

the way works *out* default stores java.io.outputstreamwriter wrapping java.lang.system.out, known system/out. java.io.outputstreamwriter instance (in fact, java.io.writer instance) stores, in protected lock field, object synchronizes on when performing writes. in case of *out*, object happens system/out. print , friends feed arguments (and intervening spaces) *out* 1 one, so, mentioned above, individual argument protected being interleaved other data in output, several arguments single print call may broken apart. hence, building string , printing thread-safe, while multi-argument print convenient in simpler scenarios.

reasons deadlock when locking system/out @ repl

at point i'd reiterate think avoiding locking protocol using built-in objects synchronize on (1) idea in case, (2) should solve problem , (3) can recommend without asking more details codebase. on describing why such behaviour expected @ repl. the discussion below applies straight clojure repl, , not lein repl etc.

first, locks obtained synchronized (java) / locking (clojure) reentrant, explains fact there no problems log function in single-threaded use -- it's clear once control has reached body of locking form, current thread able print line (since holds system/out monitor).

introducing deadlock involving system/out simple enough:

(locking system/out   @(future (println :foo))) ; note @ ! 

with function call in middle, system may or may not deadlock:

(defn f [fut]   (locking system/out     @fut))  ;; deadlock or not depending on whether future quick enough (f (future (println :foo))) 

expanding upon comment in code snippet above, if future fails of printing (which here involves :foo, newline , flush operation, though last part depends on current value of *flush-on-newline*) before f acquires lock on system/out, , f's thread deadlock. if future fast print, it'll done before f acquires lock , fine.

now, when working in repl, similar condition possible:

(defn f [i]   (locking system/out     (println :foo i)))  (dotimes [i 10]   (future (f i))) 

this deadlocks consistently on machine without printing anything. iteration count bumped 10000, instead tends in quite lot of printouts, each on own line, before deadlocking.

in contrast,

(defn f [i]   (println :foo i))  (dotimes [i 10]   (future (f i))) 

prints out should, "in no particular order"; in particular, next prompt occurs in arbitrary place, not typically near end of printed text.

do note though in every case if printed @ all, each individual item (:foo, integers, spaces, newlines) printed separately (that without interleaving). is, of course, due aforementioned locking performed *out*.