From 6f88bc9c617e8a20a59a880b8e654c0879585c33 Mon Sep 17 00:00:00 2001 From: Zach Daniel Date: Wed, 18 Sep 2024 22:34:04 -0400 Subject: [PATCH] improvement: add span & telemetry events for running calculations --- documentation/topics/advanced/monitoring.md | 2 + lib/ash/actions/read/calculations.ex | 77 +++++++++++++++++++-- lib/ash/tracer/tracer.ex | 1 + test/tracer_test.exs | 69 ++++++++++++++++++ 4 files changed, 144 insertions(+), 5 deletions(-) diff --git a/documentation/topics/advanced/monitoring.md b/documentation/topics/advanced/monitoring.md index a69f2bc5..777546e7 100644 --- a/documentation/topics/advanced/monitoring.md +++ b/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 diff --git a/lib/ash/actions/read/calculations.ex b/lib/ash/actions/read/calculations.ex index bd075584..e781e174 100644 --- a/lib/ash/actions/read/calculations.ex +++ b/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) diff --git a/lib/ash/tracer/tracer.ex b/lib/ash/tracer/tracer.ex index 37bbb08d..6dc2d174 100644 --- a/lib/ash/tracer/tracer.ex +++ b/lib/ash/tracer/tracer.ex @@ -8,6 +8,7 @@ defmodule Ash.Tracer do | :changeset | :query | :flow + | :calculate | :request_step | :change | :validation diff --git a/test/tracer_test.exs b/test/tracer_test.exs index 965c3a5f..7bc7da56 100644 --- a/test/tracer_test.exs +++ b/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