Forem: Marcos Ramos

Build A Simple Tracing System in Elixir

Marcos Ramos — Tue, 06 Feb 2024 11:53:45 +0000

In this post, we'll cover how Elixir applications can be traced using OpenTelemetry and how macros can make this process super easy and streamlined.

First, we'll talk about tracing and OpenTelemetry in Elixir. Then we'll improve our custom tracing layer step-by-step until we get an easy and seamless tool to trace our application.

Let's get started!

On Tracing in Elixir

Note: All the research done to write this article resulted in the creation of the abstracing library. It's far from complete, but it encapsulates all the ideas written here.

Think of instances when your app crashes in production. A bunch of artifacts are generated: stacktraces, logs, reports, etc.

When using proper tracing, developers can link all these artifacts in a sequence of events — from a starting point down to the response, and operations with side effects.

Here is a simple example of a POST /users trace request:

From left to right, we can see that the request was received, decoded, validated, saved, and then, finally, a response was encoded and sent. Each little block in this trace is called a span. Spans are the building blocks of tracing, as they represent events inside an application.

Spans require this basic information: the start, the end, and the status (success or error). We can enrich each span with more data, and they can even have a direct correlation to these entities if we add the appropriate metadata to logs and errors.

Meet OpenTelemetry for Elixir

The OpenTelemetry project homepage states that it is a:

Collection of APIs, SDKs, and tools

That can be used to:

Instrument,
generate, collect, and export telemetry data (metrics, logs, and traces).

For Elixir, the OpenTelemetry library has everything we need to perform distributed tracing.

Here is a very simple example of how we can use it:

# example.ex
defmodule Example do
  require OpenTelemetry.Tracer

  def some_fun() do
    OpenTelemetry.Tracer.with_span "example.some_fun" do
      # ...
      OpenTelemetry.Tracer.set_attribute("key", "value")
      # ...
  end
end

What's Happening Here?

As you can see, it's pretty straightforward. To start using all macros inside OpenTelemetry.Tracer, we first require it at the top of our module.

When we want to start a span, we just need to call OpenTelemetry.Tracer.with_span/2 and write our code.

Under the hood, :otel_tracer.with_span/4 is used to actually start the span — even though the OpenTelemetry API does provide Elixir modules to interact with, all the heavy lifting is actually written in Erlang.

One really cool thing about spans is that we can add metadata to reported data. This gives us more contextual information to investigate issues. We can do this by calling OpenTelemetry.Tracer.set_attribute/2. It only accepts a small set of types (atoms, booleans, binaries, and tuples), so we need to be mindful when using it.

Now for a brief overview of how I ended up building an abstraction layer for OpenTelemetry.

Why I Built an Abstraction Layer for OpenTelemetry

When I first started using OpenTelemetry, I noticed that I was constantly creating small private functions to translate data and help me with the setup. As I did more and more of that, I eventually extracted all this boilerplate to its own feature. I created an abstraction layer for OpenTelemetry.

A few pain points during my use of OpenTelemetry that were solved by this abstraction layer:

