clojureclojure-java-interop

How can I record time for function call in clojure


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.


Solution

  • 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.