How I Built Timeasure: Part 2 — Collecting Measurements & Supplying Configuration
This story continues How I Built Timeasure: Part 1 — Motivation & Method Wrapping.
The previous story described Timeasure (see: Github / RubyGems / Live Demo), a new gem that helps Ruby developers in measuring the runtime of their methods in production and gaining valuable knowledge regarding the proper path to optimization. In the previous story, I explored the main interface Timeasure offers for that purpose and have demonstrated how it was designed and crafted.
In this post I will dive into Timeasure’s profiling manager — the component that is concerned with collecting each measurement that is produced by a call to a tracked method. I will also discuss Timeasure’s configuration mechanism, which allows greater adaptability for various usages of the gem.
Along the way, I will explain some of my design decisions in-depth and share some helpful tips about working with lambdas in configuration objects to in order to achieve that adaptability. If you are not familiar with lambdas and callable objects, don’t worry — it will be explained later on.
(As in the previous story, please note that when I refer to Timeasure’s source code in this post, I will be doing so by a link on the word “code” in parenthesis.)
Handling Measurements With The Profiling Manger
Timeasure was designed with flexibility in mind, so I tried to keep the different parts easily configurable, as will be demonstrated later on. However, for clarity, I will focus on the default, out-of-the-box path first.
Since what Timeasure basically does is wrapping methods with some additional code, I wanted to keep what happens after the original method to be as light as possible. I believe that this means minimal processing and storing of the measurement’s data. Since there are several data points related to a single measurement, I introduced the Measurement class (code).
Upon each call to a tracked method, Timeasure creates a new Measurement object (code). This object holds the name of the method in question and its class, along with t0 and t1 — the time before and after the execution of the method (code). Eventually, this object is passed into an instance of ReportedMethodsHandler, which is concerned with the actual aggregation of the different method calls.
When Timeasure’s profiling manager is prepared (more on this later), an instance of ReportedMethodsHandler is initialized with an empty hash stored in @reported_methods (code). Since each measurement that is reported to it is associated with a specific method (whose path is retrievable by Measurement#full_path), it is designed to aggregate data on the level of unique method path.
What ReportedMethodsHandler#report does when it receives a Measurement object is simple (code):
- If
Measurement#full_pathdoes not exist as a key in@reported_methods, create one such, with a newReportedMethodobject as value. - Fetch the
ReportedMethodobject from@reported_methods[Measurement#full_path]and increment its@runtime_sumaccording toMeasurement#runtime_in_milliseconds. - Increment the
ReportedMethod’s@call_countby 1.
A ReportedMethod instance is born “clean” — with its @runtime_sum and @call_count set to 0.
The distinction between Measurement and ReportedMethod is important since a single measurement and the outcome of several measurements are not the same thing. Because one method can be called and reported many times, I find it sufficient to hold just one object to represent it.
An alternative to this design could have been just storing the Measurement objects in an array throughout the process, and eventually creating ReportedMethod objects from them, probably after the time-critical process has ended.
Mainly, this could have saved Timeasure from incrementing @runtime_sum and @call_count during the process. However, in a large app this might result in the creation of a large amount of objects that are not quickly garbage-collected (in contrary to the short-lived Measurement object). I decided to keep only the aggregated data and not the source objects for that reason — it feels sufficient to me and it serves the gem’s goal.
Preparing And Exporting
As the documentation mentions, gem users are required to define the boundaries of the tracked transaction. Primarily, that means preparing the profiling manager before declared tracked methods are called. As an example, if the measured transaction is triggered through a controller, it might be a good idea to prepare the profiling manager right there:
If the profiling manager is not prepared, there will be no ReportedMethodsHandler instance to aggregate the measurements; the core code will run just the same, but no measurement will be collected. Timeasure will use the logger from Ruby’s standard library to print a warning message if that happens (code).
The previous code snippet only prepares the profiling manager, but obviously the real juice is in fetching the data! To do this, the profiling manager supplies .export. Using the previous example, our controller method could look like this:
Of course, what to do with the data is left for the user to handle. Timeasure was designed to be suitable for production use, so I find it helpful to use something like NewRelic Insights in order to obtain live reports and perhaps set up some alerts when certain SLA violations occur; others might want to save this data in some database, making it available for exploration later on. Check out the TimeasureDemo app and source code to explore an actually-working end-to-end usage of Timeasure with its profiling manager.
Having covered the default path, let’s analyze how Timeasure allows gem users to easily configure and tweak it.
The Configuration Object
Out-of-the-box, Timeasure acts as an opinionated gem: it assumes you wish to use the built-in profiling manager and it holds the profiling data in an instance variable throughout a process, as we’ve just seen. But needs vary, and some might want to use only the core functionality of the gem — that is, the easy way to declare tracked methods and the being free from managing t0 and t1. In fact, at Riskified, where I work, we do use the built in profiling manager but we store the profiling data differently. We stray from the default path (just a little!).
Crafting the gem, I wanted to make this ability accessible, so I included a configuration mechanism. This mechanism can be found in other gems and codebases (there are some nice blog posts about it too, like this one from Thoughtbot). In Timeasure, I implemented an “on-steroids”, lambda-bound version of it.
If you are not sure what a lambda is, I find “lambda is a callable object” to be the most accurate definition of it. In short, a lambda is basically a block of code that can be executed but also be assigned into a variable and passed around into other methods. Similarly to methods, lambdas can receive arguments upon being called. Lambdas are useful in configuration objects since they allow the injection of actual code as configuration by the user into something that is static by nature, such as a gem. Lambdas has several other cool features, but for now what we know about them should suffice. Let’s examine how lambdas are actually used in Timeasure.
As an example, if we wish not to use the built-in profiling manager at all, but, say, to handle measurement through your own custom profiler, this could be achieved easily by running this snippet first (in a Rails app, this should probably be an initializer):
As can be seen, Timeasure.configure accepts a block with a single argument: configuration. The latter represents a global configuration object held by Timeasure. Within the block, an assignment to configuration.post_measuring_proc is made: behind the scenes, this is just an attribute of the Configuration object (code). Supplying this simple lambda makes it possible for Timeasure to consume it later — right after a measurement was created — and run it (code). This is a very simple, yet powerful technique to allow gem users to configure the works of the gem without them needing to fork it and use their own custom version of it.
Let’s explore a different use case. As mentioned in its documentation, Timeasure might interfere with RSpec if you happen to track methods that are stubbed in your test suite. For this reason, you may turn Timeasure off easily by running this code before your test suite:
This simple lambda just return false! It is consumed by Timeasure at the critical moment right before the interceptor modules are prepended to the base classes (code). Without these interceptors Timeasure is actually futile, but your specs will pass: you probably don’t need profiling in your test suite. Check out the documentation for more info about Timeasure and RSpec.
Out-Of-The-Box Functionality
I’ve demonstrated how enabling custom configuration can prove helpful. However, I like software that “just works”, off the shelf: for this reason, Timeasure uses default configuration values. This is achieved by the fact that the configuration object is just that — an object — and as such it gets initialized; upon its creation, its initialize method defines the default values for it (code). These are simply the proper lambdas that make it work straight away. Efficient, isn’t it?
Since the configuration object is stored as a class instance variable within the Timeasure module (code), any reference to it always fetches the same object, which makes it de facto a singleton object. The communication with this object should be done entirely through Timeasure.configure and Timeasure.configuration, which serve as actual, elaborated setter and getter methods, accordingly.
Thank you for joining me on this journey of How I Built Timeasure! I hope some of the ideas presented in these two stories might inspire you in your work on your own gems and apps.
As before, I encourage you to try and use the Timeasure gem yourself! It is quite easy to setup, as you’ve seen. If you find any issues or have some feature request, you can open an issue on GitHub or contact me directly.
If you like my project, please give it a ⭐ star ⭐ on GitHub.
If you found this story interesting or useful, please support it by clapping it👏 .
