Elixir and Ecto's telemetry events

Telemetry is a lightweight library for dynamic dispatching of events, with a focus on metrics and instrumentation. Any Erlang or Elixir library can use telemetry to emit events. Application code and other libraries can then hook into those events and run custom handlers.

I created a simple sample Elixir project to demonstrate how to use Ecto’s telemetry events. It’s available in github.

The project shows how to:

• use telemetry_prefix on your repo to change the name of the event
• use telemetry_options with your queries to allow you to easily identify what database activity has occurred in your metrics handler
• what event name is if you do not use telemetry_prefix for your repo

The sections below provide information that might be helpful when you are first using Ecto telemetry.

What is Telemetry? What is a Telemetry Event?

Telemetry, as a general concept, has been around quite a while. It refers to the gathering of measurements (and other information) at or near the point of what is being measured. Then automatically transmitting that information to a system that allows analysis of the measurements. Sometimes you will see the term “telemeter” used to describe a device used to capture measurements.

A telemeter is a physical device used in telemetry. It consists of a sensor, a transmission path, and a display, recording, or control device. Electronic devices are widely used in telemetry and can be wireless or hard-wired, analog or digital. Other technologies are also possible, such as mechanical, hydraulic and optical.

Early telemetry systems may seem primitive to us but they were revolutionary at the time. For example, early steam engines performed measurements using a mercury pressure gauge. The gauge indicated the measurement and could be read at a short distance. Our modern use of telemetry involves transmitting measurements data in large volumes from multiple points to a common analysis system where graphs, charts, gauges and general queries over measurement data is possible.

A telemetry event is a measurement (or measurements) at a specific point in time and given a timestamp and a name. Telemetry events can become a history (of sorts) for your system.

Why do I want Telemetry?

Embracing telemetry allows monitoring your software. You can use the measurements to evaluate and monitor the general health of your software. You can use it to spot trends that require investigation and evaluation. For example, it’s important to know if APIs provided by your service are suddenly 50% slower. That’s something that probably needs immediate investigation! And it’s easily visible if you are using telemetry.

In the context of Ecto, using it’s telemetry events can give you:

• how many times is a particular query executed over a time interval?
• what is the current speed of a query?
• what are the trends over time for number of executions and speed of queries?

How does Telemetry work in Elixir?

In Elixir and Erlang telemetry is generated by the telemetry library. All libraries and applications generating telemetry events use the telemetry library.

There are some Erlang libraries that do not use the telemetry library. This is because the telemetry library and it’s conventions were not around when the library was first written. For a number of libraries telemetry events have been added, but its possible you will use a library that does not generate telemetry events. In some cases the library may generate its own version of telemetry events that you can coerce into the telemetry system.

In Elixir (and Erlang) telemetry events can have both measurements and metadata. Metadata provides data that adds meaning to the measurement. For example, in an Ecto database activity telemetry event the measurement data tells you how long some SQL took to execute. The metadata tells you the Repo used for the SQL.

An event is named using a List of atoms. That is, the name identifies the general category of the event. That is, we may have an event named [:my_app, :sonar_system, :ping] that is used to report some sonar ping event. This is its name but there can be multiple telemetry events of this kind generated, each with its own timestamp.

Ecto, Phoenix and other libraries you may use have a dependency on the telemetry library. When your app starts the telemetry library starts a GenServer that creates an ets table (see src/telemetry_handler_table.erl in the telemetry library). This is used to connect generated events to registered callbacks for those events. The callback is responsible for doing something with the generated event - such as sending it on to Datadog or Prometheus.

How Do I Listen for Telemetry Events?

There are two functions in the telemetry library for registering your interest in events:

• attach/4 - used to attach to a single event of interest
• attach_many/4 - used to attach to a list of events of interest

These functions are almost identical. The different is attach/4 takes a single event name as its second parameter. The attach_many/4 takes a list of event names as its second parameter. The other parameters are exactly the same. Your application should use only one of these. It makes sense to use attach_many/4 even if you are currently interested in only one event. Over time you most likely will want to listen to more.

Here are the parameters to these functions:

