00:00:24.800
Alright, so I'm going to get rolling here. How's everybody doing? I'm Matt Sanders.
00:00:30.689
I work for Librato on a product called Metric, which some of you may have seen. Today, I'm excited to talk to you about ActiveSupport::Notifications.
00:00:36.450
Is there a way I can turn this down just a little bit? How do I sound to you guys, am I too loud?
00:00:43.470
Alright, awesome! We'll carry on. I'm excited to talk to you today about ActiveSupport::Notifications.
00:00:49.980
As probably most of you know, ActiveSupport is one of the libraries that makes up Rails. One of the changes that came in Rails 3 was that a lot of its components became more modular.
00:00:57.060
We can use it inside Rails and outside of Rails. ActiveSupport::Notifications is one of those things that came in Rails 3 and is a subsection of ActiveSupport.
00:01:03.360
The reason I'm excited about it is that I think it offers you the capability to track what's going on in your applications, both during development and especially in production.
00:01:09.270
A lot of the information you probably already want to know about your apps is being instrumented for you already. Rails uses this extensively internally.
00:01:14.999
So, let's cut to the chase and look at the basics. There are basically two things you need to know about how ActiveSupport::Notifications works: subscribers and instrument calls.
00:01:20.670
When you set up a subscriber, you're essentially saying, 'For any message with this name, when instrumentation with that name gets called, let me know.'
00:01:26.039
You want to do something with that; send me the information associated with that event.
00:01:31.139
So, subscribers are setting up that callback to receive the event and do something with it. Instrument calls are actually triggering that the event is firing.
00:01:37.499
The method name, which is the message name, is how they communicate with each other.
00:01:42.509
Now, why is this important? Why do we even care in the first place? As I said before, there's a lot of valuable data that Rails already provides.
00:01:47.639
This gives you an opportunity to move away from the traditional one-to-one approach, which is often limited. You know, when I was interested in finding out what was wrong with a part of my application, I would throw debug statements in the logs.
00:01:55.049
Now, you can say there's a bunch of things I want to do when this thing fires. There are many ways I want to track what's going on, and it's super easy to set that up.
00:02:00.179
This is a quote from Peter Drucker, who is considered the father of modern management. I believe it's true: What we measure, what we look at every day, determines what we work on, what we get excited about, and what we take to the next level.
00:02:07.109
As programmers, we tend to focus on the things that are attractive to us, which may not always be the most important aspects of our application.
00:02:13.300
Often, we lack visibility into what's happening in our application and how people are using it. This excites me because it's an opportunity to hone in on what matters and gain insights that can enhance both your application and user experience.
00:02:20.670
Another important point is that your production environment is not the same as your development environment.
00:02:26.039
Even if you're running on the same operating system, different things are happening in the background when you're in production.
00:02:30.730
You're likely running on multiple nodes or different versions of components, making it vital to capture that data in production to inform your decision-making.
00:02:36.400
Let’s say you have a service that appears to be functioning well, with a response time under a hundred milliseconds.
00:02:43.450
Suddenly, there's a significant spike, and the service slows down fourfold. What happened?
00:02:50.200
When this occurs, ideally, you should be tracking all the things you care about to diagnose the problem effectively.
00:02:56.080
This way, you can investigate calmly rather than scrambling through logs to understand the chaos.
00:03:02.790
In our core applications, ActiveSupport::Notifications gives us the capacity to gain sharp insights into these issues.
00:03:09.460
Earlier, I mentioned two core ideas: subscribers and instrumentation events.
00:03:15.760
The message name drives communication between the two. Now, let’s explore how instrumentation works.
00:03:21.070
There’s one required argument: the message name. For something like this, we may only care about whether the event occurred.
00:03:26.140
Any subsequent arguments in the hash will be passed along as a payload.
00:03:32.410
For example, if you're capturing the email address of a new sign-up, passing this along ensures that all subscribers receive that information.
00:03:38.590
Here’s what the actual payload looks like: it includes the message name, start and end times, and a unique message ID.
00:03:43.750
The message ID helps differentiate between messages for the dispatcher.
00:03:49.420
Most use cases can ignore this unique ID and focus on the hash that represents your payload!
00:03:54.520
In the block form of this method, any code you run inside will get automatic timing.
00:03:59.910
This acts like a combination of a benchmark and a logging statement.
00:04:06.850
The payload arguments are the same, but the different start and end times give you clarity on duration.
00:04:13.570
If an exception occurs during this process, an additional argument will indicate the exception name and its message.
00:04:20.000
One common misunderstanding is the expectation that you'll receive the exception object itself; instead, you'll only receive the name of the exception.
00:04:27.220
In subscriber setup, you're going to want to use milliseconds for all timing.
00:04:33.450
You can calculate the duration manually by multiplying the duration in seconds by a thousand, but ActiveSupport::Notifications also provides an event class.
00:04:40.010
This class allows you to include your arguments without worrying about their order.
00:04:46.620
From our talk last night, it's always preferable to call arguments by name rather than by order.
00:04:53.020
You’ll receive an object containing all passed arguments, and the duration will be calculated for you.
00:04:59.499
The event helper class provides a useful trick for linking events. You can determine whether one event happened completely within another by using this parent_of method.
00:05:05.110
For example, if one event is triggered entirely inside another, the parent_of method returns true.
00:05:10.389
Additionally, you can use regular expressions instead of strings to match message names; this minimizes the need for multiple subscriber definitions.
00:05:15.490
Previously, I mentioned that Rails provides a wealth of instrumentation for you; let's get to the good stuff.
00:05:21.830
This is not a complete list, but here are the primary events exposed by Rails by default.
00:05:27.950
You’ll notice events related to ActionController for dispatching requests, caching stuff, ActionMailer for delivering and receiving mail.
00:05:34.000
There are even events in ActionView for rendering, as well as for caching operations in ActiveSupport.
00:05:39.680
ActiveRecord has one notable event that is crucial since it runs any time a query is executed.
00:05:46.890
By tapping into this unique instrumentation and applying conditional monitoring, you can gather fascinating data.
00:05:54.530
It’s important to mention that previous examples show the namespaced dot notation common in the monitoring realm.
00:06:01.680
Some tools, like Graphite, translate these names into folders, allowing for visible separation, which is typically left to right.
00:06:07.190
In Rails, it’s opposite, always right to left, so just keep that in mind.
00:06:13.520
Let's dive into one of these events; specifically, we can analyze the ActionController's process action event.
00:06:19.800
This event provides valuable information about the controller, action, format, status code, and timing data.
00:06:26.080
With this information, we can conduct various analyses.
00:06:33.790
The graph you've seen here illustrates the total request time versus time spent in the view and the database.
00:06:40.120
In such cases, we can quickly ascertain that our database is not the bottleneck, as we're spending more time on view rendering.
00:06:47.590
If we observe peculiar spikes in the request time not accounted for by the database, there might be an issue with external service dependencies.
00:06:54.130
This presents an opportune moment to consider caching solutions.
00:07:00.840
You can also monitor how many requests each of the servers in your cluster handle.
00:07:06.368
Ideally, if the load balancer works efficiently, the load should be evenly distributed. If not, it raises critical questions.
00:07:13.181
Here, we’re considering slow requests. By defining an arbitrary threshold (e.g., 200 milliseconds), we flag slow requests during monitoring.
00:07:19.000
As the total number of requests rises, it becomes essential to analyze whether the slowness is due to high request volumes or inherent application slowdown.
00:07:25.000
We can analyze the slowest request patterns across different servers, helping pinpoint where optimization efforts should occur.
00:07:31.430
This highlights the importance of using the existing instrumentation information effectively.
00:07:37.470
Furthermore, ActiveRecord fires an event each time it executes a query.
00:07:43.600
You collect the duration, retrieve the entire query, and obtain parameter bindings if applicable.
00:07:49.030
You receive a name argument for identifying the model associated with the query, aiding in performance assessments.
00:07:55.530
You can leverage this information to create customized integrations.
00:08:01.900
Consider models that are fetched frequently and reevaluate their necessity. Caching query results can significantly reduce database load.
00:08:08.450
It’s about elevating visibility into your application to optimize its performance effectively.
00:08:14.100
This opportunity to enhance our applications and metrics is exciting as it streamlines tracking critical success factors.
00:08:20.300
I think performance monitoring and instrumentation shouldn't feel burdensome. Instead, it should offer clarity around core application metrics.
00:08:27.940
Ultimately, what this boils down to is the actionable visibility you gain using ActiveSupport::Notifications.
00:08:34.940
It creates opportunities to improve our application's performance through insightful practice.
00:08:41.020
Now, let's pivot to how you can create your own events.
00:08:47.090
Probably the simplest way to use this is to log your desired events using Rails logger.
00:08:53.920
You can streamline your logs for machine readability or utilize products like Papertrail, which is fantastic for real-time searchable logs.
00:09:00.360
Another fantastic tool is New Relic, where you can easily create custom events.
00:09:06.790
Moreover, you can combine it with StatsD for effective collection of metrics.
00:09:12.290
StatsD is a lightweight application that collects and forwards metrics without slowing down your app.
00:09:20.540
You can utilize libraries to integrate well with existing setups, further enhancing your logging capabilities.
00:09:27.460
This integration allows you to stash data for later usage while maintaining efficient processing.
00:09:34.250
You can define patterns that allow your subscribers to operate over multiple notifications seamlessly.
00:09:40.900
Remember, all subscribers can be triggered by a single event within your controller.
00:09:47.890
Understanding performance is essential; whatever runs in your instrumentation block will complete before all related subscribers run sequentially.
00:09:54.460
Avoid long-running operations in your subscribers, as they can introduce latency in request handling.
00:10:00.800
Background operations can run asynchronously, but when performance is crucial, keep your instrumentation fast.
00:10:06.890
ActiveSupport Notifications is straightforward and manageable; you can customize it extensively.
00:10:13.490
While I don't recommend using unsubscribe method often due to its potential impact on performance.
00:10:20.790
When a message invokes, the dispatcher learns if anyone cares about this event and keeps a cache regarding it.
00:10:27.790
Careful when modifying subscribers, as it can invalidate that cache, slowing down your application's responsiveness.
00:10:34.790
Hopefully, you've now covered the basics of ActiveSupport Notifications. Any outstanding questions?
00:10:41.000
If there's anything confusing, please feel free to ask!
00:10:47.000
Now, let’s talk about conditional instrumentation—a simple but powerful practice.
00:10:53.000
Begin subscribers by verifying your relevance, returning immediately if the event does not concern you.
00:10:59.880
This decision accelerates your subscriber operations significantly.
00:11:06.190
I encourage the use of various tools that allow selective feature rollout, such as Rollout.
00:11:12.799
This service enables beta testing of features among select users, gathering insightful feedback before widening your focus.
00:11:19.690
You can enable or disable instrumentation dynamically based on customer-specific needs.
00:11:25.600
Wrap checks around the Rollout functionality to avoid bugs appearing due to Redis or other service unavailability.
00:11:33.000
Incorporate notification bot integrations, like Campfire, to streamline operations and collect user feedback or alerts efficiently.
00:11:40.870
When a service outage occurs, you can respond promptly to resolve technical hiccups.
00:11:47.680
Ruby code can reduce repeated calls to ActiveSupport::Notifications for clarity and simplicity.
00:11:54.990
By leveraging your Application Controller, you could streamline instrumentation calls.
00:12:01.210
Additionally, observe the possibility of shared patterns across Models using modular setups.
00:12:07.640
You may also notice prevalent repetitiveness when defining subscribers.
00:12:13.940
Fortunately, ActiveSupport has a separate LogSubscriber library that alleviates it.
00:12:21.090
This setup allows for dynamic logging without excessive manual annotation.
00:12:27.590
Ensure you set this up correctly; it requires associations with parent namespaces.
00:12:33.940
From here, access log methods directly within LogSubscribers for ease.
00:12:39.930
Most crucial services leverage LogSubscribers for simplifying operational logging.
00:12:46.590
We can also use this methodology beyond Rails, allowing for effective instrumentation in non-Rails code.
00:12:53.240
Even utilizing gems outside Rails can amplify your code's visibility without compromising its core functionality.
00:13:00.000
Open source projects have adopted this instrumentation approach, elevating their communities.
00:13:06.700
For example, Faraday middleware emits instrumentation across entire request environments.
00:13:12.990
On top of that, various gems already utilize this pattern, such as Excon.
00:13:19.090
Integrating instrumentation means you can create unique event signatures for enhanced clarity.
00:13:25.079
This considerably lowers the barrier for identifying performance issues without extensive overhead.
00:13:31.960
Lograge, for instance, converts verbose logs into concise and readable records.
00:13:37.180
The transformation provides parsable logs from multi-threaded environments seamlessly.
00:13:44.080
Engage with interesting projects leveraging ActiveSupport Notifications for better insights.
00:13:50.890
Review log subscribers in Rails for further inspiration and flexibility in your work.
00:13:57.000
Remember, tools only become powerful through collective utilization and understanding within a community.
00:14:04.020
It’s critical for teams to communicate and establish clear guidelines for implementing and using instrumentation.
00:14:10.490
To streamline all subscribers and initializers, clump them together to maximize visibility.
00:14:16.940
Combining client-serving operations with instrumentation can create confusion and inefficient usage.
00:14:23.400
Consider using insights gained for operational tasks while maintaining distinct functionalities for user-focused jobs.
00:14:30.000
Thanks for your time today! I hope you feel inspired to continue exploring the incredible potential of ActiveSupport Notifications.
00:14:37.000
Engage with your applications deeply; identify what matters to you, your team, and your users.
00:14:42.000
Assess your conditions for success meticulously. Explore the opportunities here.
00:14:48.000
How can you better utilize insights from ActiveSupport Notifications? Thank you!
00:34:05.600
Thank you!