calip(er)
measuring and debugging functions on demand without a need to alter the code
what does it do?
calip measures and debugs functions on demand, or in case of an error, without a need to alter the code.
it does so by adding an AOP around advice (i.e. a weaved timer function wrapper) with robert hooke
it comes really handy at development time, as well as for deployed applications:
- when you need on demand performance metrics with runtime arguments
- when you need to see the actual runtime function arguments in case of an error
- when you need to see the actual runtime function arguments as the program is running
in which case you can just connect to a deployed application via an nREPL, and add measurements, handlers, logs to any "functional suspect".
performance on demand
let's pretend we have an app with two functional suspects:
if playing from the calip source dir you can:
$ make repl
=> (defn rsum [n] (reduce + (range n)))
#'user/rsum
=> (defn rmult [n] (reduce *' (range 1 n)))
#'user/rmult
=> (rsum 10)
45
=> (rmult 10)
362880
now let's measure them:
=> (require '[calip.core :as calip])
=> (calip/measure #{#'user/rsum
#'user/rmult})
=> (rsum 10)
"#'user/rsum" args: (10) | took: 13,969 nanos | returned: 45
45
=> (rmult 10)
"#'user/rmult" args: (10) | took: 16,402 nanos | returned: 362880
362880
(10) here shows the runtime arguments to a function that is measured, or "an" argument in this case.
these measurements can be removed of course:
=> (calip/uncalip #{#'user/rsum})
=> (rsum 10)
45
=> (rmult 10)
"#'user/rmult" args: (10) | took: 17,479 nanos | returned: 362880
362880
or remove it from both:
=> (calip/uncalip #{#'user/rsum #'user/rmult})
=> (rsum 10)
45
=> (rmult 10)
362880
taming runtime errors
most of the time, in case of a runtime error/exception, JVM reports an array of stack trace elements, each representing one stack frame. This array is also known as a stacktrace.
while it is immensely useful for tracking down an error scope (i.e. where it happened), it falls short to provide a state snapshot at the time an error occurred: i.e. "what were the arguments passed to a function at the time the error occurred?"
calip helps tracking down these runtime arguments by setting an ":on-error?" flag on a measurement.
measuring on error
as an example let's take a function that creates a socket (i.e. connects) to external systems:
=> (defn connect [{:keys [host port]}]
(java.net.Socket. host port))
=> (connect {:host "my-good-host.com" :port 7889})
#object[java.net.Socket 0x59cdc19b "Socket[addr=my-good-host.com/10.X.X.23,port=7889,localport=62446]"]
=> (connect {:host "8.8.8.8" :port 1025})
java.net.ConnectException: Operation timed out
=> (connect {:host "127.0.0.1" :port 1025})
java.net.ConnectException: Connection refused
in case of an error JVM reports an exception but there is no visual on what the arguments were at the time of this exception.
let's fix it without a code change / on a running application:
=> (calip/measure #{#'user/connect} {:on-error? true})
we can still normally connect without any extra logging / metrics:
=> (connect {:host "my-good-host.com" :port 7889})
#object[java.net.Socket 0x3bc7a27c "Socket[addr=my-good-host.com/10.X.X.23,port=7889,localport=62446]"]
but in case of an error, in addition to the time a function took, calip will report the actual runtime args that led to this error:
=> (connect {:host "8.8.8.8" :port 1025})
"#'user/connect" args: ({:host "8.8.8.8", :port 1025}) | took: 75,696,573,373 nanos | error: java.net.ConnectException: Operation timed out
java.net.ConnectException: Operation timed out
=> (connect {:host "127.0.0.1" :port 22})
"#'user/connect" args: ({:host "127.0.0.1", :port 22}) | took: 309,753 nanos | error: java.net.ConnectException: Connection refused
java.net.ConnectException: Connection refused
:on-error?flag can be combined with a custom:reportfunction that is documented in the next section
reporting
by default calip will use println and a "default format" as shown above to report metrics, but it is pluggable.
you can pass a report function to calip/measure. calip would pass a map to this function with:
{:took took ;; time this function took to execute in nanoseconds
:fname fname ;; function name with a namespace
:args args ;; arguments that were passed to this function
:returned / :error} ;; a :returned value or an :error [depending on whether the :on-error? flag is set]
quite a useful scenario is to use calip to measure or debug parts of the application that writes logs. We can tap into that:
=> (require '[clojure.tools.logging :as log])
=> (calip/measure #{#'user/rsum #'user/rmult} {:report #(log/info (calip/default-format %))})
=> (rsum 10)
13:42:04.048 [nREPL-worker-24] INFO user - "#'user/rsum" args: (10) | took: 14,928 nanos | returned: 45
45
=> (rmult 10)
13:42:07.687 [nREPL-worker-24] INFO user - "#'user/rmult" args: (10) | took: 16,280 nanos | returned: 362880
362880
notice we used (calip/default-format %) to format that {:took .., :fname .., :args .., :returned} map, but you can of course customize it.
custom reporting
=> (defn create-life [{:keys [galaxy planet]}] "creating life...")
#'user/create-life
=>
=> (create-life {:galaxy "pegasus" :planet "athos"})
"creating life..."
=> (calip/measure #{#'user/create-life} {:report (fn [{:keys [took fname]}]
(log/info fname "took" took "ns"))})
=> (create-life {:galaxy "pegasus" :planet "athos"})
13:54:20.334 [nREPL-worker-25] INFO user - #'user/create-life took 2637 ns
"creating life..."
or with args and return values:
=> (calip/measure #{#'user/create-life} {:report (fn [{:keys [took fname args returned]}]
(log/info "\n|>" fname
"\n|> with args:" args
"\n|> took:" took
"ns \n|> return value:" returned))})
=> (create-life {:galaxy "pegasus" :planet "athos"})
INFO user -
|> #'user/create-life
|> with args: ({:galaxy pegasus, :planet athos})
|> took: 2911 ns
|> return value: creating life...
"creating life..."
custom reports on errors
a custom :report function can be combined with an :on-error? flag:
user=> (calip/measure #{#'user/connect}
{:on-error? true
:report #(log/info (calip/default-format %))})
user=> (connect {:host "127.0.0.1" :port 22})
INFO user - "#'user/connect" args: ({:host "127.0.0.1", :port 22}) | took: 339,019 nanos | error: java.net.ConnectException: Connection refused
or
user=> (calip/measure #{#'user/rsum}
{:report #(log/info (calip/default-format %))
:on-error? true})
user=> (rsum "oops")
INFO user - "#'user/rsum" args: ("oops") | took: 87,268 nanos | error: java.lang.ClassCastException: java.lang.String cannot be cast to java.lang.Number
match and wrap many functions
while profiling applications there are two questions that are very frequent:
out of all these functions what exactly takes so long?
and
how long does each function take in this module (namespace)?
instead of explicitly listing all the functions in a particular namespace, calip accepts strings in a:
"#'foo.bar/prefix-*"format that would expand to include function names that starts with "prefix-" in a particular namespace"#'foo.bar/*"format that would expand to include all the functions in a particular namespace
for example wrap only functions in a user namespace that start with "r":
user=> (calip/measure #{"#'user/r*"})
adding hook to #'user/rmult
adding hook to #'user/rsum
or all of the functions in the user ns:
user=> (calip/measure #{"#'user/*"})
would add "hooks" to:
adding hook to #'user/+version+
adding hook to #'user/check-sources
adding hook to #'user/dev
adding hook to #'user/log4b
adding hook to #'user/rmult
adding hook to #'user/rsum
i.e. it expands "#'user/*" into all the 'user functions currently known to the runtime.
license
Copyright © 2021 tolitius
Distributed under the Eclipse Public License either version 1.0 or (at your option) any later version.
Can you improve this documentation? These fine people already did:
anatoly & AnatolyEdit on GitHub
cljdoc is a website building & hosting documentation for Clojure/Script libraries
× close