If your code throws an unexpected exception, the span will not be collected.
Adding complex data requires transforming it first.
Long namespaces (not really a problem, but I just don't like them 😁).

Luckily, the OpenTelemetry library also has a low-level API that can be used to customize our tracing tooling, and that's exactly what we'll be doing now!

Breaking Down the Pain Points of OpenTelemetry

Now that we know some of the direct pain points of using OpenTelemetry, let's break them down into separate categories and solve each one. We can group the features that we inject boilerplate code in to:

Setup: how we prepare a module to be traced
Start/stop spans: the steps required to actually create spans
Modifying spans: adding more attributes to spans
Exception handling: collecting errors and changing the span status

In the end, we want to cover all these features with the least amount of boilerplate code as possible.

A Setup for a Setup in Elixir

The very first thing we need to do is prepare our module to use the tracing macros and libraries. We'll use Elixir's special macro __using__/1 to automate some of this stuff for us:

# lib/tracing.ex
# ...
defmacro __using__(_opts) do
  quote do
    require OpenTelemetry.Tracer

    require unquote(__MODULE__)
    import unquote(__MODULE__), only: [span: 1, span: 2, span: 3]
  end
end
# ...

Now, whenever we need to trace our code, we just need to call use Tracing at the top of our module.

defmodule MyModule do
  use Tracing
  # ...
end

So far, so good — but nothing too exciting. However, by using this simple setup macro we don't have to modify the modules using it if we ever make changes to the setup process, as all changes will be automatically replicated. That's a good start!

In the next section, we'll start to remove some more meaningful boilerplate.

Translating Elixir Application Data to Span Attributes

OpenTelemetry allows applications to include attributes in spans. An attribute consists of a key and a value. This helps us to include useful information that can later be used to either create monitoring triggers or investigate a crash.

But here is a catch: OpenTelemetry only accepts numbers, strings, atoms, booleans, and lists (if its elements are from any of the supported basic types). Applications work with a richer set of data types: not only numbers and strings but also complex lists, maps, structs, and tuples.

Of course, we can use inspect/1 on the variable values and have everything in there. However, this makes searching for spans a much harder task, as we would need to use complex regexes to search for them.

Convert Complex Types to Basic Types

It's possible, however, to convert the complex types to more basic (and supported) types. Let's define a few rules:

Lists will use their indexes to name the values
Tuples will be converted to lists
Maps will use their keys to name values
Structs will be converted to maps

So, a simple list like [1, 2, 3] would be transformed into a list of pairs:

my_list = [1, 2, 3]
Tracing.set_attribute("numbers", my_list)
# numbers.0 = 1
# numbers.1 = 2
# numbers.2 = 3

For maps, we can use their keys to generate the pairs:

my_map = %{first_name: "John", last_name: "Wick"}
Tracing.set_attribute("user", my_map)
# user.first_name = "John"
# user.last_name = "Wick"

Using Elixir's `defguard`

Since we're handling maps, lists, and tuples as a set of values, we can use Elixir's defguard
to create a custom function guard:

# lib/tracing.ex
defmodule Tracing do
  # ...
  defguard is_set(value) when is_map(value) or is_list(value) or is_tuple(value)
  # ...
end

Now we can start building our custom set_attribute:

# lib/tracing.ex
defmodule Tracing do
  # ...
  def set_attribute(key, value) when is_set(value) do
    set_attributes(key, value) # To be yet defined!
  end

  def set_attribute(key, value) do
    OpenTelemetry.Tracer.set_attribute(key, value)
  end
  # ...
end

It's simple: if the value is a set, we call set_attributes (in plural!), otherwise, we just delegate to OpenTelemety.Tracer.set_attribute/2.

The next piece is where all the transformation happens:

# lib/tracing.ex
defmodule Tracing do
  # ...
  def set_attributes(key, values) do
    key
    |> enumerable_to_attrs(values) # To be yet defined!
    |> OpenTelemetry.Tracer.set_attributes()
  end
  # ...
end

Here, we receive the set of values, convert them, and then call OpenTelemetry.Tracer.set_attributes/1 to do the actual work of adding the attributes to the span.

The data conversion happens in the enumerable_to_attrs/2 function. It works by recursively going into each element of the collection and converting it to the appropriate basic type supported by OpenTelemetry. Adding its code here is beyond the scope of this post, but feel free to check it out on GitHub!

Wrapping Up

In this post, we discussed the basics of tracing and began to explore how we can utilize OpenTelemetry in Elixir. We laid the foundation for an abstraction layer that will simplify the creation and manipulation of spans, making the process seamless and straightforward.

Happy coding!

P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, subscribe to our Elixir Alchemy newsletter and never miss a single post!

Tackling Performance Issues in Ecto Applications

Marcos Ramos — Tue, 30 May 2023 10:56:36 +0000

Ecto can be considered the standard database wrapper and query generator for Elixir, enabling developers to interact with databases efficiently.

However, inefficient queries or misconfigurations still can (and will) happen. Addressing these issues is crucial for a smooth user experience.

In this article, we'll explore three common performance issues in Ecto applications:

N+1 query problem: You get excessive redundant queries from retrieving related data.
Inefficient query execution: Poorly designed queries will strain a database.
Connection pooling and concurrency issues: Bottlenecks and slow response times are caused by configuration or concurrency problems.

We'll discuss how to detect each issue, as well as their common causes and solutions, so you can optimize your Elixir applications for peak performance.

Let's start!

The N+1 Query Problem

The N+1 query problem occurs when an application loads a parent record and its associated child records in separate queries.

This leads to one query for the parent record (1) and one query for each child record (N), resulting in N+1 queries in total. This issue can cause a significant performance hit due to an excessive number of redundant queries.

Detecting the Problem in Elixir

Suppose we have a User schema on a many-to-many relationship with a Role schema. We'll call the schema that associates the two RoleAssignment:

# my_app/lib/my_app/user.ex
defmodule MyApp.User do
  use Ecto.Schema

  schema "users" do
    field :name, :string

    has_many :role_assignments, MyApp.RoleAssignment, foreign_key: :user_id

    timestamps()
  end
end

# my_app/lib/my_app/role.ex
defmodule MyApp.Role do
  use Ecto.Schema
  import Ecto.Changeset

  schema "roles" do
    field :name, :string

    has_many :role_assignments, MyApp.RoleAssignment, foreign_key: :role_id

    timestamps()
  end
end

# my_app/lib/my_app/role_assignment.ex
defmodule MyApp.RoleAssignment do
  use Ecto.Schema

  schema "role_assignments" do
    belongs_to :role, MyApp.Role, foreign_key: :role_id
    belongs_to :user, MyApp.User, foreign_key: :user_id
    timestamps()
  end
end

Imagine that we want to show all the users and their roles on an admin page:

users = Repo.all(User)

users_with_roles =
  Enum.map(users, fn user ->
    role_assignments = Repo.all(from ra in MyApp.RoleAssignment, where: ra.user_id == ^user.id)
    roles = Enum.map(role_assignments, fn ra -> Repo.get!(MyApp.Role, ra.role_id) end)

    %{user | roles: roles}
  end)

As you can see here, we generate N queries to load the associated roles for every user.

To detect the N+1 query problem, you can use tools like Telemetry. Telemetry monitors query counts and identifies queries that are executed multiple times with slight variations.

For example, you wrap the query into a span and then attach a handler to the events to detect it:

# my_app/lib/user_context.ex
defmodule MyApp.UserContext do
  alias MyApp.User
  alias MyApp.Role
  alias MyApp.RoleAssignment

  alias MyApp.Repo

  def get_all_users do
    event = [:my_app, :query]                    # the name of the event
    start_metadata = %{context: "get_all_users"} # metadata to be sent on start

    :telemetry.span(event, start_metadata, fn ->
      users = Repo.all(User)
      result = Enum.map(users, fn user ->
        %{user | roles: get_roles(user)}
      end)

      stop_metadata = %{}                        # metadata to be sent on stop

      {result, stop_metadata}
    end)
  end

  def get_roles_for_user(user) do
    event = [:my_app, :query]                    # the name of the event
    start_metadata = %{                          # metadata to be sent on start
      context: "get_roles_for_user",
      user_id: user.id
    }

    :telemetry.span(event, start_metadata, fn ->
      role_assignments = Repo.all(from ra in MyApp.RoleAssignment, where: ra.user_id == ^user.id)
      roles = Enum.map(role_assignments, fn ra -> Repo.get!(MyApp.Role, ra.role_id) end)

      stop_metadata = %{}                        # metadata to be sent on stop

      {roles, stop_metadata}
    end)
  end
end

We receive two events for every function call: one when the span starts and the other when the span has finished.

With the spans in place, we can now attach a handler to listen for any call to them:

defmodule MyApp.Telemetry do
  # ...
  def handle_user_context_spans([:my_app, :user_repo, start_or_stop], _measurements, _metadata, _config) do

    case start_or_stop do
      :start ->
        # handle span start

      :stop ->
        # Record that a query was executed within the context
    end
  end
  #...
end

New Phoenix applications ship with a telemetry supervisor under <app_web>/telemetry.ex. We can add the handler to its init/1 function:

# my_app/lib/my_app_web/telemetry.ex
defmodule MyAppWeb.Telemetry do
  # ...
  def init(_args) do
    children = [
      # ...
    ]

    :telemetry.attach_many("user_context_handler",
      [
        [:my_app, :user_repo, :start],
        [:my_app, :user_repo, :stop]
      ],
      &MyApp.Telemetry.handle_user_context_spans/4, [])

    Supervisor.init(children, strategy: :one_for_one)
  end
  # ...
end

Here are a couple of strategies to detect N+1:

Count the total number of queries within a span context to analyze anomalies or spikes.
Create a metric, publish an event from the span handler, and, from there, plot data into a dashboard.

It is not an easy problem to spot, but when your application traffic starts to increase, you'll see some symptoms. Here are some additional things you can look for that may indicate you're experiencing an N+1 problem:

High CPU usage on your database systems
All the pages of your web app are fast except for a few
When you open them, lots of the same SQL is being executed

In general, the more instrumentation you have in place, the easier it is to detect N+1 queries.

For more information on N+1 queries and how to use AppSignal to detect them, read our post Performance and N+1 Queries: Explained, Spotted, and Solved.

Using Ecto's Preload

Ecto provides the preload/3 function to load associated records in a single query, avoiding the N+1 query problem.

Here's an example of how to use preload/3. First, add the proper relationship to the model:

# my_app/lib/my_app/user.ex
defmodule MyApp.User do
  # ...

  schema "users" do
    # ...
    many_to_many :roles, MyApp.Role, join_through: MyApp.RoleAssignment
    # ...
  end
end

Now, to fetch all users along with their roles, you can use preload/3 like this:

import Ecto.Query

users = MyApp.Repo.all(
  from(u in MyApp.User,
    preload: [:roles]
  )
)

This will load the user in one query, and roles in another query, regardless of the number of posts a user might have. Great — we go from N+1 to 2!

As an example, an N+1 query with 200 users and 200 roles takes 20 seconds to load on my computer. Using the preload, this number is reduced to 600 milliseconds!

But there is room for even more optimization.

Preloading with Joins

Preloading with joins has the advantage of generating only one query to load all associated records from a database.

In addition, you can also filter or sort the associated records! Just use join/5 along with preload/3.

Following the same example from the last section:

import Ecto.Query

query = from u in User,
  left_join: ra in assoc(u, :role_assignments),
  left_join: r in assoc(ra, :role),
  preload: [role_assignments: ra, roles: r],
  select: u

Repo.all(query)

This fetches users and their assigned roles using a single query, avoiding the N+1 query problem. On my computer, this takes about 100 milliseconds to run.

By leveraging Ecto's preload/3 function and combining it with join/5 when necessary, you can efficiently load associated records and eliminate the N+1 query problem in your Ecto-based applications.

Inefficient Queries in Ecto

Inefficient query execution can result in slow database performance, as poorly designed queries may place unnecessary strain on the database. Now we'll learn how to detect and fix them.

Example 1: Missing Indexes

One of the most common causes of inefficient queries is a lack of indexes.

Suppose we have a Post schema like this one:

# my_app/lib/post.ex
defmodule MyApp.Role do
  use Ecto.Schema
  import Ecto.Changeset

  schema "posts" do
    field :title, :string
    field :body, :string

    field :published_at, Date

    timestamps()
  end
end

Let's fetch all published posts ordered by their publication date:

import Ecto.Query

published_posts = MyApp.Repo.all(
  from(p in MyApp.Post,
    where: is_nil(p.published_at) == false,
    order_by: [desc: p.published_at]
  )
)

If there is no index on the published_at field, this query may become slow when the number of posts in the database grows. The database system will perform a full scan of the table for every query.

To fix this issue, you can add an index to the relevant column using a migration:

defmodule MyApp.Repo.Migrations.AddIndexOnPublishedAt do
  use Ecto.Migration

  def change do
    create index(:posts, [:published_at])
  end
end

There's really no easy way to detect this from the application — it will only start to be noticeable with queries on large tables. From the point of view of an application, it's only a slow query.

In the next section, we'll learn how to monitor the query execution time with telemetry to detect such problems.

Detecting Bad Queries with PostgreSQL and Telemetry

You can use tools like EXPLAIN ANALYZE in PostgreSQL (or similar features in other databases) to detect inefficient queries by analyzing the execution plan and identifying possible bottlenecks.

Additionally, you can use telemetry to monitor query execution times and set up alerts if a query takes too long to execute.

For example, you might add a handler to alert you if a query takes longer than 5 seconds:

# my_app/lib/my_app/telemetry.ex
defmodule MyApp.Telemetry do
  # ...
  def handle_event([:my_app, :repo, :query], measurements, metadata, _config) do
    query_time_ms = measurements[:query_time] / (1_000 * 1_000)
    if query_time_ms > 5_000 do
      # Send an alert or log a warning
    end
  end
  # ...
end

Now we can attach the handler during the telemetry supervisor startup, just like we did for the span handlers:

# my_app/lib/my_app_web/telemetry.ex
defmodule MyAppWeb.Telemetry do
  # ...
  def init(_args) do
    # ...

    :telemetry.attach("query-time-handler", [:my_app, :repo, :query], &MyApp.Telemetry.handle_event/4, [])

    Supervisor.init(children, strategy: :one_for_one)
  end
  # ...
end

Query timeouts can also serve as a bad smell, indicating that inefficient query execution is occurring.

Ecto Connection Pooling and Concurrency Issues

Connection pooling problems can occur when an application tries to open more connections to a database than the pool allows. This can lead to a bottleneck, as processes are left waiting in a queue for an available connection.

Once again, telemetry can help us identify this problem. Ecto already ships with Telemetry support and emits several events that we can listen to and react to. The documentation has data and metadata that Ecto emits for all queries, including queue_time.

We can modify the previous handler example and also monitor long query waiting times in the connection pool queue:

# my_app/lib/my_app/telemetry.ex

  # ...
  def handle_event([:my_app, :repo, :query], measurements, metadata, _config) do
    queue_time_ms = measurements[:queue_time]

    if queue_time_ms > 5_000 do
      # The query waited more than 5s for a connection to be available
    end
  end

Of course, you can always increase the number of connections in an application's configuration:

# config/runtime.exs or config/dev.exs
config :hatch, MyApp.Repo,
  # ...
  pool_size: String.to_integer(System.get_env("POOL_SIZE", "10"))

With the config above, you can control the pool size using the POOL_SIZE env var or the default 10 connections size.

PostgreSQL Deadlocks

Locks are a fundamental mechanism that databases use to ensure data integrity. Still, they can struggle when there's a high volume of updates from different sources in the same timeframe.

A deadlock occurs when two or more processes wait for each other to release a resource, causing all processes to be stuck indefinitely.

How Deadlocks Occur

Deadlocks can happen when two or more processes try to acquire locks on multiple resources in an inconsistent order.

Consider the following schemas:

# my_app/lib/my_app/post.ex
defmodule MyApp.Post do
  use Ecto.Schema

  schema "posts" do
    field :reaction_count, :integer, default: 0
    has_many :reactions, MyApp.Reaction
  end
end

# my_app/lib/my_app/reaction.ex
defmodule MyApp.Reaction do
  use Ecto.Schema

  schema "reactions" do
    field :type, :string
    belongs_to :post, MyApp.Post
  end
end

Now imagine the following scenario using post and reaction schemas:

Process A acquires a lock on Post X.
Process B acquires a lock on Post Y.
Process A tries to acquire a lock on Post Y (but is blocked because Process B holds the lock).
Process B tries to acquire a lock on Post X (but is blocked because Process A holds the lock).

In this case, both processes wait for each other to release the locks, resulting in a deadlock.

If two processes try to add reactions to different posts and update reaction counts at the same time, we could potentially run into a deadlock:

# Process A
task_a = Task.async(fn ->
  Repo.transaction(fn ->
    post_x = Repo.lock!(from(p in Post, where: p.id == ^post_x_id))
    Repo.insert!(%Reaction{type: "like", post_id: post_x.id})
    Repo.update!(Post.changeset(post_x, %{reaction_count: post_x.reaction_count + 1}))
  end)
end)

# Process B
task_b = Task.async(fn ->
  Repo.transaction(fn ->
    post_y = Repo.lock!(from(p in Post, where: p.id == ^post_y_id))
    Repo.insert!(%Reaction{type: "like", post_id: post_y.id})
    Repo.update!(Post.changeset(post_y, %{reaction_count: post_y.reaction_count + 1}))
  end)
end)

Task.await(task_a)
Task.await(task_b)

Most database systems provide mechanisms to detect and automatically resolve deadlocks by rolling back one of the transactions involved.

To prevent deadlocks, you can:

Acquire locks in a consistent order across all processes. For example, you can enforce ordering by post ID:

Repo.transaction(fn ->
  post = Repo.lock!(from(p in Post, where: p.id == ^post_id, order_by: :id))
  Repo.insert!(%Reaction{type: "like", post_id: post.id})
  Repo.update!(Post.changeset(post, %{reaction_count: post.reaction_count + 1}))
end)

Use timeouts when acquiring locks to prevent indefinite waits. In Ecto, you can use the :timeout option with the Repo.transaction/2 function:

Repo.transaction(fn ->
  post = Repo.lock!(from(p in Post, where: p.id == ^post_id))
  Repo.insert!(%Reaction{type: "like", post_id: post.id})
  Repo.update!(Post.changeset(post, %{reaction_count: post.reaction_count + 1}))
end, timeout: 5_000)

By setting a timeout, a transaction will be rolled back if it cannot acquire the necessary locks within the specified time (preventing deadlocks from causing an application to hang indefinitely).

Final Thoughts

From the application point of view, there is only so much that we can actually monitor, since only a handful of entities can evaluate application context like query execution time, queue time, memory consumption, etc.

The best way to know what is happening to your whole stack is to instrument your application with tools like Telemetry or OpenTelemetry, then connect it to your favorite monitoring tool, like AppSignal!

Wrap Up

In this article, we explored common performance issues in Elixir applications using Ecto and provided insights on detecting and addressing these problems.

We started with the N+1 query problem, learning to identify and solve it using Ecto's preload functionality. Then we investigated inefficient query execution, discussing how to optimize queries and use Telemetry for monitoring.

Lastly, we covered connection pooling and concurrency issues, emphasizing the importance of proper configuration, monitoring, and techniques for avoiding deadlocks.

Happy coding!

P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, subscribe to our Elixir Alchemy newsletter and never miss a single post!

Debugging and Tracing in Erlang

Marcos Ramos — Tue, 17 Jan 2023 15:35:25 +0000

In part one of this series, the debugging tools we used — Elixir's IO.inspect/2, IEx.pry, and dbg/2 — required us to insert changes into code directly. Outside the development environment, you probably won't (and shouldn't) have access to your code.

Erlang has a few tools to debug code at runtime: :debugger, :dbg.tracer, and :observer.

First, let's look at the :debugger, a graphical debugging tool.

Let's get going!

Debugging Runtime with `:debugger` in Erlang

Side note: While :debugger has a graphical interface, Erlang also provides :dbg. That's a debugging tool as well, but it uses a text-based interface you can run directly on IEx to achieve the same results.

The very first thing that we need to do is to start the debugger. To do that, we simply call :debugger.start/0:

iex> :debugger.start()

We'll be presented with the debugger graphical interface:

However, to start debugging, we need to tell Erlang's interpreter where to stop.

We can interact with the interpreter using the :int module. We'll use two functions: :int.ni/1 and :int.break/2.

:int.ni/1 tells the interpreter to go over all nodes and
interpret the given module, while :int.break/2 adds a breakpoint in the given line:

# Tell the interpreter to interpret the given module
iex> :int.ni(Messenger.IExClient)
{:module, Messenger.IExClient}
# Add a breakpoint at line 78
iex> :int.break(Messenger.IExClient, 78)
:ok

Now, when we try to call the msg/2 function, our code will pause the execution, and the debugger interface will update:

Clicking twice on the breakpoint will open another window, so we can see the exact line of code where execution is paused. In this same window, we can also view all variables in the current execution context (like we did with IEx.pry).

As this is an Erlang tool, it will show the variables from Elixir code in a weird way. Erlang doesn't allow variables to be reassigned. The Elixir compiler has a trick to allow that: variables have versions.

Let's take the following Erlang snippet:

Name = "Jake",
Name2 = string:uppercase(Name).

Note how we have to create another variable to store the result of string:uppercase(Name). We can write this code in Elixir as:

name = "Jake"
name = String.upcase(name)

Behind the scenes, the compiler will automatically version this variable for us.

_name@1 = "Jake"
_name@2 = String.upcase(_name@1)

And that's how we see Elixir variables in the debugger window.

We can add breakpoints at any point in our code and inspect what happens on function calls, loops, recursive functions, etc. And the good thing is that we don't need to modify any lines of code as we did with IO.inspect, IEX.pry, and dbg/2 — but we still need the code to be available.

In the next section, we'll learn about tracing: a way to debug applications at runtime without modifying or having access to the source code.

Tracing (Distributed) Elixir Applications

So far, we've learned how to inspect and debug code and modules. However, sometimes we need to go even further.

Tracing an application means you can track an event starting in one function and follow its execution all the way down into the execution chain — even across the network.

Erlang provides different tools to do that. We'll look into :dbg.tracer (which is text-based) to learn the basics of tracing. Then, we'll use Trace Overview in :observer
(a graphical interface) to trace applications.

Traces with `:dbg.tracer`

Because we won't use the source code to tell the debugger where to stop, to get the tracer working, we need to set up a few things:

Start Erlang's debugger
Start the tracer process
Select which nodes should be monitored (when in clusters)
Tell the tracer which processes it should monitor
Tell the tracer how to detect a function call that should be traced

First, let's start the debugger and tracer processes:

# Start the debugger
iex> :dbg.start()
# Start the tracer
iex> :dbg.tracer()

For now, the tracer will only listen to the local node. We'll change this later.

To configure the process to listen to, we'll use :dbg.p/2 (p stands for process). To keep things simple, we'll listen to all processes:

# listen to all processes
iex> :dbg.p(:all, :c)

Now we need to give the tracer some function call patterns to monitor. To do that, we need function match specs.

Match specs alone require an entire post to explain. To keep it short, think of them as a regex for functions. You can match function calls with specific values and returns, which can be very useful when debugging a problem.

The match pattern we'll use here, [], says that we don't care about the values passed as an argument. Using :dbg.fun2ms, you can write the pattern as a function, and it will generate the match spec for you.

To identify the function to debug, use :dbg.tpl/4. tpl stands for trace pattern local.

In this example, we'll match all GenServer callbacks that
Messaging.MessengerServer implemented:

iex> :dbg.tpl(Messaging.MessengerServer, :handle_call, 3, [])
iex> :dbg.tpl(Messaging.MessengerServer, :handle_cast, 2, [])
iex> :dbg.tpl(Messaging.MessengerServer, :handle_info, 2, [])

Now, whenever we interact with the messenger functions, we'll be notified that it was called:

iex> sign in "alice"
Signed in!
(<0.159.0>) call 'Elixir.Messenger.MessagingServer':handle_call({sign_in,<<"alice">>,nil},{<0.160.0>,[alias|#Ref<0.3934582249.1729953800.172958>]},nil)
:ok
iex> msg "bob", "hello!"
Message sent!
(<0.159.0>) call 'Elixir.Messenger.MessagingServer':handle_call({send,<<"bob">>,<<"hello!">>},{<0.160.0>,[alias|#Ref<0.3934582249.1729953796.173763>]},#{inbox => [],notify_fun => nil,sent => [],user => <<"alice">>})
:ok

We don't need to edit code, load modules, or add breakpoints. The Erlang tracer detects function calls that match our rules and automatically traces them for us.

The log prints, but it is not Elixir-friendly because this tool was designed with Erlang code in mind. However, we can give the tracer a custom function to handle traces. With this function, we can translate the trace information into something that makes more sense to an Elixir developer.

This function will be called for all traces and given the trace information that should be handled, such as:

caller pid
module name
function name
function arguments
timestamp

iex> # Custom trace handler
iex> handler = fn data, trace_name ->
...>  case data do
...>    {_, pid, _, {module, fun, args}, timestamp} ->
...>      {{y, mm, d}, {h, m, s}} =  :calendar.now_to_datetime(timestamp)
...>      arg_list = Enum.map(args, &inspect/1)
...>
...>      IO.puts("#{trace_name} :: [#{y}-#{mm}-#{d} #{h}:#{m}:#{s}] (#{inspect(pid)}) #{inspect(module)}.#{fun}(#{Enum.join(arg_list, ", ")})")
...>  end
...> end

# Start tracer with the custom function
iex> :dbg.tracer(:process, {handler, "Initial Data"})
# Include timestamps on traces
iex> :dbg.p(:all, [:call, :timestamp])

Yes, the custom function is not pretty, but it does the job. We have to convert the timestamp from Erlang format to a readable string, and the arg list has to be transformed so we can read the values.

But now, the logged trace looks like it's coming from an Elixir application:

Initial Trace :: [2022-10-20 12:56:48] (#PID<18901.161.0>) Messenger.MessagingServer.handle_call({:sign_in, "bob", nil}, {#PID<18901.162.0>, [:alias | #Reference<18901.2941783407.3368878085.222214>]}, nil)

Now that we know the important concepts around tracing, let's do this in a cluster!

Remote Nodes

So far, we have worked with the local node, but our messenger application is designed to run in a cluster.

By tracing remote nodes, we can view everything that happens - from the moment we send a message in a local node to when it reaches the remote node.

The good news is that we already know most of what's required to do that. We just need to tell the tracer to monitor other nodes using :dbg.n (n stands for node).

To monitor the whole cluster, we iterate over the list of nodes and call :dbg.n/1:

iex> [Node.self() | Node.list()] |> Enum.each(&:dbg.n/1)

Putting it All Together: A Script that Runs a Tracer

Let's create a script that will automatically set up a tracer for us:

# tracer.exs

# Custom trace handler
handler = fn data, trace_name ->
  case data do
    {_, pid, _, {module, fun, args}, timestamp} ->
      {{y, mm, d}, {h, m, s}} =  :calendar.now_to_datetime(timestamp)
      arg_list = Enum.map(args, &inspect/1)

      IO.puts("#{trace_name} :: [#{y}-#{mm}-#{d} #{h}:#{m}:#{s}] (#{inspect(pid)}) #{inspect(module)}.#{fun}(#{Enum.join(arg_list, ", ")})")
  end
end

# Start the debugger process
:dbg.start()

# Start the tracer process
:dbg.tracer(:process, {handler, "Initial Trace"})

# Tell the tracer to monitor all nodes
[Node.self() | Node.list()] |> Enum.each(&:dbg.n/1)

# Tell the tracer to monitor all processes and include a timestamp
:dbg.p(:all, [:call, :timestamp])

# Tell the tracer the function pattern to monitor
:dbg.tpl(Messenger.MessagingServer, :handle_call, 3, [])
:dbg.tpl(Messenger.MessagingServer, :handle_cast, 2, [])
:dbg.tpl(Messenger.MessagingServer, :handle_info, 2, [])

To see it in action, let's start another node with ./start dbg that will just print the trace logs. Load the script above with c "tracer.exs" on iex:

$ ./start dbg
iex> c "tracer.exs"

The new node will see all messages exchanged between node0 and node1, as well as all internal calls:

# alice signs in
Initial Trace :: [2022-10-13 4:42:59] (#PID<18901.159.0>) Messenger.MessagingServer.handle_call({:sign_in, "alice", nil}, {#PID<18901.160.0>, [:alias | #Reference<18901.3988451517.2270494721.161681>]}, nil)

# bob signing in
ok :: [2022-10-13 4:43:8] (#PID<19318.159.0>) Messenger.MessagingServer.handle_call({:sign_in, "bob", nil}, {#PID<19318.160.0>, [:alias | #Reference<19318.2685074897.123797505.34702>]}, nil)

# alice sends "Hello!" to bob
ok :: [2022-10-13 4:43:42] (#PID<18901.159.0>) Messenger.MessagingServer.handle_call({:send, "bob", "Hello!"}, {#PID<18901.160.0>, [:alias | #Reference<18901.3988451517.2270494721.161694>]}, %{inbox: [], notify_fun: nil, sent: [], user: "alice"})

# bob receives "Hello!" from alice
ok :: [2022-10-13 4:43:42] (#PID<19318.159.0>) Messenger.MessagingServer.handle_info({:msg, "alice", "Hello!"}, %{inbox: [], notify_fun: nil, sent: [], user: "bob"})

# bob opens its inbox
ok :: [2022-10-13 4:43:52] (#PID<19318.159.0>) Messenger.MessagingServer.handle_call(:inbox, {#PID<19318.160.0>, [:alias | #Reference<19318.2685074897.123797505.34749>]}, %{inbox: [{"alice", "Hello!"}], notify_fun: nil, sent: [], user: "bob"})

By tweaking the trace handler function and the match specs, we can design powerful tracing scripts to see everything that happens in our application.

The `:observer` in Erlang

This is another valuable tool with a graphical interface included in Erlang. We can access it from iex by simply typing :observer.start:

There is a lot of information here, and you can even see stats from other nodes!

Trace Overview in `:observer`

As mentioned, :dbg is a text-based tool for debugging and tracing. But it's also possible to do the same thing using the "Trace Overview" in :observer:

And the steps are the same: select nodes, select processes, and add match specs.

Once you have this configured, hit Start Trace to view the trace logs in a new window:

Debugging Production Apps with AppSignal

AppSignal offers an integration for Erlang.

After you deploy your application to production, AppSignal can help monitor and debug errors from the real world too. You can set it up for your app easily and painlessly — once installed, you'll immediately gain access to the main dashboard, which includes error tracking, alongside some other great features.

Set up alerts, and you'll be instantly notified when errors occur.

You can drill down to see the root causes of errors and easily fix them from there:

Wrap Up

In both parts of this series, we put the most important Elixir and Erlang debugging tools into action (with the help of our demo project).

From Elixir's simple IO.inspect/2 to Erlang's powerful tracer, the Erlang ecosystem has tools for all kinds of debugging scenarios. We can use these tools seamlessly, whether locally or in a distributed system.

Happy debugging!

P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, subscribe to our Elixir Alchemy newsletter and never miss a single post!

Debugging in Elixir and Erlang: An Introduction

Marcos Ramos — Tue, 06 Dec 2022 12:54:28 +0000

Welcome to part one of this two-part series on debugging in Elixir and Erlang. In this post, we'll use several different tools and techniques to debug Elixir code.

First, we'll get to know the demo project I created to showcase certain tools: dist_messenger. It's an Elixir project of a distributed messaging system that can be used directly on IEx. It allows users in different nodes to send and receive messages to each other.

Then, we'll learn about the basic debugging tools of Elixir: inspect, pry and dbg.

In part two, we'll turn our attention to Erlang, putting together what we learn into a simple script to trace a process message across nodes.

Let's get going!

The Necessity of Debugging

You write a piece of code, you run it, and it doesn't execute as expected.

That is what programming looks like most of the time. Trying to figure out what's happening can not only be time-consuming, but very frustrating when we don't have the right tools.

Can you level your washing machine without a leveling tool, instead using a ruler? Of course, but it will take much more time and energy.

So, to understand what's happening in our code, it's good sometimes to take a few steps back and ask some questions, like:

Is the value of this variable correct?
Are the transformations being applied to a variable producing the expected result?
Are the messages being correctly sent from one process to another?
Is there any abnormality in resource consumption?

Both Elixir and Erlang provide tools to answer these questions. Knowing how to use the tools certainly adds a lot of value.

Getting to Know Our Demo Project

The dist_messenger project uses a combination of GenServer and :global to provide a distributed messaging system inside an Erlang cluster.

Each node in this cluster can handle one user, and its state is maintained by a single GenServer, the Messenger.MessagingServer. Users can sign in to the cluster with a unique name, which is then registered across all nodes using the :global.register_name/2 function.

For the user interface, the Messenger.IExClient provides several functions that allow users to interact with the messaging system in IEx. This module is imported by the .iex.exsscript, so we can use all its functions directly on iex when running it with iex -S mix. Check the docs for .iex.exs
files.

Because each node handles one user, to get the full experience of this project, we need to run multiple nodes (by running nodes with a node name and a shared secret cookie). To make things simple, the project includes a script start that will do that for us. You just need to give the name (it will run all nodes on 0.0.0.0).

You'll notice that the included .iex.exs script will automatically try to connect to nodes node0 up to node9 on localhost. So, by naming the nodes within this range, we should get a cluster.

Let's start two nodes and sign-in two users: user alice on node0 and bob on node1.

# On terminal 1
$ ./start node0

# On terminal 2
$ ./start node0

To sign in to the messaging system, you can call sign in <name> on iex:

# node0 - user: alice
iex> sign in "alice"
Signed in!

Now you can send a message to other users using msg <user> <message>:

# node0 - user: alice
iex> msg "bob", "Hello! How are you?"
Message sent!

In bob's session, we get a notification that a new message has arrived:

# node1 - user: bob
[!] New message from alice

We can use the inbox command to view all received messages:

# node1 - user: bob
iex> inbox
> from: alice
> Hello! How are you?
---

In alice's session, we can use sent to view all sent messages:

# node0 - user: alice
iex> sent
> to: bob
> Hello! How are you?
---

There are also other commands:

signout: signs out the current users from the cluster
whoami: prints the current signed-in user
last_msg: prints the last received message
editor: sends a message like msg, but it's interactive

Now that we know how our example works, let's get started with debugging!

Elixir Debugging Basics

You can use the tools in this section to:

quickly gather information about a specific variable
get the result of a function call
check a whole pipe chain

They do require changes in the source code, so we'll use them during development and tests.

Debugging with `IO.inspect/2` in Elixir

This is the easiest — and probably the first — tool that an Elixir developer will reach for to investigate issues. The IO.inspect/2 function prints the contents of an expression and returns the expression itself.

iex> name = {:name, "Jack Shephard"}
iex> IO.inspect(name, label: "Name")
# Name: {:name, "Jack Shephard"}

It returns the value of the evaluated expression so that you can use it within a pipeline. The label option is very useful when you have multiple calls to IO.inspect and need some hints to understand what you are looking at.

person = %{name: "Kate Austen"}

iex> " some text "
...> |> String.trim()
...> |> String.upcase() |> IO.inspect(label: "Here")
...> |> String.split()
Here: "SOME TEXT"
["SOME", "TEXT"]

`IEx.pry` for Elixir

While IO.inspect allows you to read the content of any variable, IEx.pry gives us a bit more insight and information on the code.

You can think of IO.pry as an interactive IO.inspect.

Let's use it in the editor/0 function and see what happens:

...

def editor do
  case Messaging.whoami() do
    {:ok, _user} ->
      recipient = IO.gets("recipient: ") |> String.trim()
      message = IO.gets("message: ") |> String.trim()

      # Pause the execution here
      require IEx; IEx.pry

      msg(recipient, message)

    _ ->
      IO.puts("Not signed in!")
  end
end

...

Note: you must use IEx in the application context in order to use IEx.pry. This means you need to start it with iex -S mix.

When you call the editor/0 (after you type in the recipient and the message), the iex session will pause execution on the line.

iex> editor
recipient: kate.austen
message: Hello, Kate!
Break reached: Messenger.IExClient.editor/0 (lib/messenger/iex_client.ex:96)

   93:         recipient = IO.gets("recipient: ") |> String.trim()
   94:         message = IO.gets("message: ") |> String.trim()
   95:
   96:         require IEx; IEx.pry
   97:
   98:         msg(recipient, message)
   99:

pry>

In this new console, you can type a variable's name to see its contents:

pry> recipient
"kate.austen"
pry> message
"Hello, Kate!"

Type continue or next to continue the execution.

`dbg/2` Debugging in Elixir

This is a new feature since Elixir 1.14. It's pretty much IO.inspect/2 with superpowers.

To demonstrate it, we'll add dbg to this demo line. It will be called whenever the server receives a message from another server.

# ...

def handle_info({:msg, from, body}, %{inbox: inbox} = state) do
  # ...

  message = {from, body}
  updated_state = %{state | inbox: [message | inbox]} |> dbg()

  {:noreply, updated_state}
end

#...

Now, when your node receives a message, the recipient's iex session will request to pry on the code:

[!] New message from jacob
Request to pry #PID<0.159.0> at Messenger.MessagingServer.handle_info/2 (lib/messenger/messaging_server.ex:82)

   79:     end
   80:
   81:     message = {from, body}
   82:     updated_state = %{state | inbox: [message | inbox]} |> dbg()
   83:
   84:     {:noreply, updated_state}
   85:   end

Allow? [Yn]

This will open an IEx.pry session, and you can check the values of all variables.

You can also use dbg at the end of a pipe to see what's happening:

[["h"], ["i"]] #=> [["h"], ["i"]
|> List.flatten() #=> ["h", "i"]
|> Enum.join() #=> "hi
|> dbg()

dbg/2 is macro-evaluated at compile time. When called, it will inject code
that allows the interpreter to pause an application's execution and pry the
current context. Check out 'Elixir 1.14: Better Debugging with dbg/2 and More' for an overview of dbg/2.

Debugging Production Apps with AppSignal

After deploying your app to production, AppSignal can help debug issues from the real world.

Set up AppSignal for your Elixir application, and you'll automatically gain access to an error dashboard with information about all the errors in your app.

From there, you can dig deeper for more information on individual errors, so you can fix them:

Wrap Up

This post has introduced debugging basics in Elixir using IO.inspect/2, IEx.pry, and dbg/2. Check out Three Ways to Debug Code in Elixir for some more information.

Next time, we'll focus on Erlang specifically, debugging runtime and finding out how to trace an Elixir clustered application using Erlang's :debugger.

Until then, happy coding!

P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, subscribe to our Elixir Alchemy newsletter and never miss a single post!

Predictable Code in Elixir: Expressions as Reducers and Macros

Marcos Ramos — Tue, 30 Aug 2022 11:51:52 +0000

In the first part of this series on maintainable Elixir code, we started by applying rules for code predictability in our code design. We immediately saw an emerging pattern: a series of transformations on state. In this part, we'll explore this pattern further.

We'll first learn how to write expressions as reducers. Then we'll use metaprogramming to make use of reducers and enforce code style seamlessly.

Finishing up, we'll see an example where all the pieces fit together.

Let's get going!

Quick Recap of Part One and What We'll Do

In the first part, we experimented with applying code styles to this snippet:

with %Payment{} = payment <- fetch_payment_information(params),
     {:ok, user} <- Session.get(conn, :user),
     address when !is_nil(address) <- fetch_address(user, params),
     {:ok, order} <- create_order(user, payment, address) do
  conn
  |> put_flash(:info, "Order completed!")
  |> render("checkout.html")
else
  {:error, :payment_failed} ->
    handle_error(conn, "Payment Error")

  %Store.OrderError{message: message} ->
    handle_error(conn, "Order Error")

  error ->
    handle_error(conn, "Unprocessable order")
end

By the end of this post, we'll have all the tools to rewrite it like this:

case Checkout.execute(%{params: params}, options) do
  {:ok, %{order: order}} ->
    conn
    |> put_flash(:info, "Order completed!")
    |> redirect(to: Routes.order_path(conn, order))

  {:error, error}
    conn
    |> put_flash(:error, parse_error(error_description))
    |> render("checkout.html")
end

While writing this post, I created ex_pipeline, an open source library that allows developers to create pipelines while enforcing code style easily.

All code examples in this post are simplified versions of what exists in that project.

Chain of Transformations

One of my favorite hobbies is woodworking — I'm not good at it, by all means, but it's something that I do enjoy. Before starting a new project, I always write down all the materials and tools I'll need, as well as the steps I'll follow. That's how I go from pieces of wood to a finished table, from an initial state to a finished state.

Let's think about how a table is made: you get some raw materials — wood, nails, glue — and a few tools. Then you execute a set of actions to modify the shape and appearance of the materials — cutting, assembling, polishing, and painting.

You apply a chain of transformations on an initial state (raw materials) until you get the desired state (the table).

We already talked about the emerging pattern of a pipeline. That's what we are going to explore over the next paragraphs.

Writing Expressions as Reducers in Elixir

Reducers are one of the key concepts of functional programming. They are very simple to understand: you take a list of values, apply a function to each element, and accumulate the results.

In Elixir, we can work with reducers using the Enum.reduce/3
function and its variants — Enum.reduce/2 and Enum.reduce_while/3.

For example, we can use a reducer to filter all even numbers from a list:

numbers = [1, 2, 3, 4, 5, 6]
starting_value = []

Enum.reduce(numbers, starting_value, fn current_number, filtered_values ->
  if rem(current_number, 2) == 0 do   # is the current number even?
    [number | filtered_values]        # if so, add it to the accumulator
  else                                # otherwise...
    filtered_values                   # just ignore it and return the accumulator
  end
end)

This code will return the list [2, 4, 6].

To execute different actions on a value, we can transform the list of values into a list of functions. Then we pass the value as the initial value for the accumulator:

transformations = [
  fn x -> x + 1 end, # add 1
  fn x -> x * 2 end  # multiply by two
]
starting_value = 10

Enum.reduce(transformations, starting_value, fn transformation, current_value ->
  apply(transformation, [current_value])
end)

This looks like a complicated way to write (10 + 1) * 2, right? But by expressing each transformation as a function, we can attach an arbitrary number of transformations. They all must accept the same number of parameters and return the next updated state. In other words, these functions must look the same and be small.

In the end, we want to write the previous example as something like this:

defmodule MyModule do
  use Pipeline

  def sum_step(value, _), do: {:ok, value + 1}
  def double_step(value, _), do: {:ok, value * 2}
end

In the next part, we can do just that using a bit of magic from macros!

Sewing Reducers Into Features with Macros

Now that we know how to use reducers let's use them to write pipelines.

The goal is to make the process of writing, reading, and maintaining pipelines as easy as possible. So, instead of adding a DSL or using complex configs, we just want to write our functions using the same pattern of name and arity. We can then automate the process of building the pipeline by detecting which functions follow this pattern.

We create a new pipeline by writing code on the same pattern.

The State: Track What's Happening in Elixir

Before we dive into macros, let's take a step back and talk a little bit about the state of the pipeline.

When executing a pipeline, we need to know a few things: the initial state, the current state, if it's still valid, and if there are any errors. All this information will help us debug and troubleshoot any problems we might find when writing our code.

Also, by abstracting state updates in this module, we can enforce a very important rule on reducers: the return value must be an ok/error tuple.

The starting point of a module that manages state should be something like this:

defmodule Pipeline.State do
  defstruct [:initial_value, :value, :valid?, :errors]

  def new(value) do
    %Pipeline.State{valid?: true, initial_value: value, value: value, errors: []}
  end

  def update(state, {module, function_name} = _function_definition, options \\ []) do
    case apply(module, function_name, [state.value, options]) do
      {:ok, value} ->
        %Pipeline.State{state | value: value}

      {:error, error_description} ->
        %Pipeline.State{state | valid?: false, errors: [error_description | state.errors]}

      bad_return ->
        raise "Unexpected return value for pipeline step: #{inspect(bad_return)}"
    end
  end
end

The new/1 function will create a new valid and clean %Pipeline.State{} struct based on the initial value we give to the pipeline executor.

The update/3 function will update or invalidate the given state by calling function with the state's value and the given options.

If the given function returns an {:ok, <updated_value>}, then the state's value is updated, and we are good to go. However, if the function returns an {:error, <error>} value, the state is invalidated. The returned error is added to the list of errors in the state. If the function returns anything that's different from an ok/error tuple, it will raise an exception.

See the full implementation of this module.

Pipeline Steps and Hooks

Each function that transforms the state will be called a step. Here are some guidelines to follow:

A step is a function whose name ends with _step and accepts two parameters.
Steps execute in the order they are declared in their module.
If one step fails, then all remaining steps are ignored.

Sometimes, we still want to execute code, even during failures — write a log, update a trace, publish a message, etc. We have a special type of step for these cases: a hook. Let's list the guidelines for hooks:

A hook is a function whose name ends with _hook and accepts two parameters.
Hooks execute in the order they are declared, just like steps.
They are always executed at the end of the pipeline, after all steps execute.

Good! But how do we detect that steps and hooks exist? The answer is
metaprogramming! Luckily for us, Elixir has powerful metaprogramming tools to make all this possible.

Setting Up the Required Macros in Elixir

We'll need two things: macros and compile callbacks to read information about the functions of a module, and store what a step and a hook are.

Starting with the base module Pipeline, we want to use Pipeline in other modules. For that to happen, we declare a special macro, __using__/1. This macro is called with the keyword use in Elixir.

In this macro, we add a compile hook to the target module so that we can inject code into it. The @before_compile hook does exactly that by calling the given function when a compiler is about to generate the underlying bytecode. It accepts either a module or a tuple with a module and function name. We'll go with the second option to make things simpler.

defmodule Pipeline do
  defmacro __using__(_options) do
    quote do
      # Calls Pipeline.build_pipeline/1 before generating the final bytecode, allowing us to analyze, generate and
      # inject code whenever we call `use Pipeline`.
      @before_compile {Pipeline, :build_pipeline}
    end
  end

  defmacro build_pipeline(env) do
    # inject code!
  end
end

Anything called inside the quote block will be injected into the caller module — including the result of the @before_compile hook.

Check out the official docs for more information about quote and unquote blocks.

Now, whenever we want to create a pipeline, we call use:

defmodule MyPipeline do
  use Pipeline # <- code will be injected!
end

Detecting Steps and Hooks

We have everything in place to inject code, but we still need to generate the code that will be injected. Let's expand the build_pipeline/1 macro:

defmacro build_pipeline(env) do
  # Fetch all public functions from the caller module
  definitions = Module.definitions_in(env.module, :def)

  # Filter functions that are steps and hooks
  steps = filter_functions(env.module, definitions, "_step", 2)
  hooks = filter_functions(env.module, definitions, "_hook", 2)

  # Generate code on the caller module
  quote do
    # returns all steps and hooks
    def __pipeline__, do: {unquote(steps), unquote(hooks)}

    # Syntatic sugar so we can execute directly from the module that defines it
    def execute(value, options \\ []), do: Pipeline.execute(__MODULE__, value, options)
  end

  # Filter functions from the given module based on their suffix and arity
  defp filter_functions(module, definitions, suffix, expected_arity) do
    functions =
      Enum.reduce(definitions, [], fn {function, arity}, acc ->
        # Detect if the function name ends with the desired suffix: _step or _hook
        valid_name? =
          function
          |> Atom.to_string()
          |> String.ends_with?(suffix)

        # Detect if the function arity matches the expected arity
        has_expected_args? = arity == expected_arity

        cond do
          valid_name? and has_expected_args? ->
            # In this case, the function does end with the desired suffix and has the correct arity.
            # We include it in the accumulator along with the line where it was declared so we can
            # order them by their position in their module
            {_, _, [line: line], _} = Module.get_definition(module, {function, arity})
            [{module, function, line} | acc]

          valid_name? ->
            # If the function has the desired suffix but the arity is not correct, we raise this error
            # because we don't want people trying to figure out why their steps or hooks are not
            # being executed.
            raise(PipelineError, "Function #{function} does not accept #{expected_arity} parameters.")

          true ->
            # If the function doesn't match our filters, it's not a part of the pipeline and can be
            # just ignored
            acc
        end
      end)

    # At this point we have filtered the functions that match the filter criteria but they
    # are not in order. We use the line number information to sort them and then drop it
    # once we don't need it anymore.
    functions
    |> Enum.sort(fn {_, _, a}, {_, _, b} -> a <= b end) # order by line number
    |> Enum.map(fn {m, f, _l} -> {m, f} end)            # drop line number
  end
end

This macro receives the compiler env, which has lots of context information. Here, the important bit is the caller module, accessible via the env.module attribute.

Then we use the module.definitions_in/2 special function to get a list of all functions declared on the module env.module with the def keyword.

We call the Pipeline.filter_functions/4 function to filter these definitions by their suffix and arity, essentially detecting our steps and hooks! The Pipeline.filter_functions/4 function is kind of big, so I've added comments to help you navigate through it.

As said before, anything inside the quote block is injected directly into the caller module. So whenever we call use Pipeline, the module will have two extra functions: __pipeline__/0, and execute/2.

The Pipeline module uses the first function to execute our custom pipeline, while the execute/2 function is just a convenience function that will execute Pipeline.execute/3. It allows us to execute our pipeline by calling MyPipeline.execute(value, options).

Speaking of Pipeline.execute/3, it's time to define it. This function is the core of this engine, and it's responsible for actually calling a reducer that will power our pipeline engine:

defmodule Pipeline do
  # ...

  def execute(module, value, options) do
    # Build a new initial state of the pipeline
    initial_state = State.new(value)

    # Fetch steps and hooks from the module
    {steps, hooks} = apply(module, :__pipeline__, [])

    # Run each step from the pipeline and build the final state
    final_state =
      Enum.reduce(steps, initial_state, fn reducer, current_state ->
        State.update(current_state, reducer, options)
      end)

    # Run each hook with the final state
    Enum.each(hooks, fn {module, function} ->
      apply(module, function, [final_state, options])
    end)

    # Transform the state value into an ok/error tuple
    case final_state do
      %State{valid?: true, value: value} ->
        {:ok, value}

      %State{errors: errors} ->
        {:error, errors}
    end
  end
end

Check out the complete version of this module here.

Note: In the complete version of this module, there is also another kind of hook, called an async hook. Async hooks work just like the hooks presented here, but are executed in parallel rather than sequentially. They will not be covered in this post, since they are essentially a hook executed with a Task.

Building and Executing a Pipeline

By simply calling use Pipeline and writing function names with the _step or _hook suffix, we are now able to build our pipelines. Let's rewrite our last example from the first part of the post with this new mechanic:

defmodule Checkout do
  use Pipeline

  def fetch_payment_information_step(value, options) do
    # ...
  end

  def fetch_user_step(value, options) do
    # ...
  end

  def fetch_address_step(value, options) do
    # ...
  end

  def create_order_step(value, options) do
    # ...
  end

  def report_checkout_attempt_hook(state, options) do
    # ...
  end
end

We can execute this new pipeline like this:

case Checkout.execute(%{params: params}, options) do
  {:ok, %{order: order}} ->
    conn
    |> put_flash(:info, "Order completed!")
    |> redirect(to: Routes.order_path(conn, order))

  {:error, error}
    conn
    |> put_flash(:error, parse_error(error_description))
    |> render("checkout.html")
end

No more with blocks, and no need to manually handle errors. The controller is now focused on handling the HTTP layer, and the checkout feature has an official place to live. Adding a new step to the checkout process just requires that we write a function in the right place!

Wrap Up

In this post, we learned how to express a set of transformations as a reducer. Then, using the power of macros, we automatically created pipelines by detecting the signature of functions at compile time.

The features that use pipeline mechanics are explicit and contained — we know exactly what to expect and where to go when modifying them. We expect all steps to look and behave in the same way. The basics of error handling are already in place, you just need to decide what to do. These pipelines are, indeed, predictable.

I hope you've found this two-part series about keeping your Elixir code maintainable helpful. Until next time, happy coding!

P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, subscribe to our Elixir Alchemy newsletter and never miss a single post!

Writing Predictable Elixir Code with Reducers

Marcos Ramos — Tue, 26 Jul 2022 12:00:16 +0000

This is the first part of a two-part series about maintainable code in Elixir. In this part, we will show how code predictability plays a crucial role in a project's short and long-term health. We will use Elixir's built-in features for this, like the pipe operator, tuples, and with blocks.

First, we'll explain what predictability is and why it is so important. Then we will go through some tools that Elixir already has and how you can use them to write better code.

Finally, we'll demonstrate how some simple rules can help developers write code that is easy to read, write, and maintain.

Let's get started!

On Complexity and Predictability

I still remember when I first started learning about functions in my math class. Things seemed simple and easy to understand:

One function, one variable, and one simple operation.

But as the years passed and more complex things were added to the basics, the small and easy functions were gone.

I was reading stuff like this:

...What? Alpha? Theta with an inverted hat?

Eventually, though, after rereading and rewriting these kinds of functions over and over, they also become easy to work with.

In the excellent book The Programmer's Brain: What Every Programmer Needs to Know About, Felienne Hermans does an amazing job of explaining the different mechanisms that our brain uses to read, write, and understand code, as well as techniques to perform these tasks as efficiently as possible.

In short: the amount of new information that our brains can handle is actually pretty small, and there is not really much we can do about it.

The good news is that our memory is very different from a computer — and we can take advantage of that. With enough repetition, we eventually start to store patterns in our long-term memory and then use that knowledge to understand new information faster.

That's why a skill becomes easier with more practice, be it math, playing the guitar, or programming. The more we make things look and behave the same, the easier and faster it is to absorb them.

Why Should I Make My Elixir Code Predictable?

When it comes to understanding what we read and how well other people will understand the code that we write, being predictable is essential.

Three key elements make code predictable:

Structure: different blocks of code look and behave the same. That is the main reason it is easy to understand a for loop, even in languages that you've never used before.
Size: smaller blocks (like functions, modules, classes, etc.) are easier to remember.
Simplicity: less moving parts, like function parameters, help our brain keep track of what is happening.

One good example of predictability in the Elixir world is the Plug library because:

It uses behaviours to keep all implementations with the same structure (expected input and output).
Each plug is expected to be as small as possible since they add latency to the HTTP response.
They have a pretty simple shape: two functions, each with two parameters.

So, what if we make our entire code predictable?

Elixir's Tools for Writing Predictable Code

Elixir itself has a couple of nice tools that, when used correctly, help us create predictable code: its pipe operator and with statement.

Keep in mind that neither of these will enforce a pattern or design principle — they are just tools.

Elixir's Pipe Operator

The pipe |> operator is an amazing tool that helps us express a chain of function calls as a simple sequence of actions.

Even if you've never written any Elixir code, you probably understand what this piece of code is trying to do:

form_params
|> validate_form()
|> insert_user()
|> report()
|> write_response()

It's simple to read and easy to understand what is happening.

However, because it's so simple, we're also very limited in what we can do with it. Since all functions are chained, they
depend on the previous result. If any of the functions break, there's not much we can do about it unless we add error handling to all of them.

For a proper pipeline where we can handle errors and don't want to make the functions dependent on one another, it's better to use the with statement.

Elixir's `with` Statement

Pipe operators are simple, but we often need to check the return to ensure we have a valid state.

Let's take the previous example and rewrite it with a with block:

with %User{} = user_data <- validate_form(form_params),
     {:ok, user} <- insert_user(user_data),
     :ok <- report(user) do
  write_response(user)
else
  error ->
    report(error)
    handle_error(error)
end

Now we have proper error handling and a chance to do something if our user data is invalid or it's not possible to insert the user. However, even in this simple example, it's a bit harder to read because of the added complexity. Note that since functions can return any value, we have to handle the return of each step explicitly.

Let's use a more complex example — a generic checkout code where we need information about the user, payment, and address — and try to create an order:

with %Payment{} = payment <- fetch_payment_information(params),
     {:ok, user} <- Session.get(conn, :user),
     address when !is_nil(address) <- fetch_address(user, params),
     {:ok, order} <- create_order(user, payment, address) do
  conn
  |> put_flash(:info, "Order completed!")
  |> render("checkout.html")
else
  {:error, :payment_failed} ->
    handle_error(conn, "Payment Error")

  %Store.OrderError{message: message} ->
    handle_error(conn, "Order Error")

  error ->
    handle_error(conn, "Unprocessable order")
end

Not only does each function have a different return type, but errors may also have different shapes.

Also, because the existing functions don't follow a pattern, a developer adding a new step to this feature will not know what the new function should return. A struct? ok/error tuple? A non-nil/nil value? What about errors?

The lack of predictability here is bad for whoever is reading this code, as well as people who will modify it in the future.

Design Better Pipelines in Elixir

As previously stated, to achieve predictability, we need three things in our code: structure, size, and simplicity. Knowing that, we can create a few rules to help us write predictable code:

Each function on a pipeline is expected to transform a given state into an updated state, and it should only do one transformation. This will help us keep functions small and focused.
Always receive two parameters. The first parameter is the state we want to transform, and the second contains any optional or extra data we might need to perform such a transformation. The second parameter is optional.
Always return an ok/error tuple. If everything goes well, an updated value of a state is returned.

For now, we won't require a structure or type for the error description.

Let's revisit our checkout code, now applying these rules:

options = %{conn: conn}

with {:ok, payment} <- fetch_payment_information(params, options),
     {:ok, user} <- fetch_user(conn),
     {:ok, address} <- fetch_address(%{user: user, params: params}, options),
     {:ok, order} <- create_order(%{user: user, address: address, payment: payment}, options)
  do
  conn
  |> put_flash(:info, "Order completed!")
  |> redirect(to: Routes.order_path(conn, order))
else
  {:error, error_description} ->
    conn
    |> put_flash(:error, parse_error(error_description))
    |> render("checkout.html")
end

It definitely looks better, and if someone in the future has to add a new step, they will know how this new function should look. Because the errors always have the same shape, we just need to find the appropriate message for a given error description, and everything else will look the same.

However, although we've solved the design of one particular feature, none of these changes or design principles are enforced. A team working on a different part of your product might never have contact with this code and may follow another design or pattern — or none at all.

If we can find a way to enforce these changes, then the code will always look the same.

An Emerging Pattern

Now we can see a pattern emerging when we write our functions: chain-of-state transformations — a pipeline. It's almost like an Enum.reduce/3 function.

However, instead of applying the same function to a collection of values, we apply a collection of functions to transform a state.

We'll explore this pattern in greater detail in the next part of this series.

Coming Up Next Time: Enforcing Predictable Elixir Code

In this article, we showed how to write code in a pattern that our brains can understand faster and more accurately. And by doing so, we also can write — and keep writing! — code that is maintainable in the long term.

Note that this pattern does not cover module organization, project structure, or API design. For that, I highly recommend the series of articles Towards Maintainable Elixir by Saša Jurić.

In the next and final part of this two-part series, we'll learn how to create a basic framework to enforce design principles in our Elixir code.

Until then, happy coding!

P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, subscribe to our Elixir Alchemy newsletter and never miss a single post!

Forem: Marcos Ramos

Build A Simple Tracing System in Elixir

On Tracing in Elixir

Meet OpenTelemetry for Elixir

What's Happening Here?

Why I Built an Abstraction Layer for OpenTelemetry

Breaking Down the Pain Points of OpenTelemetry

A Setup for a Setup in Elixir

Translating Elixir Application Data to Span Attributes

Convert Complex Types to Basic Types

Using Elixir's defguard

Wrapping Up

Tackling Performance Issues in Ecto Applications

The N+1 Query Problem

Detecting the Problem in Elixir

Using Ecto's Preload

Preloading with Joins

Inefficient Queries in Ecto

Example 1: Missing Indexes

Detecting Bad Queries with PostgreSQL and Telemetry

Ecto Connection Pooling and Concurrency Issues

PostgreSQL Deadlocks

How Deadlocks Occur

Final Thoughts

Wrap Up

Debugging and Tracing in Erlang

Debugging Runtime with :debugger in Erlang

Tracing (Distributed) Elixir Applications

Traces with :dbg.tracer

Remote Nodes

Putting it All Together: A Script that Runs a Tracer

The :observer in Erlang

Trace Overview in :observer

Debugging Production Apps with AppSignal

Wrap Up

Debugging in Elixir and Erlang: An Introduction

The Necessity of Debugging

Getting to Know Our Demo Project

Elixir Debugging Basics

Debugging with IO.inspect/2 in Elixir

IEx.pry for Elixir

dbg/2 Debugging in Elixir

Debugging Production Apps with AppSignal

Wrap Up

Predictable Code in Elixir: Expressions as Reducers and Macros

Quick Recap of Part One and What We'll Do

Chain of Transformations

Writing Expressions as Reducers in Elixir

Sewing Reducers Into Features with Macros

The State: Track What's Happening in Elixir

Pipeline Steps and Hooks

Setting Up the Required Macros in Elixir

Detecting Steps and Hooks

Building and Executing a Pipeline

Wrap Up

Writing Predictable Elixir Code with Reducers

On Complexity and Predictability

Why Should I Make My Elixir Code Predictable?

Elixir's Tools for Writing Predictable Code

Elixir's Pipe Operator

Elixir's with Statement

Design Better Pipelines in Elixir

An Emerging Pattern

Coming Up Next Time: Enforcing Predictable Elixir Code

Using Elixir's `defguard`

Debugging Runtime with `:debugger` in Erlang

Traces with `:dbg.tracer`

The `:observer` in Erlang

Trace Overview in `:observer`

Debugging with `IO.inspect/2` in Elixir

`IEx.pry` for Elixir

`dbg/2` Debugging in Elixir

Elixir's `with` Statement