Add support for Telemetry events

.iex.exs

@@ -56,3 +56,5 @@ cacheinfo = fn() ->
   IO.puts "size: #{size}"
   :ets.i(:fun_with_flags_cache)
 end
+
+# FunWithFlags.Telemetry.attach_debug_handler()

CHANGELOG.md

@@ -4,8 +4,9 @@
 
 * Add support for Elixir 1.18. Drop support for Elixir 1.15. Elixir >= 1.16 is now required. Dropping support for older versions of Elixir simply means that this package is no longer tested with them in CI, and that compatibility issues are not considered bugs.
 * Drop support for Erlang/OTP 24, and Erlang/OTP >= 25 is now required. Dropping support for older versions of Erlang/OTP simply means that this package is not tested with them in CI, and that no compatibility issues are considered bugs.
+* Instrument the package with [Telemetry](https://hex.pm/packages/telemetry): FunWithFlags now emits Telemetry events for persistence operations. ([pull/197](https://github.com/tompave/fun_with_flags/pull/197), and thanks [Kasse-Dembele](https://github.com/Kasse-Dembele) for suggesting the feature and sharing his work in [pull/176](https://github.com/tompave/fun_with_flags/pull/176))
 * Improve how the change-notification Phoenix.PubSub adapter manages its connection and readiness status. ([pull/191](https://github.com/tompave/fun_with_flags/pull/191))
-* Adding a suite of synthetic benchmark scripts for the package. ([pull/193](https://github.com/tompave/fun_with_flags/pull/193))
+* Add a suite of synthetic benchmark scripts for the package. ([pull/193](https://github.com/tompave/fun_with_flags/pull/193))
 
 ## v1.12.0
 

README.md

@@ -42,6 +42,7 @@ It stores flag information in Redis or a relational DB (PostgreSQL, MySQL, or SQ
   - [PubSub Adapters](#pubsub-adapters)
 * [Extensibility](#extensibility)
   - [Custom Persistence Adapters](#custom-persistence-adapters)
+* [Telemetry](#telemetry)
 * [Application Start Behaviour](#application-start-behaviour)
 * [Testing](#testing)
 * [Development](#development)
@@ -705,6 +706,11 @@ And then configure the library to use it:
 ```elixir
 config :fun_with_flags, :persistence, adapter: MyApp.MyAlternativeFlagStore
 ```
+## Telemetry
+
+FunWithFlags is instrumented with [Telemetry](https://hex.pm/packages/telemetry) and emits events at runtime. Please refer to the [Telemetry docs](https://hexdocs.pm/telemetry/readme.html) for detailed instructions on how to consume the emitted events.
+
+The full list of events emitted by FunWithFlags are documented in the [FunWithFlags.Telemetry](https://hexdocs.pm/fun_with_flags/FunWithFlags.Telemetry.html) module.
 
 ## Application Start Behaviour
 

lib/fun_with_flags.ex

@@ -469,7 +469,7 @@ defmodule FunWithFlags do
   """
   @spec all_flag_names() :: {:ok, [atom]} | {:error, any}
   def all_flag_names do
-    Config.persistence_adapter().all_flag_names()
+    @store.all_flag_names()
   end
 
   @doc """
@@ -483,7 +483,7 @@ defmodule FunWithFlags do
   """
   @spec all_flags() :: {:ok, [FunWithFlags.Flag.t]} | {:error, any}
   def all_flags do
-    Config.persistence_adapter().all_flags()
+    @store.all_flags()
   end
 
 
@@ -498,7 +498,11 @@ defmodule FunWithFlags do
     case all_flag_names() do
       {:ok, names} ->
         if name in names do
-          case Config.persistence_adapter().get(name) do
+          result =
+            Config.persistence_adapter().get(name)
+            |> FunWithFlags.Telemetry.emit_persistence_event(:read, name, nil)
+
+          case result do
             {:ok, flag} -> flag
             error -> error
           end

lib/fun_with_flags/simple_store.ex

@@ -2,10 +2,15 @@ defmodule FunWithFlags.SimpleStore do
   @moduledoc false
 
   import FunWithFlags.Config, only: [persistence_adapter: 0]
+  alias FunWithFlags.Telemetry
 
   @spec lookup(atom) :: {:ok, FunWithFlags.Flag.t}
   def lookup(flag_name) do
-    case persistence_adapter().get(flag_name) do
+    result =
+      persistence_adapter().get(flag_name)
+      |> Telemetry.emit_persistence_event(:read, flag_name, nil)
+
+    case result do
       {:ok, flag} -> {:ok, flag}
       _ -> raise "Can't load feature flag"
     end
@@ -14,25 +19,30 @@ defmodule FunWithFlags.SimpleStore do
   @spec put(atom, FunWithFlags.Gate.t) :: {:ok, FunWithFlags.Flag.t} | {:error, any()}
   def put(flag_name, gate) do
     persistence_adapter().put(flag_name, gate)
+    |> Telemetry.emit_persistence_event(:write, flag_name, gate)
   end
 
   @spec delete(atom, FunWithFlags.Gate.t) :: {:ok, FunWithFlags.Flag.t} | {:error, any()}
   def delete(flag_name, gate) do
     persistence_adapter().delete(flag_name, gate)
+    |> Telemetry.emit_persistence_event(:delete_gate, flag_name, gate)
   end
 
   @spec delete(atom) :: {:ok, FunWithFlags.Flag.t} | {:error, any()}
   def delete(flag_name) do
     persistence_adapter().delete(flag_name)
+    |> Telemetry.emit_persistence_event(:delete_flag, flag_name, nil)
   end
 
   @spec all_flags() :: {:ok, [FunWithFlags.Flag.t]} | {:error, any()}
   def all_flags do
     persistence_adapter().all_flags()
+    |> Telemetry.emit_persistence_event(:read_all_flags, nil, nil)
   end
 
   @spec all_flag_names() :: {:ok, [atom]} | {:error, any()}
   def all_flag_names do
     persistence_adapter().all_flag_names()
+    |> Telemetry.emit_persistence_event(:read_all_flag_names, nil, nil)
   end
 end

lib/fun_with_flags/store.ex

@@ -3,7 +3,7 @@ defmodule FunWithFlags.Store do
 
   require Logger
   alias FunWithFlags.Store.Cache
-  alias FunWithFlags.{Config, Flag}
+  alias FunWithFlags.{Config, Flag, Telemetry}
 
   import FunWithFlags.Config, only: [persistence_adapter: 0]
 
@@ -15,9 +15,11 @@ defmodule FunWithFlags.Store do
       {:miss, reason, stale_value_or_nil} ->
         case persistence_adapter().get(flag_name) do
           {:ok, flag} ->
+            Telemetry.emit_persistence_event({:ok, nil}, :read, flag_name, nil)
             Cache.put(flag)
             {:ok, flag}
-          {:error, _reason} ->
+          err = {:error, _reason} ->
+            Telemetry.emit_persistence_event(err, :read, flag_name, nil)
             try_to_use_the_cached_value(reason, stale_value_or_nil, flag_name)
         end
     end
@@ -37,6 +39,7 @@ defmodule FunWithFlags.Store do
   def put(flag_name, gate) do
     flag_name
     |> persistence_adapter().put(gate)
+    |> Telemetry.emit_persistence_event(:write, flag_name, gate)
     |> publish_change()
     |> cache_persistence_result()
   end
@@ -46,6 +49,7 @@ defmodule FunWithFlags.Store do
   def delete(flag_name, gate) do
     flag_name
     |> persistence_adapter().delete(gate)
+    |> Telemetry.emit_persistence_event(:delete_gate, flag_name, gate)
     |> publish_change()
     |> cache_persistence_result()
   end
@@ -55,6 +59,7 @@ defmodule FunWithFlags.Store do
   def delete(flag_name) do
     flag_name
     |> persistence_adapter().delete()
+    |> Telemetry.emit_persistence_event(:delete_flag, flag_name, nil)
     |> publish_change()
     |> cache_persistence_result()
   end
@@ -65,19 +70,22 @@ defmodule FunWithFlags.Store do
     Logger.debug fn -> "FunWithFlags: reloading cached flag '#{flag_name}' from storage " end
     flag_name
     |> persistence_adapter().get()
+    |> Telemetry.emit_persistence_event(:reload, flag_name, nil)
     |> cache_persistence_result()
   end
 
 
   @spec all_flags() :: {:ok, [FunWithFlags.Flag.t]} | {:error, any()}
   def all_flags do
     persistence_adapter().all_flags()
+    |> Telemetry.emit_persistence_event(:read_all_flags, nil, nil)
   end
 
 
   @spec all_flag_names() :: {:ok, [atom]} | {:error, any()}
   def all_flag_names do
     persistence_adapter().all_flag_names()
+    |> Telemetry.emit_persistence_event(:read_all_flag_names, nil, nil)
   end
 
   defp cache_persistence_result(result = {:ok, flag}) do

lib/fun_with_flags/telemetry.ex

@@ -0,0 +1,174 @@
+defmodule FunWithFlags.Telemetry do
+  @moduledoc """
+  Telemetry events for FunWithFlags.
+
+  This module centralizes the emission of all [Telemetry](https://hexdocs.pm/telemetry/readme.html)
+  events for the package.
+
+  ## Events
+
+  The common prefix for all events is `:fun_with_flags`, followed by a logical
+  scope (e.g. `:persistence`) and the event name.
+
+  Events are simple "point in time" events rather than span events (that is,
+  there is no distinct `:start` and `:stop` events with a duration measurement).
+
+  ### Persistence
+
+  Events for CRUD operations on the persistent datastore.
+
+  All events contain the same measurement:
+  * `system_time` (integer), which is the current system time in the
+    `:native` time unit. See `:erlang.system_time/0`.
+
+  Events:
+
+  * `[:fun_with_flags, :persistence, :read]`, emitted when a flag is read from
+    the DB. Crucially, this event is not emitted when the cache is enabled and
+    there is a cache hit, and it's emitted only when retrieving a flag reads
+    from the persistent datastore. Therefore, when the cache is disabled, this
+    event is always emitted every time a flag is queried.
+
+    Metadata:
+    * `flag_name` (string), the name of the flag being read.
+
+  * `[:fun_with_flags, :persistence, :read_all_flags]`, emitted when all flags
+    are read from the DB. No extra metadata.
+
+  * `[:fun_with_flags, :persistence, :read_all_flag_names]`, emitted when all
+    flags names are read from the DB. No extra metadata.
+
+  * `[:fun_with_flags, :persistence, :write]`, emitted when writing a flag to
+    the DB. In practive, what is written is one of the gates of the flag, which
+    is always upserted.
+
+    Metadata:
+    * `flag_name` (string), the name of the flag being written.
+    * `gate` (`FunWithFlags.Gate`), the gate being upserted.
+
+  * `[:fun_with_flags, :persistence, :delete_flag]`, emitted when an entire flag
+    is deleted from the DB.
+
+    Metadata:
+    * `flag_name` (string), the name of the flag being deleted.
+
+  * `[:fun_with_flags, :persistence, :delete_gate]`, emitted when one of the flag's
+    gates is deleted from the DB.
+
+    Metadata:
+    * `flag_name` (string), the name of the flag whose gate is being deleted.
+    * `gate` (`FunWithFlags.Gate`), the gate being deleted.
+
+  * `[:fun_with_flags, :persistence, :reload]`, emitted when a flag is reloaded
+    from the DB. This typically happens when the node has received a change
+    notification for a flag, which results in the cache being invalidated and
+    the flag being reloaded from the DB.
+
+    Metadata:
+    * `flag_name` (string), the name of the flag being reloaded.
+
+  * `[:fun_with_flags, :persistence, :error]`, emitted for erorrs in any of the
+    above operations.
+
+    Metadata:
+    * `error` (any), the error that occurred. This is typically a string or any
+      appropriate error term returned by the underlying persistence adapters.
+    * `original_event` (atom), the name of the original event that failed, e.g.
+      `:read`, `:write`, `:delete_gate`, etc.
+    * `flag_name` (string), the name of the flag being operated on, if supported
+      by the original event.
+    * `gate` (`FunWithFlags.Gate`), the gate being operated on, if supported by
+      the original event.
+  """
+
+  require Logger
+
+  @typedoc false
+  @type pipelining_value :: {:ok, any()} | {:error, any()}
+
+  # Receive the flag name as an explicit parameter rather than pattern matching
+  # it from the `{:ok, _}` tuple, because:
+  #
+  # * That tuple is only available on success, and it's therefore not available
+  #   when pipelining on an error.
+  # * It makes it possible to use this function even when the :ok result does
+  #   not contain a flag.
+  #
+  @doc false
+  @spec emit_persistence_event(
+    pipelining_value(),
+    event_name :: atom(),
+    flag_name :: (atom() | nil),
+    gate :: (FunWithFlags.Gate.t | nil)
+  ) :: pipelining_value()
+  def emit_persistence_event(result = {:ok, _}, event_name, flag_name, gate) do
+    metadata = %{
+      flag_name: flag_name,
+      gate: gate,
+    }
+
+    do_send_event([:fun_with_flags, :persistence, event_name], metadata)
+    result
+  end
+
+  def emit_persistence_event(result = {:error, reason}, event_name, flag_name, gate) do
+    metadata = %{
+      flag_name: flag_name,
+      gate: gate,
+      error: reason,
+      original_event: event_name
+    }
+
+    do_send_event([:fun_with_flags, :persistence, :error], metadata)
+    result
+  end
+
+  @doc false
+  @spec do_send_event([atom], :telemetry.event_metadata()) :: :ok
+  def do_send_event(event_name, metadata) do
+    measurements = %{
+      system_time: :erlang.system_time()
+    }
+
+    Logger.debug(fn ->
+      "Telemetry event: #{inspect(event_name)}, metadata: #{inspect(metadata)}, measurements: #{inspect(measurements)}"
+    end)
+
+    :telemetry.execute(event_name, measurements, metadata)
+  end
+
+
+  @doc """
+  Attach a debug handler to FunWithFlags telemetry events.
+
+  Attach a Telemetry handler that logs all events at the `:alert` level.
+  It uses the `:alert` level rather than `:debug` or `:info` simply to make it
+  more convenient to eyeball these logs and to print them while running the tests.
+  """
+  @spec attach_debug_handler() :: :ok | {:error, :already_exists}
+  def attach_debug_handler do
+    events = [
+      [:fun_with_flags, :persistence, :read],
+      [:fun_with_flags, :persistence, :read_all_flags],
+      [:fun_with_flags, :persistence, :read_all_flag_names],
+      [:fun_with_flags, :persistence, :write],
+      [:fun_with_flags, :persistence, :delete_flag],
+      [:fun_with_flags, :persistence, :delete_gate],
+      [:fun_with_flags, :persistence, :reload],
+      [:fun_with_flags, :persistence, :error],
+    ]
+
+    :telemetry.attach_many("local-debug-handler", events, &__MODULE__.debug_event_handler/4, %{})
+  end
+
+  @doc false
+  def debug_event_handler([:fun_with_flags, :persistence, event], %{system_time: system_time}, metadata, _config) do
+    dt = DateTime.from_unix!(system_time, :native) |> DateTime.to_iso8601()
+
+    Logger.alert(fn ->
+      "FunWithFlags telemetry event: #{event}, system_time: #{dt}, metadata: #{inspect(metadata)}"
+    end)
+
+    :ok
+  end
+end

mix.exs

@@ -74,6 +74,7 @@ defmodule FunWithFlags.Mixfile do
       {:postgrex, "~> 0.16", optional: true, only: [:dev, :test]},
       {:myxql, "~> 0.2", optional: true, only: [:dev, :test]},
       {:phoenix_pubsub, "~> 2.0", optional: true},
+      {:telemetry, "~> 1.3"},
 
       {:mock, "~> 0.3", only: :test},