Instrumenting Ecto

The metrics in the virtual machine are important building blocks, but they do not always tell what you need to know about the rest of your application. Moving up one level, let’s learn how to get data from the database layer. While you might find it comforting that the metrics system will tell you when your database queries are waiting for more than a second in the connection pool queue, it is better to know this will happen before you ever put your system into production. Ecto^[113] is the best place to start. To get detailed metrics, hook into the Ecto logging API. Let’s see how that works using our sample application.

First, we’ll generate some blog code to test. Use Phoenix generators to build a context that interacts with Postgres via Ecto, like this:

Make sure to follow the instructions shown at the end of the command, then open up config/config.exs and change your repository configuration to the following:

This code tells Ecto to include Demo.EctoInspector in its list of loggers. Don’t remove the original Ecto.LogEntry if you want to write messages to the console.

Next, define Demo.EctoInspector in your application. Ecto will call Demo.EctoInspector.log/1 passing an Ecto.LogEntry struct. The function must return the given struct. Our implementation will simply call IO.inspect/1 with the struct to see which fields are available to us. Then, we’ll just return it without modification. Create a lib/demo/ecto_inspector.ex file and key this in:

We’re ready to see some data. Start the server with mix phx.server and access "posts" to fetch all posts. Internally your application will call Demo.Repo.all(Post), which will cause the following to be printed to your terminal:

The struct includes the query, the result, and a couple other fields, including the following measurements:

:query_time

The amount of time the query took to execute. This time is reported by the database itself. If those times are too high, you need to change your query, add an index, or optimize your database.

:queue_time

The amount of time spent retrieving the database connection from the pool. If those times are high, it means a capacity problem. Either your load is too great, or your pool is too small.

:decode_time

This measurement shows how much time was spent converting your results into Elixir data structures. The database drivers, such as Postgrex and Mariaex, are quite optimized when it comes to decoding. Custom decoding functions may be a problem, though, such as those defined in custom Ecto.Types.

The measurements just shown are in native units. They are reported in the maximum resolution supported by the OS. To convert it to a known measure, use System.convert_time_unit/3, like this:

Those are the measurements you will want to push to whatever metrics system you’ve decided to use. Third-party performance tools will likely extract all of this information for you. In case they do not, you can tweak Demo.EctoInspector to publish the data to your data gathering services.

That’s the gist of the information Ecto makes accessible to developers. Notice that you may also bring in what you learned in the previous section. For example, you should consider monitoring the underlying Demo.Repo.Pool process, keeping count of its memory usage, the amount of reductions, and message queue length. That will tell you more about the resources Elixir is consuming to manage your database.

Now that we are extracting useful information from Ecto, it’s time to keep moving up the application stack. Let’s see what Phoenix has to offer.