It was a beautiful day in the Onfido Lisbon office, when we updated the dependencies of one of our Elixir projects and the dreaded RETIRED! warning appeared on our screen :screaming_emoji::
https://gist.github.com/52f028b5e2e204e53ba439be11d80ac3
Up to this point we used ex_statsd to collect metrics about our Elixir applications, particularly to measure the time our functions take. This was really easy, because ex_statsd provided a deftimed macro that we used to define the functions that we wanted to measure.
https://gist.github.com/52f9cddddf97a784966c20f0ec71d477
In the previous snippet you can find an example of how we used the deftimed macro and the module attributes that were used by the ex_statsd library.
The deprecation notice recommended the usage of the statix library instead. But this library didn't provide any macros or any sort of "decorators" that allowed us to easily measure the time our functions take 😢.
The statix library only provides us the raw StatsD primitives like increment, count and measure, so we need to change the functions if we want to measure them. On the other hand, we don't want to change any function that we have because we consider instrumentation a cross-cutting concern that should not "leak" into the existing codebase.
What we need is a way to say: when my function Foo.bar/2 completes successfully, call this "on success" function. If it raises an error instead, call this "on error" function. Because we want to emit StatsD metrics, the success and error callback functions would use the statix library to emit the respective metrics.
The previous scenario was enough for us to define a first set of requirements, and thus the interceptor library was born!
Given our previous experience with ex_statsd, we wanted our library to behave differently in at least two aspects.
We wanted to have all the instrumentation configuration in a single module, instead of having it scattered throughout the entire codebase a la ex_statsd.
And we also wanted to address one shortcoming of the ex_statsd library: by using its deftimed macro, whenever a function call raised an error, the metric wouldn't be emitted (in other words, ex_statsd only measures the time a function takes when it succeeds). This was particularly bad when a function raised an error due to a timeout, for example, because we wouldn't see in our charts the time the function call took before the timeout.
Since we were decided to create a new library to help us replace the ex_statsd-based metric collection we had in place, the new library should allow us to send a metric independently of the function call outcome.
Because we didn't find a library that allowed us to easily intercept function calls in Elixir, we decided to create our own.
We wanted to intercept function calls so we could collect metrics about our applications, paving the way for us to replace the ex_statsd usage with the recommended statix library. We also wanted to configure all interceptions in a single place. This would allow us to have the StatsD metric definitions in a centralized place, instead of being scattered all over the code as we had with ex_statsd.
Here's how we would configure the interception of a Foo.bar/2 function. We would define a Instrumentation.Config module that exposes a get/0 function:
https://gist.github.com/0083aa8d4e5761fed6bb77e74165a281
In the previous configuration module we're saying any call to the Foo.bar/2 function should be intercepted if successful by the Instrumentation.success_callback/3 function, whereas if it raises an error, it should be intercepted by the Instrumentation.error_callback/3 function.
We now need to point to the previous interception configuration module in the application configuration file (e.g. config/config.exs):
https://gist.github.com/9985ad1eb42e9ca0ffe40205dfe4c319
The previous on_success and on_error functions would receive as arguments the MFA (module, function, and, in our case, the arguments, not the arity) of the called function, the function result/error and the start timestamp (in microseconds).
Let's define our callback functions in the Instrumentation module. Each callback calculates the time the execution of the function takes (in milliseconds) and emits the respective StatsD metric with the help of statix:
https://gist.github.com/a088bcdf17199f1d42c69c3d866e366a
Because we are passing to our callbacks the success result or the error raised by the function, the callback function is able to act on it. And because it has access to the start timestamp, the callback can also calculate how long the function took, independently of the outcome (something we weren't able to do with ex_statsd).
Below you can find the Foo.bar/2 function that we want to measure. To allow the interceptor library to change the Foo.bar/2 function, we need to enclose the functions we want to intercept in an Interceptor.intercept/1 macro:
https://gist.github.com/5b081afdd5c0c2cf1566543e15214728
The interceptor library will transform the previous function into something that looks like this right before it is compiled into BEAM bytecode:
https://gist.github.com/c957afbe4bd97777ef5e183ab460978d
It's a big snippet to digest, but if you look closely, we just wrapped the original Foo.bar/2 function body (i.e., x / y) in a try ... rescue construct. And then we use the Kernel.apply/3 function to send the success result or the error to the respective callback. In the end of the successful code path we return the success_result value; if an error was raised somewhere down the line, we re-raise the error. This way we keep the semantics the function had.
To measure a new function with this approach, we just need to wrap the function with a Interceptor.intercept/1 do-block and configure how the interception should work in the Instrumentation.Config module. And we can now rely on statix, instead of the deprecated ex_statsd library, hurray!
You can find the interceptor library on Github, and its documentation on HexDocs. Besides the on_success and on_error callbacks, you can also configure callback functions that are called before the function starts or after it ends. If none of these callbacks work for you, you can opt to define a wrapper callback function that will receive a lambda function with the body of the intercepted function. This way you can control how the function is called and ultimately what it returns.
You may have found the configuration map returned by the Instrumentation.Config.get/0 function too cumbersome. Let me tell you that you're not alone :). Stay tuned because there will be a follow-up blog post where we'll create a DSL to simplify the callback configuration.
If you like to know more about Elixir metaprogramming, you can find a chapter dedicated to it in my recent book, Mastering Elixir.