How can I record time for function call in clojure

Question

I am newbie to Clojure. I am invoking Clojure function using java and I want to record the time a particular line of clojure code execution takes:

Suppose if my clojure function is:

     (defn sampleFunction [sampleInput]
         (fun1 (fun2 sampleInput))

Above function I am invoking from java which returns some String value and I want to record the time it takes for executing fun2.

I have a another function say logTime which will write the parameter passed to it in to some database:

      (defn logTime [time]
            .....
      )

My Question is: How can I modify my sampleFunction(..) to invoke logTime for recording time it took to execute fun2.

Thank you in advance.

Count Orlok · Accepted Answer · 2020-07-04 14:53:51Z

2

I'm not entirely sure how the different pieces of your code fit together and interoperate with Java, but here's something that could work with the way you described it.

To get the execution time of a piece of code, there's a core function called time. However, this function doesn't return the execution time, it just prints it... So given that you want to log that time into a database, we need to write a macro to capture both the return value of fun2 as well the time it took to execute:

(defmacro time-execution
  [& body]
  `(let [s# (new java.io.StringWriter)]
     (binding [*out* s#]
       (hash-map :return (time ~@body)
                 :time   (.replaceAll (str s#) "[^0-9\\.]" "")))))

What this macro does is bind standard output to a Java StringWriter, so that we can use it to store whatever the time function prints. To return both the result of fun2 and the time it took to execute, we package the two values in a hash-map (could be some other collection too - we'll end up destructuring it later). Notice that the code whose execution we're timing is wrapped in a call to time, so that we trigger the printing side effect and capture it in s#. Finally, the .replaceAll is just to ensure that we're only extracting the actual numeric value (in miliseconds), since time prints something of the form "Elapsed time: 0.014617 msecs".

Incorporating this into your code, we need to rewrite sampleFunction like so:

(defn sampleFunction [sampleInput]
  (let [{:keys [return time]} (time-execution (fun2 sampleInput))]
    (logTime time)
    (fun1 return)))

We're simply destructuring the hash-map to access both the return value of fun2 and the time it took to execute, then we log the execution time using logTime, and finally we finish by calling fun1 on the return value of fun2.

edited Jul 4, 2020 at 14:53

answered Jul 4, 2020 at 4:13

Count Orlok

1,0176 silver badges14 bronze badges

Sign up to request clarification or add additional context in comments.

5 Comments

ppp456878 Over a year ago

Thank you. It solves the problem. Is there a way I can do it without returning map like time-execution can log the time and should only return result? I was trying something like below and it doesn't seem to work. Can you tell me why? (defmacro time-execution [& body] `(let [s# (new java.io.StringWriter)] (binding [out s#] (let [return (time ~@body)] (logTime (.replaceAll (str s#) "[^0-9\\.]" "")) return)))) (defn sampleFunction [sampleInput] (fun1 (logTime time)))

Count Orlok Over a year ago

With the macro as you wrote it, might you have meant for sampleFunction to be (defn sampleFunction [sampleInput] (fun1 (time-execution (fun2 sampleInput))))?

ppp456878 Over a year ago

You are right. I meant the same. But it gives exception: Caused by: clojure.lang.ExceptionInfo: Call to clojure.core/let did not conform to spec. {:clojure.spec.alpha/problems ........ Any help to fix this error would be appreciated.

ppp456878 Over a year ago

I was able to achieve it by replacing let by def :)

Rhishikeshj Over a year ago

Be careful with this function. Since it redirects the output stream, if the body of the function being tracked has logs, printlns etc, 1. the s# param in the macro will capture it and you wont see anything 2. the calculation will be incorrect since it will now contain multiple lines so ideally you would have to do (-> s# str string/split-lines last (.replace) parseDouble)

Alan Thompson · Accepted Answer · 2020-07-04 17:36:50Z

The library tupelo.prof gives you many options if you want to capture execution time for one or more functions and accumulate it over multiple calls. An example:

(ns tst.demo.core
  (:use tupelo.core tupelo.test)
  (:require
    [tupelo.profile :as prof]))

(defn add2 [x y] (+ x y))
(prof/defnp fast [] (reduce add2 0 (range 10000)))
(prof/defnp slow [] (reduce add2 0 (range 10000000)))

(dotest
  (prof/timer-stats-reset)
  (dotimes [i 10000] (fast))
  (dotimes [i 10] (slow))
  (prof/print-profile-stats)
  )

with result:

--------------------------------------
   Clojure 1.10.2-alpha1    Java 14
--------------------------------------

Testing tst.demo.core

    ---------------------------------------------------------------------------------------------------
    Profile Stats:
       Samples       TOTAL        MEAN      SIGMA           ID
        10000        0.955     0.000096   0.000045   :tst.demo.core/fast                                                              
           10        0.905     0.090500   0.000965   :tst.demo.core/slow                                                              
    ---------------------------------------------------------------------------------------------------

If you want detailed timing for a single method, the Criterium library is what you need. Start off with the quick-bench function.

Rhishikeshj · Accepted Answer · 2022-11-02 16:32:03Z

1

Since the accepted answer has some shortcomings around eating up logs etc, A simpler solution compared to the accepted answer perhaps

(defmacro time-execution [body]
  `(let [st# (System/currentTimeMillis)
         return# ~body
         se# (System/currentTimeMillis)]
      {:return return#
       :time (double (/ (- se# st#) 1000))}))

answered Nov 2, 2022 at 16:32

Rhishikeshj

3132 silver badges9 bronze badges

Collectives™ on Stack Overflow

How can I record time for function call in clojure

3 Answers 3

5 Comments

Comments

Comments

Your Answer

Hot Network Questions

Collectives™ on Stack Overflow

3 Answers 3

5 Comments

Comments

Comments

Your Answer

Sign up or log in

Post as a guest

Related