improvement: add span & telemetry events for running calculations

documentation/topics/advanced/monitoring.md

@@ -26,6 +26,7 @@ Note the mention of `:start` and `:stop` suffixes. The event below `[:ash, (doma
 - `[:ash, :query]` - A query being processed for an action, with `Ash.Query.for_read`. Use `resource_short_name` metadata to break down measurements.
 - `[:ash, :validation]` - A validation being run on a changeset. Use `resource_short_name` and `validation` metadata to break down measurements.
 - `[:ash, :change]` - A change being run on a changeset. Use `resource_short_name` and `change` metadata to break down measurements.
+- `[:ash, :calculate]` - A calculation being computed in the app. Use `resource_short_name` and `calculation` metadata to break down measurements.
 - `[:ash, :before_action]` - A before_action being run on a changeset. Use `resource_short_name` to break down measurements.
 - `[:ash, :after_action]` - An after_action being run on a changeset. Use `resource_short_name` to break down measurements.
 - `[:ash, :preparation]` - A preparation being run on a changeset. Use `resource_short_name` and `preparation` metadata to break down measurements.
@@ -67,6 +68,7 @@ These are the list of trace types.
 - :changeset
 - :validation
 - :change
+- :calculate
 - :before_transaction
 - :before_action
 - :after_transaction

lib/ash/actions/read/calculations.ex

@@ -1,6 +1,8 @@
 defmodule Ash.Actions.Read.Calculations do
   @moduledoc false
 
+  require Ash.Tracer
+
   def calculate(resource_or_record, calculation, opts) do
     {resource, record} =
       case resource_or_record do
@@ -118,7 +120,12 @@ defmodule Ash.Actions.Read.Calculations do
 
                     {:error, error} ->
                       if module.has_calculate?() do
-                        case module.calculate([record], calc_opts, calc_context) do
+                        case with_trace(
+                               fn -> module.calculate([record], calc_opts, calc_context) end,
+                               resource,
+                               calculation,
+                               opts
+                             ) do
                           [result] ->
                             result
 
@@ -162,7 +169,12 @@ defmodule Ash.Actions.Read.Calculations do
         end
       else
         if module.has_calculate?() do
-          case module.calculate([record], calc_opts, calc_context) do
+          case with_trace(
+                 fn -> module.calculate([record], calc_opts, calc_context) end,
+                 resource,
+                 calculation,
+                 opts
+               ) do
             [result] ->
               {:ok, result}
 
@@ -425,7 +437,14 @@ defmodule Ash.Actions.Read.Calculations do
 
     records
     |> apply_transient_calculation_values(calculation, ash_query, [])
-    |> run_calculate(calculation.module, opts, context)
+    |> run_calculate(
+      calculation.module,
+      opts,
+      context,
+      ash_query.resource,
+      calculation.name,
+      Ash.Context.to_opts(context)
+    )
     |> case do
       :unknown ->
         Enum.map(records, fn _ ->
@@ -437,8 +456,13 @@ defmodule Ash.Actions.Read.Calculations do
     end
   end
 
-  defp run_calculate(records, module, opts, context) do
-    module.calculate(records, opts, context)
+  defp run_calculate(records, module, opts, context, resource, calculation_name, run_opts) do
+    with_trace(
+      fn -> module.calculate(records, opts, context) end,
+      resource,
+      calculation_name,
+      run_opts
+    )
   rescue
     e ->
       if Enum.any?(__STACKTRACE__, fn {m, f, a, meta} ->
@@ -456,6 +480,49 @@ defmodule Ash.Actions.Read.Calculations do
       end
   end
 
+  defp with_trace(callback, resource, calculation_name, opts) do
+    short_name = Ash.Resource.Info.short_name(resource)
+    tracer = opts[:tracer]
+
+    Ash.Tracer.span :calculate,
+                    fn ->
+                      calculation_name =
+                        if is_atom(calculation_name) do
+                          to_string(calculation_name)
+                        else
+                          String.replace(to_string(calculation_name), ~r/[^a-zA-Z0-9_\-?]/, "")
+                        end
+
+                      "#{short_name}:calculate:#{calculation_name}"
+                    end,
+                    tracer do
+      metadata = fn ->
+        calculation_name =
+          if is_atom(calculation_name) do
+            to_string(calculation_name)
+          else
+            String.replace(to_string(calculation_name), ~r/[^a-zA-Z0-9_\-?]/, "")
+          end
+
+        %{
+          resource: resource,
+          resource_short_name: short_name,
+          calculation: calculation_name,
+          actor: opts[:actor],
+          tenant: opts[:tenant],
+          authorize?: opts[:authorize?]
+        }
+      end
+
+      Ash.Tracer.telemetry_span [:ash, :calculate],
+                                metadata,
+                                skip?: !!opts[:initial_data] do
+        Ash.Tracer.set_metadata(tracer, :action, metadata)
+        callback.()
+      end
+    end
+  end
+
   defp apply_transient_calculation_values(records, calculation, ash_query, path) do
     ash_query
     |> get_all_rewrites(calculation, path)

lib/ash/tracer/tracer.ex

@@ -8,6 +8,7 @@ defmodule Ash.Tracer do
           | :changeset
           | :query
           | :flow
+          | :calculate
           | :request_step
           | :change
           | :validation

test/tracer_test.exs

@@ -28,6 +28,14 @@ defmodule Ash.Test.TracerTest.AsyncLoadTest do
       end
     end
 
+    calculations do
+      calculate :name_length, :integer, fn records, _ ->
+        Enum.map(records, fn record ->
+          String.length(record.name)
+        end)
+      end
+    end
+
     relationships do
       has_many :posts, Ash.Test.TracerTest.AsyncLoadTest.Post,
         destination_attribute: :author_id,
@@ -124,6 +132,7 @@ defmodule Ash.Test.TracerTest.AsyncLoadTest do
         [:ash, :domain, :create],
         [:ash, :domain, :destroy],
         [:ash, :domain, :update],
+        [:ash, :calculate],
         [:ash, :flow]
       ]
       |> Enum.flat_map(fn list ->
@@ -242,4 +251,64 @@ defmodule Ash.Test.TracerTest.AsyncLoadTest do
 
     assert Enum.any?(spans, &(&1.name == "domain:author.read"))
   end
+
+  test "a read with calculation loads calls the tracer" do
+    Ash.Changeset.for_create(Author, :create, %{name: "anc"})
+    |> Ash.create!()
+
+    assert_receive {:telemetry,
+                    {[:ash, :domain, :create, :start], %{system_time: _},
+                     %{resource_short_name: :author}, _}}
+
+    assert_receive {:telemetry,
+                    {[:ash, :domain, :create, :stop], %{duration: _},
+                     %{resource_short_name: :author}, _}}
+
+    Author
+    |> Ash.Query.load(:name_length)
+    |> Ash.read!(tracer: Ash.Tracer.Simple)
+
+    assert [
+             %Ash.Tracer.Simple.Span{
+               type: :action,
+               name: "domain:author.read",
+               metadata: %{
+                 action: :read,
+                 resource: Ash.Test.TracerTest.AsyncLoadTest.Author
+               },
+               spans: [
+                 %Ash.Tracer.Simple.Span{
+                   name: "author:calculate:name_length",
+                   type: :calculate,
+                   metadata: %{
+                     resource: Ash.Test.TracerTest.AsyncLoadTest.Author,
+                     resource_short_name: :author,
+                     calculation: "name_length",
+                     authorize?: true
+                   },
+                   spans: []
+                 }
+                 | _
+               ]
+             }
+           ] = Ash.Tracer.Simple.gather_spans()
+
+    assert_receive {:telemetry,
+                    {[:ash, :domain, :read, :start], %{system_time: _},
+                     %{resource_short_name: :author}, []}}
+
+    assert_receive {:telemetry,
+                    {[:ash, :domain, :read, :stop], %{duration: _, system_time: _},
+                     %{resource_short_name: :author}, []}}
+
+    assert_receive {:telemetry,
+                    {[:ash, :calculate, :start], %{system_time: _},
+                     %{resource_short_name: :author, calculation: "name_length"}, []}}
+
+    assert_receive {:telemetry,
+                    {[:ash, :calculate, :stop], %{duration: _, system_time: _},
+                     %{resource_short_name: :author, calculation: "name_length"}, []}}
+
+    refute_receive {:telemetry, _}
+  end
 end