CODEWITHSUNDEEP
clojuremacros
Carcigenicate
Carcigenicate

Reputation: 45741

Simple macro doesn't seem to execute given forms

I'm using this basic macro as a building block for other timing macros:

(defmacro time-pure
  "Evaluates expr and returns the time it took.
  Modified the native time macro to return the time taken."
  [expr]
  `(let [start# (current-nano-timestamp)
         ret# ~expr]
     (/ (double (- (current-nano-timestamp) start#)) 1000000.0)))

I've tested this, and used it in other macros, so I know it works fine.

My problem can be described by the following snippet:

(defmacro time-each [& exprs]
  `(mapv #(time-pure %) '~exprs))

I would expect this to give each expression to time-each, where it executes and times it; returning the result. When I test it however, it finishes instantly:

(time-each
  (Thread/sleep 500)
  (Thread/sleep 1000))

[0.036571 0.0]

I'm confused by this since I know that (time-pure (Thread/sleep 1000)) will take around a second to return, and all this macro does it delegate to time-pure.

What's causing this? I really have no idea how to properly debug a macro. I used macro-expand-1 to inspect the generated code:

(clojure.pprint/pprint
  (macroexpand-1
    '(time-each
      (Thread/sleep 500)
      (Thread/sleep 1000))))

(clojure.core/mapv
 (fn*
  [p1__1451__1452__auto__]
  (helpers.general-helpers/time-pure p1__1451__1452__auto__))
 '((Thread/sleep 500) (Thread/sleep 1000)))

But nothing really stands out to me.

What's going on here?

(Note, this is a dupe of a question I posted a few minutes ago. I realized the case I was showing was convoluted, so I made up a better example.)

Upvotes: 1

Views: 68

Answers (3)

kennytilton
kennytilton

Reputation: 1064

"I'm still trying to don't wrap my head around macros."

It takes a while. :) One thing that helped me was macro-expanding:

(macroexpand-1  '(time-each (+ 2 2 )(+ 3 3)))

That produces:

(clojure.core/mapv
    (fn* [p1__24013__24014__auto__] 
        (rieclj.core/time-pure p1__24013__24014__auto__))
    (quote ((+ 2 2) (+ 3 3))))

The alarming thing there is that time-pure is being passed a quoted list, so it is all just symbols at run time, not macroexpansion time.

Then another thing that helped me was that the beauty of Lispy macros is that they are normal functions that just run at a different time (while the reader is processing the source). But because they are normal functions we can probe them with print statements just as we probe normal code.

I have modified time-pure to print out its macroexpansion-time argument expr and, in the generate code, to have it print out the evaluated input, which we now suspect is a list of symbols, or '(+ 2 2) in the first case.

(defmacro time-pure
  "Evaluates expr and returns the time it took.
   Modified the native time macro to return the time taken."
  [expr]
 (prn :time-pure-sees expr)
 `(let [start# (now)
        ret# ~expr]
    (prn :ret-is ret# (type (first  ret#)))
    (/ (double (- (now) start#)) 1000000.0)))

I print the type of the first of ret to drive home that + is a symbol, not a function. Evaluating:

(time-each (+ 2 2 )(+ 3 3))

yields:

:time-pure-sees p1__24013__24014__auto__
:ret-is (+ 2 2) clojure.lang.Symbol
:ret-is (+ 3 3) clojure.lang.Symbol

Seeing (+ 2 2) might make you think all is well, but the key is that the rightside is '(+ 2 2) so ret# gets bound to that symbolic expression instead of the intended computation.

Again, printing the type of the first hopefully makes clear that time-pure was working on a list of symbols at runtime.

Sorry if all that was confusing, but the moral is simple: use macroexpand-1 and embedded print statements when macros mess with your head. In time you will internalize the two different times, macroexpansion and run.

Upvotes: 0

Shlomi
Shlomi

Reputation: 4748

Solution

I think what happens here is that your mapv executes after compile time, meaning at run time, this is why it cant just "paste" the code list as an sexp. I think a better approach would be to keep the mapv out of the syntax quoting:

(defmacro each-time-mine [& exprs]
  (mapv #(time-pure %) exprs))


(each-time-mine
  (Thread/sleep 500)
  (Thread/sleep 1000))

[501.580465 1001.196752]

Original

Although eval is usually frowned upon, it seems to solve the problem in this situation:

(defmacro time-pure
  [expr]
  `(let [start# (current-nano-timestamp)
         ret# (eval ~expr)]
     (/ (double (- (current-nano-timestamp) start#)) 1000000.0)))

(defmacro time-each [& exprs]
  `(mapv #(time-pure %) '~exprs))

(time-each
  (Thread/sleep 500)
  (Thread/sleep 1000))

[501.249249 1001.242522]

What happens is that mapv sees the sexps as lists, and at the moment time-pure wants to execute them, it simply assigns ret# the value of the list. So that list needs to be evaled.

There might be better ways to achieve this though.

Upvotes: 2

amalloy
amalloy

Reputation: 91907

(defmacro time-each [& exprs]
  `(list ~@(for [expr exprs]
             `(time-pure ~expr))))

You need to be careful not to evaluate an expression outside of a time-pure context, as is done in Arthur's answer, which evaluates each expression and then calls time-pure on the (very fast) operation of "looking at the result". Rather, wrap time-pure around each expression before evaluating it.

Upvotes: 1

Related Questions