tags:

views:

91

answers:

1
(use '[clojure.contrib.trace])
(dotrace [str] (reduce str [\a \b]))
+7  A: 

In a nutshell:

That's because trace-fn-call, which is the thing dotrace uses to wrap the functions to be traced, uses str to produce the nice TRACE foo => val output.

Extended explanation:

The dotrace macro does its magic by installing a thread binding for each Var holding a function to be traced; in this case, there is one such Var, clojure.core/str. The replacement looks roughly like so:

(let [f @#'str]
  (fn [& args]
    (trace-fn-call 'str f args)))

The trace-fn-call, to quote its docstring, "Traces a single call to a function f with args.". In doing so, it calls the traced function, takes note of the return value, prints out a nice informative message of the form TRACE foo => val and returns the value obtained from the traced function so that regular execution may continue.

As mentioned above, this TRACE foo => val message is produced used str; however, in the case at hand, this is actually the function being traced, so a call to it leads to another call to trace-fn-call, which makes its own attempt to produce the tracing output string using str, which leads to another call to trace-fn-call... ultimately leading to the stack blowing up.

A workaround:

The following modified versions of dotrace and trace-fn-call should work fine even in the presence of weird bindings for core Vars (note that futures may not be scheduled promptly; if that's a problem, see below):

(defn my-trace-fn-call
  "Traces a single call to a function f with args.  'name' is the
  symbol name of the function."
  [name f args]
  (let [id (gensym "t")]
    @(future (tracer id (str (trace-indent) (pr-str (cons name args)))))
    (let [value (binding [*trace-depth* (inc *trace-depth*)]
                  (apply f args))]
      @(future (tracer id (str (trace-indent) "=> " (pr-str value))))
      value)))

(defmacro my-dotrace
  "Given a sequence of function identifiers, evaluate the body
   expressions in an environment in which the identifiers are bound to
   the traced functions.  Does not work on inlined functions,
   such as clojure.core/+"
  [fnames & exprs]
  `(binding [~@(interleave fnames
                           (for [fname fnames]
                             `(let [f# @(var ~fname)]
                                (fn [& args#]
                                  (my-trace-fn-call '~fname f# args#)))))]
     ~@exprs))

(Rebinding trace-fn-call around a regular dotrace apparently doesn't work; my guess is that's because of clojure.* Var calls still being hard-wired by the compiler, but that's a separate matter. The above will work, anyway.)

An alternative would be to use the above my-dotrace macro together with a my-trace-fn-call function not using futures, but modified to call custom replacements for the clojure.contrib.trace functions using the following in place of str:

(defn my-str [& args] (apply (.getRoot #'clojure.core/str) args))

The replacements are straightforward and tedious and I omit them from the answer.

Michał Marczyk
Should this be considered a bug and where should it be reported? Or should I rebind str to smth to make this work?
Michiel Borkent
It seems like at least a documentation bug, although I have a couple of ideas for non-earth-shattering modifications to `c.c.trace` which would make it more robust in the face of core Vars being rebound... I might look into testing some designs. For the time being, I've edited in a workaround -- I hope it's acceptable to you. A straightforward rebinding of anything wouldn't work, I'm afraid.
Michał Marczyk