• handler_id - this is a unique id. It’s defined as a term. This means it can be any value - a String, an atom, a Map, etc. Ordinarily, developers use either an atom (module name) or a String. The important thing to keep in mind is that it must be unique. That is, your name cannot conflict with any other id registered to receive telemetry events.
• event_name (attach/4) or list of event_name (attach_many/4) - An event name is a unique list of atoms that identify an event. Since this must be unique an event name’s list of atoms usually starts with the application name. For example, :ecto or :phoenix. In the case of your own service this would be your app name. That can be found in your mix.exs file. The atoms that follow make the event unique for the application. You’ll want to identify a convention used by your app if you are going to generate telemetry events.
• handler_function - This is the function that is called by the telemetry library when an event matches the event_name or list of event_name passed in the attach/4 or attach_many/4 call. There’s an example below and some hints on how to write a handler function.
• handler_config - This is your config data. It’s defined as a term. This means it can be any value that you find useful. Maps are commonly used. But probably the most common thing is to pass nil for this value. It’s not required and unless you want data passed by the telemetry library back to you to handle each event you should just use nil.

Once you have attached the handler your handler function will start being called when an event is generated. The code path for an event is:

generate event -> telemetry library
                  for each handler for event
                            -> call the handler function

The basic mechanics of plugging into Ecto’s telemetry events are:

• figure out the event names and put them in a list
• call :telemetry.attach_many and give the telemetry system a handler function. The handler is a function that takes four parameters:
  • The event name
  • Measurements (Map)
  • Metadata (Map)
  • Handler Config - this is data that you pass into the telemetry library when informing it that you want to listen for events. In most cases applications do not use this and nil is passed into the telemetry library and it is what is passed to the handler function for this parameter.

How and When are Telemetry Events Generated in Ecto?

Ecto is the library that Elixir developers use to interact with a relational database. Different databases implement behaviour that allows Ecto to interact with different databases without having all the code inside the ecto library itself. So, for example, there is a postgrex library for Postgresql and a myxql library for MySQL.

Ecto is actually divided into two libraries: ecto and ecto_sql. This is because there are features in Ecto that are very useful for apps that do not use a relational database. For example, it is common to use Ecto to validate parameters for an API.

There are two telemetry events generated by ecto.

• a Repo initialization event, This occurs when an Ecto.Repo starts up (its generated by the Ecto.Repo.Supervisor module in the ecto library). This event always has the same event name. It is [:ecto, :repo, :init].
• a database activity event. This is generated when a database interaction (select, insert, update, delete, etc, etc) occurs on a Repo connection. This event does not have a fixed name. It’s naming is discussed below. This event is generally the only one that developers are interested in. It’s metrics surrounding the app’s interaction with the database. By capturing this data the developer can graph what queries are executing the most, which are the slowest queries, and other useful information. This is described in the Ecto documentation as an “Adapter Specific Event”. This somewhat awkward naming is not that important. I’ll refer to it in this doc as a “Database Activity Event”.

Database Activity Event

As mentioned previously telemetry events are named. The name is given on generation as the first parameter to :telemetry.execute/3. It’s pretty clear what the name is for the event generated in Ecto.Repo.Supervisor. It’s hard-coded as [:ecto, :repo, :init].

The other telemetry event (the more useful one) has the name of your repo module as the event name, by default. This takes your Repo module name and converts it from camel-case to snake-case. So, if your Ecto repo is called MyApp.MyRepo the event name is [:my_app, :my_repo].

You can set the event name yourself by using a telemetry_prefix on your Ecto Repo definition in your config files. For example, you might set the telemetry_prefix to [:my_app, :ecto, :primary_db] for a Repo associated with your primary database and [:my_app, :ecto, :replica_db] for your replica database. The event that Ecto generates will be your telemetry_prefix concatenated with [:query].

What Data is In A Database Activity Event?

The activity event passes the following measurements and metadata.

Measurements

The :measurements map may include the following, all given in the :native time unit:

• :idle_time - the time the connection spent waiting before being checked out for the query
• :queue_time - the time spent waiting to check out a database connection
• :query_time - the time spent executing the query
• :decode_time - the time spent decoding the data received from the database
• :total_time - the sum of (queue_time, query_time, and decode_time)️

Metadata

• :type - the type of the Ecto query. For example, for Ecto.SQL databases, it would be :ecto_sql_query
• :repo - the Ecto repository (the module name)
• :result - the query result
• :params - the dumped query parameters (formatted for database drivers like Postgrex)
• :cast_params - the casted query parameters (normalized before dumping)
• :query - the query sent to the database as a string
• :source - the source the query was made on (may be nil)
• :stacktrace - the stacktrace information, if enabled, or nil
• :options - extra options given to the repo operation under :telemetry_options