From 4fcfcb27d22103ba78ba45da60c180be76e48382 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 5 Dec 2024 16:07:32 +0100 Subject: [PATCH 01/46] Telemetry refresh and element/pipeline telemetry testing for init and terminate (#905) --- config/config.exs | 6 ++ lib/membrane/core/bin.ex | 3 +- lib/membrane/core/element.ex | 4 +- lib/membrane/core/pipeline.ex | 4 +- lib/membrane/core/telemetry.ex | 18 +---- test/membrane/telemetry_test.exs | 127 +++++++++++++++++++++++++++++++ 6 files changed, 144 insertions(+), 18 deletions(-) create mode 100644 test/membrane/telemetry_test.exs diff --git a/config/config.exs b/config/config.exs index 6e62d2427..3f582015e 100644 --- a/config/config.exs +++ b/config/config.exs @@ -2,4 +2,10 @@ import Config if config_env() == :test do config :junit_formatter, include_filename?: true + + config :membrane_core, :telemetry_flags, [ + :links, + :inits_and_terminates, + # {:metrics, [:buffer, :bitrate, :queue_len, :stream_format, :event, :store, :take_and_demand]} + ] end diff --git a/lib/membrane/core/bin.ex b/lib/membrane/core/bin.ex index 61b6862b0..f6ec9f8e7 100644 --- a/lib/membrane/core/bin.ex +++ b/lib/membrane/core/bin.ex @@ -128,7 +128,8 @@ defmodule Membrane.Core.Bin do SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) Telemetry.report_init(:bin) - ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:bin) end) + path = Membrane.ComponentPath.get_formatted() + ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:bin, path) end) state = %State{ diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index 0c639dacc..e1db255f2 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -119,8 +119,8 @@ defmodule Membrane.Core.Element do SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) Telemetry.report_init(:element) - - ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:element) end) + path = Membrane.ComponentPath.get_formatted() + ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:element, path) end) self_pid = self() diff --git a/lib/membrane/core/pipeline.ex b/lib/membrane/core/pipeline.ex index 6f9fc95db..bee98636f 100644 --- a/lib/membrane/core/pipeline.ex +++ b/lib/membrane/core/pipeline.ex @@ -45,8 +45,10 @@ defmodule Membrane.Core.Pipeline do Telemetry.report_init(:pipeline) + path = Membrane.ComponentPath.get_formatted() + ResourceGuard.register(resource_guard, fn -> - Telemetry.report_terminate(:pipeline) + Telemetry.report_terminate(:pipeline, path) end) {:ok, clock_proxy} = diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index ff182ea7b..c39fbad5e 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -103,10 +103,7 @@ defmodule Membrane.Core.Telemetry do Reports a pipeline/bin/element initialization. """ defmacro report_init(type) when type in [:pipeline, :bin, :element] do - event = - quote do - [:membrane, unquote(type), :init] - end + event = [:membrane, type, :init] value = quote do @@ -129,16 +126,9 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports a pipeline/bin/element termination. """ - defmacro report_terminate(type) when type in [:pipeline, :bin, :element] do - event = - quote do - [:membrane, unquote(type), :terminate] - end - - value = - quote do - %{path: ComponentPath.get_formatted()} - end + defmacro report_terminate(type, path) when type in [:pipeline, :bin, :element] do + event = [:membrane, type, :terminate] + value = quote do %{path: unquote(path)} end report_event( event, diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs new file mode 100644 index 000000000..3a1aaa451 --- /dev/null +++ b/test/membrane/telemetry_test.exs @@ -0,0 +1,127 @@ +defmodule Membrane.TelemetryTest do + use ExUnit.Case, async: true + + import Membrane.ChildrenSpec + + require Logger + alias Membrane.Testing + + defmodule TestFilter do + use Membrane.Filter + + def_input_pad :input, flow_control: :manual, accepted_format: _any, demand_unit: :buffers + + def_output_pad :output, flow_control: :manual, accepted_format: _any + + def_options target: [spec: pid()] + + @impl true + def handle_init(_ctx, opts), do: {[], opts} + + @impl true + def handle_playing(_ctx, state) do + {[], state} + end + + @impl true + def handle_start_of_stream(_pad, _context, state) do + {[], state} + end + + @impl true + def handle_end_of_stream(_pad, _context, state) do + {[], state} + end + + @impl true + def handle_event(_pad, _event, _context, state) do + {[], state} + end + + @impl true + def handle_demand(_pad, size, _unit, _context, state) do + {[demand: {:input, size}], state} + end + + @impl true + def handle_buffer(_pad, _buffer, _context, state), do: {[], state} + end + + defmodule TelemetryListener do + def handle_event(name, value, metadata, %{dest: pid, ref: ref}) do + pid |> send({ref, :telemetry_ack, {name, value, metadata}}) + end + end + + setup do + ref = make_ref() + + links = [ + child(:source, %Testing.Source{output: [~c"a", ~c"b", ~c"c"]}) + |> child(:filter, %TestFilter{target: self()}) + |> child(:sink, Testing.Sink) + ] + + [links: links, ref: ref] + end + + describe "Telemetry attaching" do + test "handles init events", %{ref: ref, links: links} do + :ok = + [ + [:membrane, :element, :init], + [:membrane, :pipeline, :init] + ] + |> attach_to_events(ref) + + Testing.Pipeline.start_link_supervised!(spec: links) + + assert_receive({^ref, :telemetry_ack, {[:membrane, :pipeline, :init], _, _}}, 1000) + assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :init], e1, _}}, 1000) + assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :init], e2, _}}, 1000) + assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :init], e3, _}}, 1000) + + elements = + [e1, e2, e3] + |> Enum.map(&extract_type/1) + |> Enum.sort() + + assert ^elements = ["filter", "sink", "source"] + end + + test "handles terminate events", %{ref: ref, links: links} do + :ok = + [ + [:membrane, :element, :terminate], + [:membrane, :pipeline, :terminate] + ] + |> attach_to_events(ref) + + pid = Testing.Pipeline.start_link_supervised!(spec: links) + :ok = Testing.Pipeline.terminate(pid) + + assert_receive({^ref, :telemetry_ack, {[:membrane, :pipeline, :terminate], _, _}}, 1000) + assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :terminate], e1, _}}, 1000) + assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :terminate], e2, _}}, 1000) + assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :terminate], e3, _}}, 1000) + + elements = + [e1, e2, e3] + |> Enum.map(&extract_type/1) + |> Enum.sort() + + assert ^elements = ["filter", "sink", "source"] + end + end + + defp attach_to_events(events, ref) do + :telemetry.attach_many(ref, events, &TelemetryListener.handle_event/4, %{ + dest: self(), + ref: ref + }) + end + + defp extract_type(%{path: pid_type}) do + String.split(pid_type, ":") |> List.last() + end +end From 328d30af90a0e9368a40a2a41be999878c38ae06 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 5 Dec 2024 16:31:09 +0100 Subject: [PATCH 02/46] Tests async false. Telemetry captured other tests' processes --- test/membrane/telemetry_test.exs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 3a1aaa451..e5a616323 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -1,5 +1,5 @@ defmodule Membrane.TelemetryTest do - use ExUnit.Case, async: true + use ExUnit.Case, async: false import Membrane.ChildrenSpec From e599fcb3c0b6f06c6772b94f34f37b42efdfbb25 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 5 Dec 2024 16:34:30 +0100 Subject: [PATCH 03/46] Unnecessary code trim --- test/membrane/telemetry_test.exs | 23 ----------------------- 1 file changed, 23 deletions(-) diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index e5a616323..587bf6d38 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -15,29 +15,6 @@ defmodule Membrane.TelemetryTest do def_options target: [spec: pid()] - @impl true - def handle_init(_ctx, opts), do: {[], opts} - - @impl true - def handle_playing(_ctx, state) do - {[], state} - end - - @impl true - def handle_start_of_stream(_pad, _context, state) do - {[], state} - end - - @impl true - def handle_end_of_stream(_pad, _context, state) do - {[], state} - end - - @impl true - def handle_event(_pad, _event, _context, state) do - {[], state} - end - @impl true def handle_demand(_pad, size, _unit, _context, state) do {[demand: {:input, size}], state} From e60b127ecdeb9da91cc3aee28665d93d190ac186 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 6 Dec 2024 15:32:06 +0100 Subject: [PATCH 04/46] Telemetry spans for init and setup using :telemetry.span --- config/config.exs | 3 +- lib/membrane/core/bin.ex | 5 +- lib/membrane/core/element.ex | 15 ++++-- lib/membrane/core/pipeline.ex | 6 +-- lib/membrane/core/telemetry.ex | 92 ++++++++++++++++++++------------ lib/membrane/telemetry.ex | 7 +-- test/membrane/telemetry_test.exs | 82 +++++++++++----------------- test/test_helper.exs | 1 - 8 files changed, 112 insertions(+), 99 deletions(-) diff --git a/config/config.exs b/config/config.exs index 3f582015e..4e601b5af 100644 --- a/config/config.exs +++ b/config/config.exs @@ -3,9 +3,10 @@ import Config if config_env() == :test do config :junit_formatter, include_filename?: true - config :membrane_core, :telemetry_flags, [ + config :membrane_core, :telemetry_flags, include: [ :links, :inits_and_terminates, + :spans # {:metrics, [:buffer, :bitrate, :queue_len, :stream_format, :event, :store, :take_and_demand]} ] end diff --git a/lib/membrane/core/bin.ex b/lib/membrane/core/bin.ex index f6ec9f8e7..c5e391c6e 100644 --- a/lib/membrane/core/bin.ex +++ b/lib/membrane/core/bin.ex @@ -96,7 +96,9 @@ defmodule Membrane.Core.Bin do {:continue, :setup}} def init(options) do Utils.log_on_error do - do_init(options) + Telemetry.report_span :bin, :init do + do_init(options) + end end end @@ -127,7 +129,6 @@ defmodule Membrane.Core.Bin do {:ok, resource_guard} = SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) - Telemetry.report_init(:bin) path = Membrane.ComponentPath.get_formatted() ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:bin, path) end) diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index e1db255f2..b9817e1ab 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -118,8 +118,7 @@ defmodule Membrane.Core.Element do {:ok, resource_guard} = SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) - Telemetry.report_init(:element) - path = Membrane.ComponentPath.get_formatted() + path = Membrane.ComponentPath.get() ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:element, path) end) self_pid = self() @@ -157,15 +156,21 @@ defmodule Membrane.Core.Element do } |> PadSpecHandler.init_pads() - state = LifecycleController.handle_init(options.user_options, state) + state = + Telemetry.report_span :element, :init do + LifecycleController.handle_init(options.user_options, state) + end + {:ok, state, {:continue, :setup}} end @impl GenServer def handle_continue(:setup, state) do Utils.log_on_error do - state = LifecycleController.handle_setup(state) - {:noreply, state} + Telemetry.report_span :element, :setup do + state = LifecycleController.handle_setup(state) + {:noreply, state} + end end end diff --git a/lib/membrane/core/pipeline.ex b/lib/membrane/core/pipeline.ex index bee98636f..c764b9dc8 100644 --- a/lib/membrane/core/pipeline.ex +++ b/lib/membrane/core/pipeline.ex @@ -25,7 +25,9 @@ defmodule Membrane.Core.Pipeline do @impl GenServer def init(params) do Utils.log_on_error do - do_init(params) + Telemetry.report_span :pipeline, :init do + do_init(params) + end end end @@ -43,8 +45,6 @@ defmodule Membrane.Core.Pipeline do {:ok, resource_guard} = SubprocessSupervisor.start_utility(subprocess_supervisor, {ResourceGuard, self()}) - Telemetry.report_init(:pipeline) - path = Membrane.ComponentPath.get_formatted() ResourceGuard.register(resource_guard, fn -> diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index c39fbad5e..4c4fb3108 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -1,16 +1,23 @@ defmodule Membrane.Core.Telemetry do @moduledoc false + require Logger alias Membrane.ComponentPath require Membrane.Pad + defp warn(warning) do + IO.warn(warning, Macro.Env.stacktrace(__ENV__)) + end + + @possible_flags [:all, :metrics, :bitrate, :links, :inits_and_terminates, :spans] @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) + @invalid_config_warning "`config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]]" @doc """ Reports metrics such as input buffer's size inside functions, incoming events and received stream format. """ - defmacro report_metric(metric, value, log_tag \\ nil) do + defmacro report_metric(metric, value, meta \\ quote(do: %{})) do event = quote do [:membrane, :metric, :value] @@ -19,16 +26,17 @@ defmodule Membrane.Core.Telemetry do value = quote do %{ - component_path: ComponentPath.get_formatted() <> "/" <> (unquote(log_tag) || ""), + component_path: ComponentPath.get(), metric: Atom.to_string(unquote(metric)), - value: unquote(value) + value: unquote(value), + meta: unquote(meta) } end report_event( event, value, - Keyword.get(@telemetry_flags, :metrics, []) |> Enum.find(&(&1 == metric)) != nil + Keyword.get(@telemetry_flags, :metrics, []) |> Enum.member?(metric) ) end @@ -45,7 +53,7 @@ defmodule Membrane.Core.Telemetry do value = quote do %{ - component_path: ComponentPath.get_formatted() <> "/", + component_path: ComponentPath.get(), metric: "bitrate", value: 8 * @@ -60,7 +68,7 @@ defmodule Membrane.Core.Telemetry do report_event( event, value, - Keyword.get(@telemetry_flags, :metrics, []) |> Enum.find(&(&1 == :bitrate)) != nil + Keyword.get(@telemetry_flags, :metrics, []) |> Enum.member?(:bitrate) ) end @@ -96,31 +104,29 @@ defmodule Membrane.Core.Telemetry do } end - report_event(event, value, Enum.find(@telemetry_flags, &(&1 == :links)) != nil) + report_event(event, value, Enum.member?(@telemetry_flags, :links)) end - @doc """ - Reports a pipeline/bin/element initialization. - """ - defmacro report_init(type) when type in [:pipeline, :bin, :element] do - event = [:membrane, type, :init] - - value = - quote do - %{path: ComponentPath.get_formatted()} - end + defmacro report_span(type, subtype, do: block) do + enabled = flag_enabled?(:inits_and_terminates) - metadata = + if enabled do quote do - %{log_metadata: Logger.metadata()} + :telemetry.span( + [:membrane, unquote(type), unquote(subtype)], + %{ + log_metadata: Logger.metadata(), + path: ComponentPath.get() + }, + fn -> + unquote(block) + |> then(&{&1, %{log_metadata: Logger.metadata(), path: ComponentPath.get()}}) + end + ) end - - report_event( - event, - value, - Enum.find(@telemetry_flags, &(&1 == :inits_and_terminates)) != nil, - metadata - ) + else + block + end end @doc """ @@ -128,18 +134,18 @@ defmodule Membrane.Core.Telemetry do """ defmacro report_terminate(type, path) when type in [:pipeline, :bin, :element] do event = [:membrane, type, :terminate] - value = quote do %{path: unquote(path)} end - report_event( - event, - value, - Enum.find(@telemetry_flags, &(&1 == :inits_and_terminates)) != nil - ) + value = + quote do + %{path: unquote(path)} + end + + report_event(event, value, Enum.member?(@telemetry_flags, :inits_and_terminates)) end # Conditional event reporting of telemetry events - defp report_event(event_name, measurement, enable, metadata \\ nil) do - if enable do + defp report_event(event_name, measurement, enabled, metadata \\ nil) do + if enabled do quote do :telemetry.execute( unquote(event_name), @@ -160,4 +166,22 @@ defmodule Membrane.Core.Telemetry do end end end + + defp flag_enabled?(flag) do + Enum.member?(get_flags(@telemetry_flags), flag) + end + + defp get_flags(:all), do: @possible_flags + defp get_flags(include: _, exclude: _), do: warn(@invalid_config_warning) + defp get_flags(exclude: exclude), do: @possible_flags -- exclude + + defp get_flags(include: include) do + case include -- @possible_flags do + [] -> + include + + incorrect_flags -> + warn("#{inspect(incorrect_flags)} are not correct Membrane telemetry flags") + end + end end diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 6000b6f05..129c952a7 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -61,15 +61,16 @@ defmodule Membrane.Telemetry do * `:take_and_demand` - reports the current size of a input buffer when taking buffers and making a new demand """ - @type event_name :: [atom(), ...] - + @type instrument :: :element | :bin | :pipeline + @type event :: :init | :terminate | :setup | :playback_change + @type event_name :: [atom() | list(atom())] @typedoc """ * component_path - element's or bin's path * metric - metric's name * value - metric's value """ @type metric_event_value :: %{ - component_path: String.t(), + component_path: Membrane.ComponentPath.path(), metric: String.t(), value: integer() } diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 587bf6d38..34e0bdfab 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -1,6 +1,5 @@ defmodule Membrane.TelemetryTest do use ExUnit.Case, async: false - import Membrane.ChildrenSpec require Logger @@ -10,9 +9,7 @@ defmodule Membrane.TelemetryTest do use Membrane.Filter def_input_pad :input, flow_control: :manual, accepted_format: _any, demand_unit: :buffers - def_output_pad :output, flow_control: :manual, accepted_format: _any - def_options target: [spec: pid()] @impl true @@ -42,63 +39,48 @@ defmodule Membrane.TelemetryTest do [links: links, ref: ref] end - describe "Telemetry attaching" do - test "handles init events", %{ref: ref, links: links} do - :ok = - [ - [:membrane, :element, :init], - [:membrane, :pipeline, :init] - ] - |> attach_to_events(ref) + describe "Telemetry reports" do + @tag :telemetry - Testing.Pipeline.start_link_supervised!(spec: links) + @paths ~w[:filter :sink :source] + @events [:init, :setup] + @steps [:start, :stop] + + setup %{links: links} do + ref = make_ref() - assert_receive({^ref, :telemetry_ack, {[:membrane, :pipeline, :init], _, _}}, 1000) - assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :init], e1, _}}, 1000) - assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :init], e2, _}}, 1000) - assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :init], e3, _}}, 1000) + events = + for event <- @events, + step <- @steps do + [:membrane, :element, event, step] + end - elements = - [e1, e2, e3] - |> Enum.map(&extract_type/1) - |> Enum.sort() + :telemetry.attach_many(ref, events, &TelemetryListener.handle_event/4, %{ + dest: self(), + ref: ref + }) - assert ^elements = ["filter", "sink", "source"] + Testing.Pipeline.start_link_supervised!(spec: links) + [ref: ref] end - test "handles terminate events", %{ref: ref, links: links} do - :ok = - [ - [:membrane, :element, :terminate], - [:membrane, :pipeline, :terminate] - ] - |> attach_to_events(ref) + # Test each lifecycle step for each element type + for path <- @paths, + event <- @events do + test "#{path}/#{event}", %{ref: ref} do + path = unquote(path) + event = unquote(event) - pid = Testing.Pipeline.start_link_supervised!(spec: links) - :ok = Testing.Pipeline.terminate(pid) + assert_receive {^ref, :telemetry_ack, + {[:membrane, :element, ^event, :start], meta, %{path: [_, ^path]}}} - assert_receive({^ref, :telemetry_ack, {[:membrane, :pipeline, :terminate], _, _}}, 1000) - assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :terminate], e1, _}}, 1000) - assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :terminate], e2, _}}, 1000) - assert_receive({^ref, :telemetry_ack, {[:membrane, :element, :terminate], e3, _}}, 1000) + assert meta.system_time > 0 - elements = - [e1, e2, e3] - |> Enum.map(&extract_type/1) - |> Enum.sort() + assert_receive {^ref, :telemetry_ack, + {[:membrane, :element, ^event, :stop], meta, %{path: [_, ^path]}}} - assert ^elements = ["filter", "sink", "source"] + assert meta.duration > 0 + end end end - - defp attach_to_events(events, ref) do - :telemetry.attach_many(ref, events, &TelemetryListener.handle_event/4, %{ - dest: self(), - ref: ref - }) - end - - defp extract_type(%{path: pid_type}) do - String.split(pid_type, ":") |> List.last() - end end diff --git a/test/test_helper.exs b/test/test_helper.exs index 2f5b09483..10efabeb7 100644 --- a/test/test_helper.exs +++ b/test/test_helper.exs @@ -3,5 +3,4 @@ System.cmd("epmd", ["-daemon"]) Node.start(:"my_node@127.0.0.1", :longnames) ExUnit.configure(formatters: [ExUnit.CLIFormatter, JUnitFormatter]) -# ExUnit.start(exclude: [:long_running], assert_receive_timeout: 500) ExUnit.start(exclude: [:long_running], capture_log: true, assert_receive_timeout: 500) From 42f099e1e6ff9638ec9c2a34a34ad81923e98b57 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 12 Dec 2024 15:52:26 +0100 Subject: [PATCH 05/46] Telemetry for spans, metrics and events for elements and pipelines --- config/config.exs | 13 ++-- lib/membrane/core/bin.ex | 3 - lib/membrane/core/callback_handler.ex | 6 +- lib/membrane/core/element.ex | 3 - .../core/element/lifecycle_controller.ex | 18 +++-- .../manual_flow_controller/input_queue.ex | 4 +- lib/membrane/core/pipeline.ex | 12 ++-- lib/membrane/core/telemetry.ex | 69 ++++++------------- test/membrane/telemetry_test.exs | 62 ++++++++++++++--- 9 files changed, 101 insertions(+), 89 deletions(-) diff --git a/config/config.exs b/config/config.exs index 4e601b5af..2728a826b 100644 --- a/config/config.exs +++ b/config/config.exs @@ -3,10 +3,11 @@ import Config if config_env() == :test do config :junit_formatter, include_filename?: true - config :membrane_core, :telemetry_flags, include: [ - :links, - :inits_and_terminates, - :spans - # {:metrics, [:buffer, :bitrate, :queue_len, :stream_format, :event, :store, :take_and_demand]} - ] + config :membrane_core, :telemetry_flags, + include: [ + :init, + :setup, + :terminate, + :playing + ] end diff --git a/lib/membrane/core/bin.ex b/lib/membrane/core/bin.ex index c5e391c6e..7655dcacd 100644 --- a/lib/membrane/core/bin.ex +++ b/lib/membrane/core/bin.ex @@ -129,9 +129,6 @@ defmodule Membrane.Core.Bin do {:ok, resource_guard} = SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) - path = Membrane.ComponentPath.get_formatted() - ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:bin, path) end) - state = %State{ module: module, diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 731f2777a..c16a5303d 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -7,6 +7,8 @@ defmodule Membrane.Core.CallbackHandler do use Bunch + require Membrane.Core.Telemetry + alias Membrane.Core.Telemetry alias Membrane.CallbackError require Membrane.Logger @@ -136,7 +138,9 @@ defmodule Membrane.Core.CallbackHandler do callback_result = try do - apply(module, callback, args) + Telemetry.report_span :element, :terminate do + apply(module, callback, args) + end rescue e in UndefinedFunctionError -> _ignored = diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index b9817e1ab..6d1074079 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -118,9 +118,6 @@ defmodule Membrane.Core.Element do {:ok, resource_guard} = SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) - path = Membrane.ComponentPath.get() - ResourceGuard.register(resource_guard, fn -> Telemetry.report_terminate(:element, path) end) - self_pid = self() Stalker.register_metric_function(:message_queue_length, fn -> diff --git a/lib/membrane/core/element/lifecycle_controller.ex b/lib/membrane/core/element/lifecycle_controller.ex index 6f7c231cf..e91c7082e 100644 --- a/lib/membrane/core/element/lifecycle_controller.ex +++ b/lib/membrane/core/element/lifecycle_controller.ex @@ -6,6 +6,8 @@ defmodule Membrane.Core.Element.LifecycleController do use Bunch + require Membrane.Core.Telemetry + alias Membrane.Core.Telemetry alias Membrane.{Clock, Element, Sync} alias Membrane.Core.{CallbackHandler, Element, Message, SubprocessSupervisor} @@ -81,13 +83,15 @@ defmodule Membrane.Core.Element.LifecycleController do |> EffectiveFlowController.resolve_effective_flow_control() state = - CallbackHandler.exec_and_handle_callback( - :handle_playing, - ActionHandler, - %{context: &CallbackContext.from_state/1}, - [], - state - ) + Telemetry.report_span :element, :playing do + CallbackHandler.exec_and_handle_callback( + :handle_playing, + ActionHandler, + %{context: &CallbackContext.from_state/1}, + [], + state + ) + end PlaybackQueue.eval(state) end diff --git a/lib/membrane/core/element/manual_flow_controller/input_queue.ex b/lib/membrane/core/element/manual_flow_controller/input_queue.ex index 8eb1d4ed4..6c43e0481 100644 --- a/lib/membrane/core/element/manual_flow_controller/input_queue.ex +++ b/lib/membrane/core/element/manual_flow_controller/input_queue.ex @@ -132,11 +132,11 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do def store(input_queue, :buffer, v), do: store(input_queue, :buffers, [v]) - def store(%__MODULE__{q: q, size: size} = input_queue, type, v) + def store(%__MODULE__{q: q} = input_queue, type, v) when type in @non_buf_types do "Storing #{type}" |> mk_log(input_queue) |> Membrane.Logger.debug_verbose() - Telemetry.report_metric(:store, size, input_queue.log_tag) + Telemetry.report_metric(:store, input_queue.size, input_queue.log_tag) %__MODULE__{input_queue | q: q |> @qe.push({:non_buffer, type, v})} end diff --git a/lib/membrane/core/pipeline.ex b/lib/membrane/core/pipeline.ex index c764b9dc8..1b4d29b1c 100644 --- a/lib/membrane/core/pipeline.ex +++ b/lib/membrane/core/pipeline.ex @@ -45,12 +45,6 @@ defmodule Membrane.Core.Pipeline do {:ok, resource_guard} = SubprocessSupervisor.start_utility(subprocess_supervisor, {ResourceGuard, self()}) - path = Membrane.ComponentPath.get_formatted() - - ResourceGuard.register(resource_guard, fn -> - Telemetry.report_terminate(:pipeline, path) - end) - {:ok, clock_proxy} = SubprocessSupervisor.start_utility( params.subprocess_supervisor, @@ -84,8 +78,10 @@ defmodule Membrane.Core.Pipeline do @impl GenServer def handle_continue(:setup, state) do Utils.log_on_error do - state = LifecycleController.handle_setup(state) - {:noreply, state} + Telemetry.report_span :pipeline, :setup do + state = LifecycleController.handle_setup(state) + {:noreply, state} + end end end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 4c4fb3108..d367cd05a 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -6,11 +6,7 @@ defmodule Membrane.Core.Telemetry do require Membrane.Pad - defp warn(warning) do - IO.warn(warning, Macro.Env.stacktrace(__ENV__)) - end - - @possible_flags [:all, :metrics, :bitrate, :links, :inits_and_terminates, :spans] + @possible_flags [:init, :terminate, :setup, :playing] @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) @invalid_config_warning "`config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]]" @@ -19,23 +15,19 @@ defmodule Membrane.Core.Telemetry do """ defmacro report_metric(metric, value, meta \\ quote(do: %{})) do event = - quote do - [:membrane, :metric, :value] - end + [:membrane, :metric, :value] - value = - quote do - %{ - component_path: ComponentPath.get(), - metric: Atom.to_string(unquote(metric)), - value: unquote(value), - meta: unquote(meta) - } - end + val = + Macro.escape(%{ + component_path: ComponentPath.get(), + metric: Atom.to_string(metric), + value: value, + meta: meta + }) report_event( event, - value, + val, Keyword.get(@telemetry_flags, :metrics, []) |> Enum.member?(metric) ) end @@ -107,13 +99,11 @@ defmodule Membrane.Core.Telemetry do report_event(event, value, Enum.member?(@telemetry_flags, :links)) end - defmacro report_span(type, subtype, do: block) do - enabled = flag_enabled?(:inits_and_terminates) - - if enabled do + defmacro report_span(element_type, event_type, do: block) do + if event_enabled?(event_type) do quote do :telemetry.span( - [:membrane, unquote(type), unquote(subtype)], + [:membrane, unquote(element_type), unquote(event_type)], %{ log_metadata: Logger.metadata(), path: ComponentPath.get() @@ -129,20 +119,6 @@ defmodule Membrane.Core.Telemetry do end end - @doc """ - Reports a pipeline/bin/element termination. - """ - defmacro report_terminate(type, path) when type in [:pipeline, :bin, :element] do - event = [:membrane, type, :terminate] - - value = - quote do - %{path: unquote(path)} - end - - report_event(event, value, Enum.member?(@telemetry_flags, :inits_and_terminates)) - end - # Conditional event reporting of telemetry events defp report_event(event_name, measurement, enabled, metadata \\ nil) do if enabled do @@ -154,20 +130,11 @@ defmodule Membrane.Core.Telemetry do ) end else - # A hack to suppress the 'unused variable' warnings - quote do - _fn = fn -> - _unused = unquote(event_name) - _unused = unquote(measurement) - _unused = unquote(metadata) - end - - :ok - end + :ok end end - defp flag_enabled?(flag) do + defp event_enabled?(flag) do Enum.member?(get_flags(@telemetry_flags), flag) end @@ -184,4 +151,10 @@ defmodule Membrane.Core.Telemetry do warn("#{inspect(incorrect_flags)} are not correct Membrane telemetry flags") end end + + defp get_flags(_), do: [] + + defp warn(warning) do + IO.warn(warning, Macro.Env.stacktrace(__ENV__)) + end end diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 34e0bdfab..fabdb8e90 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -27,6 +27,10 @@ defmodule Membrane.TelemetryTest do end end + @paths ~w[:filter :sink :source] + @events [:init, :setup, :playing, :terminate] + @steps [:start, :stop] + setup do ref = make_ref() @@ -39,13 +43,9 @@ defmodule Membrane.TelemetryTest do [links: links, ref: ref] end - describe "Telemetry reports" do + describe "Telemetry reports elements" do @tag :telemetry - @paths ~w[:filter :sink :source] - @events [:init, :setup] - @steps [:start, :stop] - setup %{links: links} do ref = make_ref() @@ -60,27 +60,67 @@ defmodule Membrane.TelemetryTest do ref: ref }) - Testing.Pipeline.start_link_supervised!(spec: links) + pid = Testing.Pipeline.start_link_supervised!(spec: links) + :ok = Testing.Pipeline.terminate(pid) [ref: ref] end # Test each lifecycle step for each element type - for path <- @paths, + for element_type <- @paths, event <- @events do - test "#{path}/#{event}", %{ref: ref} do - path = unquote(path) + test "#{element_type}/#{event}", %{ref: ref} do + element_type = unquote(element_type) event = unquote(event) assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :start], meta, %{path: [_, ^path]}}} + {[:membrane, :element, ^event, :start], meta, %{path: [_, ^element_type]}}} assert meta.system_time > 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :stop], meta, %{path: [_, ^path]}}} + {[:membrane, :element, ^event, :stop], meta, %{path: [_, ^element_type]}}} assert meta.duration > 0 end end end + + describe "Pipelines" do + setup %{links: links} do + ref = make_ref() + + events = + for event <- @events, + step <- @steps do + [:membrane, :pipeline, event, step] + end + + :telemetry.attach_many(ref, events, &TelemetryListener.handle_event/4, %{ + dest: self(), + ref: ref + }) + + pid = Testing.Pipeline.start_link_supervised!(spec: links) + :ok = Testing.Pipeline.terminate(pid) + [ref: ref] + end + + test "Pipeline lifecycle", %{ref: ref} do + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], meta, %{}}} + + assert meta.system_time > 0 + + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], meta, %{}}} + + assert meta.duration > 0 + + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], meta, %{}}} + + assert meta.system_time > 0 + + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], meta, %{}}} + + assert meta.duration > 0 + end + end end From 56890e0500301a2652c580f9c0a475c9088aec09 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 16 Dec 2024 12:41:31 +0100 Subject: [PATCH 06/46] Report playing and links --- config/config.exs | 3 +- lib/membrane/core/element.ex | 5 +- lib/membrane/core/pipeline.ex | 1 - lib/membrane/core/telemetry.ex | 115 ++++++++++++++++++------------- lib/membrane/telemetry.ex | 22 ++++-- test/membrane/telemetry_test.exs | 20 +++--- 6 files changed, 99 insertions(+), 67 deletions(-) diff --git a/config/config.exs b/config/config.exs index 2728a826b..be48204cd 100644 --- a/config/config.exs +++ b/config/config.exs @@ -8,6 +8,7 @@ if config_env() == :test do :init, :setup, :terminate, - :playing + :playing, + :link ] end diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index 6d1074079..4b1172df3 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -20,6 +20,7 @@ defmodule Membrane.Core.Element do alias Membrane.{Clock, Core, ResourceGuard, Sync} alias Membrane.Core.Child.PadSpecHandler + alias Membrane.Core.Telemetry alias Membrane.Core.Element.{ BufferController, @@ -187,6 +188,7 @@ defmodule Membrane.Core.Element do _from, state ) do + Telemetry.report_link(this, other) {reply, state} = PadController.handle_link(direction, this, other, params, state) {:reply, reply, state} end @@ -248,7 +250,8 @@ defmodule Membrane.Core.Element do end defp do_handle_info(Message.new(:play), state) do - state = LifecycleController.handle_playing(state) + Telemetry.report_playing(:element) + LifecycleController.handle_playing(state) {:noreply, state} end diff --git a/lib/membrane/core/pipeline.ex b/lib/membrane/core/pipeline.ex index 1b4d29b1c..0b6fdcd8a 100644 --- a/lib/membrane/core/pipeline.ex +++ b/lib/membrane/core/pipeline.ex @@ -12,7 +12,6 @@ defmodule Membrane.Core.Pipeline do require Membrane.Core.Utils, as: Utils require Membrane.Core.Message, as: Message require Membrane.Core.Telemetry, as: Telemetry - require Membrane.Core.Component @spec get_stalker(pipeline :: pid()) :: Membrane.Core.Stalker.t() def get_stalker(pipeline) do diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index d367cd05a..b2ff5dc34 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -1,23 +1,48 @@ defmodule Membrane.Core.Telemetry do @moduledoc false + # This module provides a way to gather metrics from running Membrane components, as well + # as exposing these metrics in a format idiomatic with [Telemetry](https://hexdocs.pm/telemetry/) + # library. It uses compile time flags from `config.exs` to determine a priori which metrics should be + # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. require Logger alias Membrane.ComponentPath - require Membrane.Pad - - @possible_flags [:init, :terminate, :setup, :playing] + @possible_flags [:init, :terminate, :setup, :playing, :link] @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) - @invalid_config_warning "`config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]]" + @invalid_config_warning """ + `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]]" + """ + + @public_state_keys %{ + Membrane.Core.Element.State => [ + :type, + :name, + :pads_info, + :initialized? + ] + } + + # Verify at compile time that every key is actually present in Core.Element.State + for {mod, keys} <- @public_state_keys do + case keys -- Map.keys(struct(mod)) do + [] -> + :ok + + other -> + raise "Public telemetry keys #{inspect(other)} absent in #{mod}" + end + end @doc """ - Reports metrics such as input buffer's size inside functions, incoming events and received stream format. + Reports a metric with an inherent value. E.g. input buffers size or received stream format. """ - defmacro report_metric(metric, value, meta \\ quote(do: %{})) do + @spec report_metric(atom(), any(), map()) :: Macro.t() + defmacro report_metric(metric, value, meta \\ %{}) do event = [:membrane, :metric, :value] - val = + value = Macro.escape(%{ component_path: ComponentPath.get(), metric: Atom.to_string(metric), @@ -25,22 +50,16 @@ defmodule Membrane.Core.Telemetry do meta: meta }) - report_event( - event, - val, - Keyword.get(@telemetry_flags, :metrics, []) |> Enum.member?(metric) - ) + report_event(:metrics, event, value) end @doc """ - Given list of buffers (or a single buffer) calculates total size of their payloads in bits + Given a list of buffers calculates total size of their payloads in bits and reports it. """ + @spec report_bitrate([Membrane.Buffer.t()]) :: Macro.t() defmacro report_bitrate(buffers) do - event = - quote do - [:membrane, :metric, :value] - end + event = [:membrane, :metric, :value] value = quote do @@ -57,53 +76,52 @@ defmodule Membrane.Core.Telemetry do } end - report_event( - event, - value, - Keyword.get(@telemetry_flags, :metrics, []) |> Enum.member?(:bitrate) - ) + report_event(:bitrate, event, value) end - @doc false - @spec __get_public_pad_name__(Membrane.Pad.ref()) :: Membrane.Pad.ref() - def __get_public_pad_name__(pad) do - case pad do - {:private, direction} -> direction - {Membrane.Pad, {:private, direction}, ref} -> {Membrane.Pad, direction, ref} - _pad -> pad + defp get_public_pad_name(pad) do + quote bind_quoted: [pad: pad] do + case pad.pad_ref do + {:private, direction} -> direction + {Membrane.Pad, {:private, direction}, ref} -> {Membrane.Pad, direction, ref} + _pad -> pad.pad_ref + end end end @doc """ Reports new link connection being initialized in pipeline. """ + @spec report_link(Membrane.Pad.t(), Membrane.Pad.t()) :: Macro.t() defmacro report_link(from, to) do - event = - quote do - [:membrane, :link, :new] - end + event = [:membrane, :link, :new] value = quote do %{ - parent_path: Membrane.ComponentPath.get_formatted(), - from: inspect(unquote(from).child), - to: inspect(unquote(to).child), - pad_from: - Membrane.Core.Telemetry.__get_public_pad_name__(unquote(from).pad_ref) |> inspect(), - pad_to: - Membrane.Core.Telemetry.__get_public_pad_name__(unquote(to).pad_ref) |> inspect() + from: unquote(from), + to: unquote(to), + pad_from: unquote(get_public_pad_name(from)), + pad_to: unquote(get_public_pad_name(to)) } end - report_event(event, value, Enum.member?(@telemetry_flags, :links)) + report_event(:link, event, value) end - defmacro report_span(element_type, event_type, do: block) do + defmacro report_playing(component_type) do + report_event(:playing, [:membrane, component_type, :playing], quote(do: %{})) + end + + @doc """ + Reports an arbitrary span consistent with span format in `:telementry` + """ + @spec report_span(atom(), atom(), do: block) :: block when block: Macro.t() + defmacro report_span(component_type, event_type, do: block) do if event_enabled?(event_type) do quote do :telemetry.span( - [:membrane, unquote(element_type), unquote(event_type)], + [:membrane, unquote(component_type), unquote(event_type)], %{ log_metadata: Logger.metadata(), path: ComponentPath.get() @@ -119,14 +137,17 @@ defmodule Membrane.Core.Telemetry do end end - # Conditional event reporting of telemetry events - defp report_event(event_name, measurement, enabled, metadata \\ nil) do - if enabled do + defp report_event(event_type, event_name, measurement, metadata \\ quote(do: %{})) do + if event_enabled?(event_type) do quote do :telemetry.execute( unquote(event_name), unquote(measurement), - unquote(metadata) || %{} + %{ + log_metadata: Logger.metadata(), + path: ComponentPath.get() + } + |> Map.merge(unquote(metadata)) ) end else diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 129c952a7..53e5c6d64 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -18,17 +18,21 @@ defmodule Membrane.Telemetry do * Measurement: `t:link_event_value/0` * Metadata: `%{}` - * `[:membrane, :pipeline | :bin | :element, :init]` - to report pipeline/element/bin initialization + * `[:membrane, :pipeline | :bin | :element, :init, :start | :stop | :exception]` - to report pipeline/element/bin initialization * Measurement: `t:init_or_terminate_event_value/0` * Metadata: `%{log_metadata: keyword()}`, includes Logger's metadata of created component - * `[:membrane, :pipeline | :bin | :element, :terminate]` - to report pipeline/element/bin termination + * `[:membrane, :pipeline | :bin | :element, :setup, :start | :stop | :exception]` - to report pipeline/element/bin setup + * Measurement: `t:init_or_terminate_event_value/0` + * Metadata: `%{log_metadata: keyword()}`, includes Logger's metadata of created component + + * `[:membrane, :pipeline | :bin | :element, :terminate, :start | :stop | :exception]` - to report pipeline/element/bin termination * Measurement: `t:init_or_terminate_event_value/0` * Metadata: `%{}` ## Enabling certain metrics/events - A lot of events can happen literally hundreds times per second such as registering that a buffer has been sent/processed. + A lot of events can happen hundreds times per second such as registering that a buffer has been sent/processed. This behaviour can come with a great performance penalties but may be helpful for certain discoveries. To avoid any runtime overhead when the reporting is not necessary all metrics/events are hidden behind a compile-time feature flags. @@ -37,20 +41,24 @@ defmodule Membrane.Telemetry do config :membrane_core, telemetry_flags: [ - :flag_name, - ..., - {:metrics, [list of metrics]} - ... + include: [...] | exclude: [...] | :all ] Available flags are (those are of a very low overhead): * `:links` - enables new links notifications + # TODO redact * `:inits_and_terminates` - enables notifications of `init` and `terminate` events for elements/bins/pipelines Additionally one can control which metric values should get measured by passing an option of format : `{:metrics, [list of metrics]}` + Available spans are: + * `:init` - Time spent on executing components initialization handler + * `:terminate` - Time spent on executing components termination handler + * `:setup` - Time spent on executing components setup handler + * `:playing` - Time spent on executing components playing handler + Available metrics are: * `:buffer` - number of buffers being sent from a particular element * `:bitrate` - total number of bits carried by the buffers mentioned above diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index fabdb8e90..e37e424aa 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -1,9 +1,13 @@ defmodule Membrane.TelemetryTest do + @moduledoc """ + Test suite for Membrane telemetry public API. It tests if telemetry events are reported + properly for all elements and pipelines upon attaching to the :telemetry system. + """ + use ExUnit.Case, async: false + alias Membrane.Testing import Membrane.ChildrenSpec - require Logger - alias Membrane.Testing defmodule TestFilter do use Membrane.Filter @@ -27,10 +31,6 @@ defmodule Membrane.TelemetryTest do end end - @paths ~w[:filter :sink :source] - @events [:init, :setup, :playing, :terminate] - @steps [:start, :stop] - setup do ref = make_ref() @@ -43,6 +43,10 @@ defmodule Membrane.TelemetryTest do [links: links, ref: ref] end + @paths ~w[:filter :sink :source] + @events [:init, :setup, :playing, :terminate] + @steps [:start, :stop] + describe "Telemetry reports elements" do @tag :telemetry @@ -107,19 +111,15 @@ defmodule Membrane.TelemetryTest do test "Pipeline lifecycle", %{ref: ref} do assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], meta, %{}}} - assert meta.system_time > 0 assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], meta, %{}}} - assert meta.duration > 0 assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], meta, %{}}} - assert meta.system_time > 0 assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], meta, %{}}} - assert meta.duration > 0 end end From 3cb267e8e52c29ff28a24d0f1ad431b4166c596c Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 16 Dec 2024 12:55:22 +0100 Subject: [PATCH 07/46] CQ and cleanup --- lib/membrane/core/element.ex | 2 +- lib/membrane/core/telemetry.ex | 9 ++++----- 2 files changed, 5 insertions(+), 6 deletions(-) diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index 4b1172df3..69ddcda75 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -250,8 +250,8 @@ defmodule Membrane.Core.Element do end defp do_handle_info(Message.new(:play), state) do + state = LifecycleController.handle_playing(state) Telemetry.report_playing(:element) - LifecycleController.handle_playing(state) {:noreply, state} end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index b2ff5dc34..d844d7f33 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -1,8 +1,8 @@ defmodule Membrane.Core.Telemetry do @moduledoc false # This module provides a way to gather metrics from running Membrane components, as well - # as exposing these metrics in a format idiomatic with [Telemetry](https://hexdocs.pm/telemetry/) - # library. It uses compile time flags from `config.exs` to determine a priori which metrics should be + # as exposing these metrics in a format idiomatic to [Telemetry](https://hexdocs.pm/telemetry/) + # library. It uses compile time flags from `config.exs` to determine which metrics should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. require Logger @@ -35,7 +35,7 @@ defmodule Membrane.Core.Telemetry do end @doc """ - Reports a metric with an inherent value. E.g. input buffers size or received stream format. + Reports a metric with its coresponding value. E.g. input buffers size or received stream format. """ @spec report_metric(atom(), any(), map()) :: Macro.t() defmacro report_metric(metric, value, meta \\ %{}) do @@ -127,8 +127,7 @@ defmodule Membrane.Core.Telemetry do path: ComponentPath.get() }, fn -> - unquote(block) - |> then(&{&1, %{log_metadata: Logger.metadata(), path: ComponentPath.get()}}) + {unquote(block), %{log_metadata: Logger.metadata(), path: ComponentPath.get()}} end ) end From 7a69d1edc83397db929dcf834d7fcfab70205042 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 7 Jan 2025 18:18:54 +0100 Subject: [PATCH 08/46] Cleanup of old telemetry and more universal method of measuring spans (wip) --- config/config.exs | 2 +- lib/membrane/core/bin.ex | 5 +- lib/membrane/core/callback_handler.ex | 14 +- lib/membrane/core/element.ex | 13 +- lib/membrane/core/element/action_handler.ex | 3 - .../core/element/buffer_controller.ex | 3 - .../core/element/lifecycle_controller.ex | 18 +- .../manual_flow_controller/input_queue.ex | 7 +- lib/membrane/core/pipeline.ex | 12 +- lib/membrane/core/telemetry.ex | 198 +++++++++++------- test/membrane/telemetry_test.exs | 96 +++++---- 11 files changed, 195 insertions(+), 176 deletions(-) diff --git a/config/config.exs b/config/config.exs index be48204cd..c84985e47 100644 --- a/config/config.exs +++ b/config/config.exs @@ -7,7 +7,7 @@ if config_env() == :test do include: [ :init, :setup, - :terminate, + :terminate_request, :playing, :link ] diff --git a/lib/membrane/core/bin.ex b/lib/membrane/core/bin.ex index 7655dcacd..e88bf8b69 100644 --- a/lib/membrane/core/bin.ex +++ b/lib/membrane/core/bin.ex @@ -13,7 +13,6 @@ defmodule Membrane.Core.Bin do Parent, ProcessHelper, SubprocessSupervisor, - Telemetry, TimerController } @@ -96,9 +95,7 @@ defmodule Membrane.Core.Bin do {:continue, :setup}} def init(options) do Utils.log_on_error do - Telemetry.report_span :bin, :init do - do_init(options) - end + do_init(options) end end diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index c16a5303d..0600ab4d1 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -7,11 +7,10 @@ defmodule Membrane.Core.CallbackHandler do use Bunch - require Membrane.Core.Telemetry - alias Membrane.Core.Telemetry alias Membrane.CallbackError require Membrane.Logger + require Membrane.Core.Telemetry, as: Telemetry @type state :: %{ :module => module, @@ -138,9 +137,14 @@ defmodule Membrane.Core.CallbackHandler do callback_result = try do - Telemetry.report_span :element, :terminate do - apply(module, callback, args) - end + Telemetry.report_span( + state.__struct__, + callback, + fn -> + apply(module, callback, args) + |> Telemetry.state_result(internal_state, state) + end + ) rescue e in UndefinedFunctionError -> _ignored = diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index 69ddcda75..dbe4a37f0 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -20,7 +20,6 @@ defmodule Membrane.Core.Element do alias Membrane.{Clock, Core, ResourceGuard, Sync} alias Membrane.Core.Child.PadSpecHandler - alias Membrane.Core.Telemetry alias Membrane.Core.Element.{ BufferController, @@ -154,10 +153,7 @@ defmodule Membrane.Core.Element do } |> PadSpecHandler.init_pads() - state = - Telemetry.report_span :element, :init do - LifecycleController.handle_init(options.user_options, state) - end + state = LifecycleController.handle_init(options.user_options, state) {:ok, state, {:continue, :setup}} end @@ -165,10 +161,8 @@ defmodule Membrane.Core.Element do @impl GenServer def handle_continue(:setup, state) do Utils.log_on_error do - Telemetry.report_span :element, :setup do - state = LifecycleController.handle_setup(state) - {:noreply, state} - end + state = LifecycleController.handle_setup(state) + {:noreply, state} end end @@ -251,7 +245,6 @@ defmodule Membrane.Core.Element do defp do_handle_info(Message.new(:play), state) do state = LifecycleController.handle_playing(state) - Telemetry.report_playing(:element) {:noreply, state} end diff --git a/lib/membrane/core/element/action_handler.ex b/lib/membrane/core/element/action_handler.ex index 4a4ec1aed..8d5df71c8 100644 --- a/lib/membrane/core/element/action_handler.ex +++ b/lib/membrane/core/element/action_handler.ex @@ -319,9 +319,6 @@ defmodule Membrane.Core.Element.ActionHandler do "Sending #{length(buffers)} buffer(s) through pad #{inspect(pad_ref)}" ) - Telemetry.report_metric(:buffer, length(buffers)) - Telemetry.report_bitrate(buffers) - Enum.each(buffers, fn %Buffer{} -> :ok value -> raise ElementError, "Tried to send an invalid buffer #{inspect(value)}" diff --git a/lib/membrane/core/element/buffer_controller.ex b/lib/membrane/core/element/buffer_controller.ex index fff2946b9..de7fe8d92 100644 --- a/lib/membrane/core/element/buffer_controller.ex +++ b/lib/membrane/core/element/buffer_controller.ex @@ -112,9 +112,6 @@ defmodule Membrane.Core.Element.BufferController do def exec_buffer_callback(pad_ref, buffers, %State{type: type} = state) when type in [:sink, :endpoint] do - Telemetry.report_metric(:buffer, length(List.wrap(buffers))) - Telemetry.report_bitrate(buffers) - do_exec_buffer_callback(pad_ref, buffers, state) end diff --git a/lib/membrane/core/element/lifecycle_controller.ex b/lib/membrane/core/element/lifecycle_controller.ex index e91c7082e..6f7c231cf 100644 --- a/lib/membrane/core/element/lifecycle_controller.ex +++ b/lib/membrane/core/element/lifecycle_controller.ex @@ -6,8 +6,6 @@ defmodule Membrane.Core.Element.LifecycleController do use Bunch - require Membrane.Core.Telemetry - alias Membrane.Core.Telemetry alias Membrane.{Clock, Element, Sync} alias Membrane.Core.{CallbackHandler, Element, Message, SubprocessSupervisor} @@ -83,15 +81,13 @@ defmodule Membrane.Core.Element.LifecycleController do |> EffectiveFlowController.resolve_effective_flow_control() state = - Telemetry.report_span :element, :playing do - CallbackHandler.exec_and_handle_callback( - :handle_playing, - ActionHandler, - %{context: &CallbackContext.from_state/1}, - [], - state - ) - end + CallbackHandler.exec_and_handle_callback( + :handle_playing, + ActionHandler, + %{context: &CallbackContext.from_state/1}, + [], + state + ) PlaybackQueue.eval(state) end diff --git a/lib/membrane/core/element/manual_flow_controller/input_queue.ex b/lib/membrane/core/element/manual_flow_controller/input_queue.ex index 6c43e0481..493f7a590 100644 --- a/lib/membrane/core/element/manual_flow_controller/input_queue.ex +++ b/lib/membrane/core/element/manual_flow_controller/input_queue.ex @@ -15,7 +15,6 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do alias Membrane.StreamFormat require Membrane.Core.Stalker, as: Stalker - require Membrane.Core.Telemetry, as: Telemetry require Membrane.Logger @qe Qex @@ -124,7 +123,6 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do %__MODULE__{size: size} = input_queue = do_store_buffers(input_queue, v) - Telemetry.report_metric(:store, size, input_queue.log_tag) :atomics.put(stalker_metrics.size, 1, size) input_queue @@ -132,12 +130,10 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do def store(input_queue, :buffer, v), do: store(input_queue, :buffers, [v]) - def store(%__MODULE__{q: q} = input_queue, type, v) + def store(%__MODULE__{q: q, size: size} = input_queue, type, v) when type in @non_buf_types do "Storing #{type}" |> mk_log(input_queue) |> Membrane.Logger.debug_verbose() - Telemetry.report_metric(:store, input_queue.size, input_queue.log_tag) - %__MODULE__{input_queue | q: q |> @qe.push({:non_buffer, type, v})} end @@ -176,7 +172,6 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do input_queue = maybe_increase_atomic_demand(input_queue) %{size: size, stalker_metrics: stalker_metrics} = input_queue - Telemetry.report_metric(:take, size, input_queue.log_tag) :atomics.put(stalker_metrics.size, 1, size) {out, input_queue} diff --git a/lib/membrane/core/pipeline.ex b/lib/membrane/core/pipeline.ex index 0b6fdcd8a..850e82537 100644 --- a/lib/membrane/core/pipeline.ex +++ b/lib/membrane/core/pipeline.ex @@ -11,7 +11,7 @@ defmodule Membrane.Core.Pipeline do require Membrane.Core.Utils, as: Utils require Membrane.Core.Message, as: Message - require Membrane.Core.Telemetry, as: Telemetry + require Membrane.Core.Component @spec get_stalker(pipeline :: pid()) :: Membrane.Core.Stalker.t() def get_stalker(pipeline) do @@ -24,9 +24,7 @@ defmodule Membrane.Core.Pipeline do @impl GenServer def init(params) do Utils.log_on_error do - Telemetry.report_span :pipeline, :init do - do_init(params) - end + do_init(params) end end @@ -77,10 +75,8 @@ defmodule Membrane.Core.Pipeline do @impl GenServer def handle_continue(:setup, state) do Utils.log_on_error do - Telemetry.report_span :pipeline, :setup do - state = LifecycleController.handle_setup(state) - {:noreply, state} - end + state = LifecycleController.handle_setup(state) + {:noreply, state} end end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index d844d7f33..abd8b9fd3 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -8,22 +8,60 @@ defmodule Membrane.Core.Telemetry do require Logger alias Membrane.ComponentPath - @possible_flags [:init, :terminate, :setup, :playing, :link] + @possible_flags [:init, :terminate_request, :setup, :playing, :link] @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) - @invalid_config_warning """ - `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]]" - """ @public_state_keys %{ Membrane.Core.Element.State => [ + :subprocess_supervisor, + :terminating?, + :setup_incomplete?, + :effective_flow_control, + :resource_guard, + :initialized?, + :playback, + :module, :type, :name, + :internal_state, + :pads_info, + :pads_data, + :parent_pid + ], + Membrane.Core.Bin.State => [ + :internal_state, + :module, + :children, + :subprocess_supervisor, + :name, :pads_info, - :initialized? + :pads_data, + :parent_pid, + :links, + :crash_groups, + :children_log_metadata, + :playback, + :initialized?, + :terminating?, + :resource_guard, + :setup_incomplete? + ], + Membrane.Core.Pipeline.State => [ + :module, + :playback, + :internal_state, + :children, + :links, + :crash_groups, + :initialized?, + :terminating?, + :resource_guard, + :setup_incomplete?, + :subprocess_supervisor ] } - # Verify at compile time that every key is actually present in Core.Element.State + # Verify at compile time that every key is actually present in Core.*.State for {mod, keys} <- @public_state_keys do case keys -- Map.keys(struct(mod)) do [] -> @@ -34,49 +72,16 @@ defmodule Membrane.Core.Telemetry do end end - @doc """ - Reports a metric with its coresponding value. E.g. input buffers size or received stream format. - """ - @spec report_metric(atom(), any(), map()) :: Macro.t() - defmacro report_metric(metric, value, meta \\ %{}) do - event = - [:membrane, :metric, :value] + defmacro report_metric(_, _), do: nil - value = - Macro.escape(%{ - component_path: ComponentPath.get(), - metric: Atom.to_string(metric), - value: value, - meta: meta - }) - - report_event(:metrics, event, value) - end + defmacro report_metric(_, _, _), do: nil @doc """ - Given a list of buffers calculates total size of their payloads in bits - and reports it. + Sanitizes state data by removing keys that are meant to be internal-only. """ - @spec report_bitrate([Membrane.Buffer.t()]) :: Macro.t() - defmacro report_bitrate(buffers) do - event = [:membrane, :metric, :value] - - value = - quote do - %{ - component_path: ComponentPath.get(), - metric: "bitrate", - value: - 8 * - Enum.reduce( - List.wrap(unquote(buffers)), - 0, - &(Membrane.Payload.size(&1.payload) + &2) - ) - } - end - - report_event(:bitrate, event, value) + @spec sanitize_state_data(struct()) :: map() + def sanitize_state_data(state = %struct{}) do + Map.take(state, @public_state_keys[struct]) end defp get_public_pad_name(pad) do @@ -92,7 +97,7 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports new link connection being initialized in pipeline. """ - @spec report_link(Membrane.Pad.t(), Membrane.Pad.t()) :: Macro.t() + @spec report_link(Membrane.Pad.ref(), Membrane.Pad.ref()) :: Macro.t() defmacro report_link(from, to) do event = [:membrane, :link, :new] @@ -116,26 +121,51 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports an arbitrary span consistent with span format in `:telementry` """ - @spec report_span(atom(), atom(), do: block) :: block when block: Macro.t() - defmacro report_span(component_type, event_type, do: block) do + @spec report_span(module(), binary(), do: block) :: block when block: Macro.t() + def report_span(component_type, event_type, f) do + component_type = struct_to_name(component_type) + event_type = handler_to_name(event_type) + if event_enabled?(event_type) do - quote do - :telemetry.span( - [:membrane, unquote(component_type), unquote(event_type)], - %{ - log_metadata: Logger.metadata(), - path: ComponentPath.get() - }, - fn -> - {unquote(block), %{log_metadata: Logger.metadata(), path: ComponentPath.get()}} + :telemetry.span( + [:membrane, component_type, event_type], + %{ + log_metadata: Logger.metadata(), + path: ComponentPath.get() + }, + fn -> + case f.() do + {:telemetry_result, {r, new_intstate, old_intstate, old_state}} -> + {r, %{new_state: new_intstate}, + %{ + old_internal_state: old_intstate, + old_state: sanitize_state_data(old_state), + log_metadata: Logger.metadata(), + path: ComponentPath.get() + }} + + _other -> + raise "Unexpected telemetry span result. Use Telemetry.result/3 macro" end - ) - end + end + ) else - block + {:telemetry_result, {result, _, _, _}} = f.() + result end end + defp struct_to_name(Membrane.Core.Element.State), do: :element + defp struct_to_name(Membrane.Core.Bin.State), do: :bin + defp struct_to_name(Membrane.Core.Pipeline.State), do: :pipeline + + defp handler_to_name(a) when is_atom(a), do: handler_to_name(Atom.to_string(a)) + defp handler_to_name("handle_" <> r) when is_binary(r), do: String.to_atom(r) + + def state_result(res = {_actions, new_internal_state}, old_internal_state, old_state) do + {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} + end + defp report_event(event_type, event_name, measurement, metadata \\ quote(do: %{})) do if event_enabled?(event_type) do quote do @@ -154,27 +184,37 @@ defmodule Membrane.Core.Telemetry do end end - defp event_enabled?(flag) do - Enum.member?(get_flags(@telemetry_flags), flag) - end - - defp get_flags(:all), do: @possible_flags - defp get_flags(include: _, exclude: _), do: warn(@invalid_config_warning) - defp get_flags(exclude: exclude), do: @possible_flags -- exclude - - defp get_flags(include: include) do - case include -- @possible_flags do - [] -> - include + case @telemetry_flags do + :all -> + def event_enabled?(_), do: true + + include: _, exclude: _ -> + IO.warn( + """ + `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]] + """, + Macro.Env.stacktrace(__ENV__) + ) + + include: inc -> + for event <- inc do + if event not in @possible_flags do + raise """ + Invalid telemetry flag: #{inspect(event)}. + Possible values are: #{inspect(@possible_flags)} + """ + end + + def event_enabled?(unquote(event)), do: true + end - incorrect_flags -> - warn("#{inspect(incorrect_flags)} are not correct Membrane telemetry flags") - end - end + def event_enabled?(_), do: false - defp get_flags(_), do: [] + exclude: exc -> + for event <- exc do + def event_enabled?(unquote(event)), do: false + end - defp warn(warning) do - IO.warn(warning, Macro.Env.stacktrace(__ENV__)) + def event_enabled?(_), do: true end end diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index e37e424aa..7f347135d 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -9,18 +9,14 @@ defmodule Membrane.TelemetryTest do import Membrane.ChildrenSpec require Logger + @moduletag :telemetry defmodule TestFilter do use Membrane.Filter - def_input_pad :input, flow_control: :manual, accepted_format: _any, demand_unit: :buffers - def_output_pad :output, flow_control: :manual, accepted_format: _any + def_input_pad :input, accepted_format: _any + def_output_pad :output, accepted_format: _any def_options target: [spec: pid()] - @impl true - def handle_demand(_pad, size, _unit, _context, state) do - {[demand: {:input, size}], state} - end - @impl true def handle_buffer(_pad, _buffer, _context, state), do: {[], state} end @@ -44,22 +40,20 @@ defmodule Membrane.TelemetryTest do end @paths ~w[:filter :sink :source] - @events [:init, :setup, :playing, :terminate] + @spans [:init, :setup, :playing, :terminate_request] @steps [:start, :stop] - describe "Telemetry reports elements" do - @tag :telemetry - + describe "Telemetry reports elements'" do setup %{links: links} do ref = make_ref() - events = - for event <- @events, + spans = + for event <- @spans, step <- @steps do [:membrane, :element, event, step] end - :telemetry.attach_many(ref, events, &TelemetryListener.handle_event/4, %{ + :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ dest: self(), ref: ref }) @@ -71,56 +65,66 @@ defmodule Membrane.TelemetryTest do # Test each lifecycle step for each element type for element_type <- @paths, - event <- @events do + event <- @spans do test "#{element_type}/#{event}", %{ref: ref} do element_type = unquote(element_type) event = unquote(event) assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :start], meta, %{path: [_, ^element_type]}}} + {[:membrane, :element, ^event, :start], value, + %{path: [_, ^element_type]}}}, + 1000 - assert meta.system_time > 0 + assert value.system_time > 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :stop], meta, %{path: [_, ^element_type]}}} + {[:membrane, :element, ^event, :stop], value, %{path: [_, ^element_type]}}}, + 1000 - assert meta.duration > 0 + assert value.duration > 0 end end end - describe "Pipelines" do - setup %{links: links} do - ref = make_ref() + # describe "Telemetry reports pipelines'" do + # setup %{links: links} do + # ref = make_ref() - events = - for event <- @events, - step <- @steps do - [:membrane, :pipeline, event, step] - end + # spans = + # for event <- @spans, + # step <- @steps do + # [:membrane, :pipeline, event, step] + # end - :telemetry.attach_many(ref, events, &TelemetryListener.handle_event/4, %{ - dest: self(), - ref: ref - }) + # :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ + # dest: self(), + # ref: ref + # }) - pid = Testing.Pipeline.start_link_supervised!(spec: links) - :ok = Testing.Pipeline.terminate(pid) - [ref: ref] - end + # pid = Testing.Pipeline.start_link_supervised!(spec: links) + # :ok = Testing.Pipeline.terminate(pid) + # [ref: ref] + # end - test "Pipeline lifecycle", %{ref: ref} do - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], meta, %{}}} - assert meta.system_time > 0 + # test "lifecycle", %{ref: ref} do + # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], value, %{}}} + # assert value.system_time > 0 - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], meta, %{}}} - assert meta.duration > 0 + # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], value, %{}}} + # assert value.duration > 0 - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], meta, %{}}} - assert meta.system_time > 0 + # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], value, %{}}} + # assert value.system_time > 0 - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], meta, %{}}} - assert meta.duration > 0 - end - end + # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], value, %{}}} + # assert value.duration > 0 + # end + + # # test "diefferent and sanitized states on start and stop", %{ref: ref} do + # # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], value, _meta}} + + # # assert Map.has_key?(value, :children) + # # refute Map.has_key?(value, :stalker) + # # end + # end end From a77d6c08b0188e299d8c74eead882b35837c298f Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 9 Jan 2025 17:06:17 +0100 Subject: [PATCH 09/46] Tests for handlers throwing exceptions and proper santization of component states --- config/config.exs | 3 +- lib/membrane/core/element/action_handler.ex | 3 - .../manual_flow_controller/input_queue.ex | 2 +- lib/membrane/core/telemetry.ex | 37 +++--- test/membrane/telemetry_test.exs | 122 ++++++++++++------ 5 files changed, 107 insertions(+), 60 deletions(-) diff --git a/config/config.exs b/config/config.exs index c84985e47..6384c18aa 100644 --- a/config/config.exs +++ b/config/config.exs @@ -9,6 +9,7 @@ if config_env() == :test do :setup, :terminate_request, :playing, - :link + :link, + :parent_notification ] end diff --git a/lib/membrane/core/element/action_handler.ex b/lib/membrane/core/element/action_handler.ex index 8d5df71c8..fafd2fd58 100644 --- a/lib/membrane/core/element/action_handler.ex +++ b/lib/membrane/core/element/action_handler.ex @@ -8,8 +8,6 @@ defmodule Membrane.Core.Element.ActionHandler do import Membrane.Pad, only: [is_pad_ref: 1] - alias Membrane.Telemetry - alias Membrane.{ ActionError, Buffer, @@ -34,7 +32,6 @@ defmodule Membrane.Core.Element.ActionHandler do require Membrane.Core.Child.PadModel, as: PadModel require Membrane.Core.Message, as: Message - require Membrane.Core.Telemetry, as: Telemetry require Membrane.Logger @impl CallbackHandler diff --git a/lib/membrane/core/element/manual_flow_controller/input_queue.ex b/lib/membrane/core/element/manual_flow_controller/input_queue.ex index 493f7a590..76c8432ea 100644 --- a/lib/membrane/core/element/manual_flow_controller/input_queue.ex +++ b/lib/membrane/core/element/manual_flow_controller/input_queue.ex @@ -130,7 +130,7 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do def store(input_queue, :buffer, v), do: store(input_queue, :buffers, [v]) - def store(%__MODULE__{q: q, size: size} = input_queue, type, v) + def store(%__MODULE__{q: q, size: _size} = input_queue, type, v) when type in @non_buf_types do "Storing #{type}" |> mk_log(input_queue) |> Membrane.Logger.debug_verbose() diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index abd8b9fd3..d8f122bb5 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -8,7 +8,9 @@ defmodule Membrane.Core.Telemetry do require Logger alias Membrane.ComponentPath - @possible_flags [:init, :terminate_request, :setup, :playing, :link] + + # TODO find a proper way to describe types of measured metrics + @possible_flags [:init, :terminate_request, :setup, :playing, :link, :parent_notification] @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) @public_state_keys %{ @@ -114,17 +116,13 @@ defmodule Membrane.Core.Telemetry do report_event(:link, event, value) end - defmacro report_playing(component_type) do - report_event(:playing, [:membrane, component_type, :playing], quote(do: %{})) - end - @doc """ Reports an arbitrary span consistent with span format in `:telementry` """ - @spec report_span(module(), binary(), do: block) :: block when block: Macro.t() + @spec report_span(module(), binary(), fun()) :: any() def report_span(component_type, event_type, f) do - component_type = struct_to_name(component_type) - event_type = handler_to_name(event_type) + component_type = state_module_to_atom(component_type) + event_type = handler_to_event_name(event_type) if event_enabled?(event_type) do :telemetry.span( @@ -140,6 +138,7 @@ defmodule Membrane.Core.Telemetry do %{ old_internal_state: old_intstate, old_state: sanitize_state_data(old_state), + new_internal_state: new_intstate, log_metadata: Logger.metadata(), path: ComponentPath.get() }} @@ -155,12 +154,12 @@ defmodule Membrane.Core.Telemetry do end end - defp struct_to_name(Membrane.Core.Element.State), do: :element - defp struct_to_name(Membrane.Core.Bin.State), do: :bin - defp struct_to_name(Membrane.Core.Pipeline.State), do: :pipeline + defp state_module_to_atom(Membrane.Core.Element.State), do: :element + defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin + defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline - defp handler_to_name(a) when is_atom(a), do: handler_to_name(Atom.to_string(a)) - defp handler_to_name("handle_" <> r) when is_binary(r), do: String.to_atom(r) + defp handler_to_event_name(a) when is_atom(a), do: handler_to_event_name(Atom.to_string(a)) + defp handler_to_event_name("handle_" <> r) when is_binary(r), do: String.to_atom(r) def state_result(res = {_actions, new_internal_state}, old_internal_state, old_state) do {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} @@ -188,13 +187,15 @@ defmodule Membrane.Core.Telemetry do :all -> def event_enabled?(_), do: true + exclude: _, include: _ -> + raise """ + `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]] + """ + include: _, exclude: _ -> - IO.warn( - """ + raise """ `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]] - """, - Macro.Env.stacktrace(__ENV__) - ) + """ include: inc -> for event <- inc do diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 7f347135d..fe2877592 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -19,6 +19,12 @@ defmodule Membrane.TelemetryTest do @impl true def handle_buffer(_pad, _buffer, _context, state), do: {[], state} + + @impl true + def handle_parent_notification(:crash, _context, state) do + raise "Crash" + {[], state} + end end defmodule TelemetryListener do @@ -30,13 +36,12 @@ defmodule Membrane.TelemetryTest do setup do ref = make_ref() - links = [ + child_spec = child(:source, %Testing.Source{output: [~c"a", ~c"b", ~c"c"]}) |> child(:filter, %TestFilter{target: self()}) |> child(:sink, Testing.Sink) - ] - [links: links, ref: ref] + [child_spec: child_spec, ref: ref] end @paths ~w[:filter :sink :source] @@ -44,7 +49,7 @@ defmodule Membrane.TelemetryTest do @steps [:start, :stop] describe "Telemetry reports elements'" do - setup %{links: links} do + setup %{child_spec: child_spec} do ref = make_ref() spans = @@ -58,8 +63,9 @@ defmodule Membrane.TelemetryTest do ref: ref }) - pid = Testing.Pipeline.start_link_supervised!(spec: links) + pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) :ok = Testing.Pipeline.terminate(pid) + [ref: ref] end @@ -86,45 +92,87 @@ defmodule Membrane.TelemetryTest do end end - # describe "Telemetry reports pipelines'" do - # setup %{links: links} do - # ref = make_ref() + describe "Telemetry reports pipelines'" do + setup %{child_spec: child_spec} do + ref = make_ref() + + spans = + for event <- @spans, + step <- @steps do + [:membrane, :pipeline, event, step] + end + + :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ + dest: self(), + ref: ref + }) + + pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) + :ok = Testing.Pipeline.terminate(pid) + [ref: ref] + end + + test "lifecycle", %{ref: ref} do + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], value, %{}}} + assert value.monotonic_time != 0 - # spans = - # for event <- @spans, - # step <- @steps do - # [:membrane, :pipeline, event, step] - # end + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], value, %{}}} + assert value.duration > 0 - # :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ - # dest: self(), - # ref: ref - # }) + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], value, %{}}} + assert value.monotonic_time != 0 - # pid = Testing.Pipeline.start_link_supervised!(spec: links) - # :ok = Testing.Pipeline.terminate(pid) - # [ref: ref] - # end + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], value, %{}}} + assert value.duration > 0 + end - # test "lifecycle", %{ref: ref} do - # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], value, %{}}} - # assert value.system_time > 0 + test "santized state and different internal states", %{ref: ref} do + assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], _value, meta}} - # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], value, %{}}} - # assert value.duration > 0 + assert Map.has_key?(meta.old_state, :children) + refute Map.has_key?(meta.old_state, :stalker) - # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], value, %{}}} - # assert value.system_time > 0 + assert meta.old_internal_state != meta.new_internal_state + end + end - # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], value, %{}}} - # assert value.duration > 0 - # end + describe "Telemetry properly reports end of span when exception was encountered" do + setup %{child_spec: child_spec} do + ref = make_ref() - # # test "diefferent and sanitized states on start and stop", %{ref: ref} do - # # assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], value, _meta}} + spans = + [ + [:membrane, :element, :parent_notification, :start], + [:membrane, :element, :parent_notification, :stop], + [:membrane, :element, :parent_notification, :exception] + ] - # # assert Map.has_key?(value, :children) - # # refute Map.has_key?(value, :stalker) - # # end - # end + :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ + dest: self(), + ref: ref + }) + + pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) + Process.flag(:trap_exit, true) + :ok = Testing.Pipeline.notify_child(pid, :filter, :crash) + [ref: ref] + end + + test "in filter", %{ref: ref} do + assert_receive {^ref, :telemetry_ack, + {[:membrane, :element, :parent_notification, :start], _value, + %{path: [_, ":filter"]}}}, + 1000 + + assert_receive {^ref, :telemetry_ack, + {[:membrane, :element, :parent_notification, :exception], value, + %{path: [_, ":filter"]}}}, + 1000 + + assert value.duration > 0 + + refute_received {^ref, :telemetry_ack, + {[:membrane, :element, :parent_notification, :stop], _value, _}} + end + end end From 386185965d749a278eb6532854c410c72381d442 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 13 Jan 2025 17:05:25 +0100 Subject: [PATCH 10/46] Proper naming, dead code cleanup, no unnecessary optimization, crash testing --- config/config.exs | 20 ++- lib/membrane/core/element.ex | 1 - .../core/element/buffer_controller.ex | 2 +- lib/membrane/core/element/event_controller.ex | 2 +- .../core/element/stream_format_controller.ex | 2 +- .../child_life_controller/link_utils.ex | 4 +- lib/membrane/core/telemetry.ex | 159 ++++++++---------- test/membrane/telemetry_test.exs | 35 ++-- 8 files changed, 105 insertions(+), 120 deletions(-) diff --git a/config/config.exs b/config/config.exs index 6384c18aa..b38b4915e 100644 --- a/config/config.exs +++ b/config/config.exs @@ -4,12 +4,16 @@ if config_env() == :test do config :junit_formatter, include_filename?: true config :membrane_core, :telemetry_flags, - include: [ - :init, - :setup, - :terminate_request, - :playing, - :link, - :parent_notification - ] + tracked_callbacks: [ + element: [ + :handle_init, + :handle_playing, + :handle_setup, + :handle_terminate_request, + :handle_parent_notification + ], + bin: :all, + pipeline: :all + ], + metrics: :all end diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index dbe4a37f0..71a5272e3 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -182,7 +182,6 @@ defmodule Membrane.Core.Element do _from, state ) do - Telemetry.report_link(this, other) {reply, state} = PadController.handle_link(direction, this, other, params, state) {:reply, reply, state} end diff --git a/lib/membrane/core/element/buffer_controller.ex b/lib/membrane/core/element/buffer_controller.ex index de7fe8d92..348e14649 100644 --- a/lib/membrane/core/element/buffer_controller.ex +++ b/lib/membrane/core/element/buffer_controller.ex @@ -105,7 +105,7 @@ defmodule Membrane.Core.Element.BufferController do """ @spec exec_buffer_callback(Pad.ref(), [Buffer.t()], State.t()) :: State.t() def exec_buffer_callback(pad_ref, buffers, %State{type: :filter} = state) do - Telemetry.report_metric(:buffer, 1, inspect(pad_ref)) + Telemetry.report_metric(:buffer, 1, %{pad_ref: inspect(pad_ref)}) do_exec_buffer_callback(pad_ref, buffers, state) end diff --git a/lib/membrane/core/element/event_controller.ex b/lib/membrane/core/element/event_controller.ex index f97169308..28c28c814 100644 --- a/lib/membrane/core/element/event_controller.ex +++ b/lib/membrane/core/element/event_controller.ex @@ -39,7 +39,7 @@ defmodule Membrane.Core.Element.EventController do def handle_event(pad_ref, event, state) do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do - Telemetry.report_metric(:event, 1, inspect(pad_ref)) + Telemetry.report_metric(:event, 1, %{pad_ref: inspect(pad_ref)}) async? = Event.async?(event) diff --git a/lib/membrane/core/element/stream_format_controller.ex b/lib/membrane/core/element/stream_format_controller.ex index 4913a248e..9ba82fdb4 100644 --- a/lib/membrane/core/element/stream_format_controller.ex +++ b/lib/membrane/core/element/stream_format_controller.ex @@ -33,7 +33,7 @@ defmodule Membrane.Core.Element.StreamFormatController do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do %{direction: :input} = data - Telemetry.report_metric(:stream_format, 1, inspect(pad_ref)) + Telemetry.report_metric(:stream_format, 1, %{pad_ref: inspect(pad_ref)}) queue = data.input_queue diff --git a/lib/membrane/core/parent/child_life_controller/link_utils.ex b/lib/membrane/core/parent/child_life_controller/link_utils.ex index a276d721f..b6baf4230 100644 --- a/lib/membrane/core/parent/child_life_controller/link_utils.ex +++ b/lib/membrane/core/parent/child_life_controller/link_utils.ex @@ -4,7 +4,7 @@ defmodule Membrane.Core.Parent.ChildLifeController.LinkUtils do use Bunch alias Membrane.Child - alias Membrane.Core.{Bin, Message, Parent, Telemetry} + alias Membrane.Core.{Bin, Message, Parent} alias Membrane.Core.Bin.PadController alias Membrane.Core.Parent.{ @@ -274,8 +274,6 @@ defmodule Membrane.Core.Parent.ChildLifeController.LinkUtils do end def link(%Link{from: from, to: to} = link, state) do - Telemetry.report_link(from, to) - if {Membrane.Bin, :itself} in [from.child, to.child] do state else diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index d8f122bb5..6fb108d71 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -6,12 +6,31 @@ defmodule Membrane.Core.Telemetry do # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. require Logger + require Membrane.Element.Base, as: ElementBase + require Membrane.Element.WithOutputPads + require Membrane.Element.WithInputPads + require Membrane.Pipeline, as: Pipeline + require Membrane.Bin, as: Bin + + alias Membrane.Element.WithOutputPads + alias Membrane.Element.WithInputPads alias Membrane.ComponentPath + @component_modules [ + bin: [Bin], + pipeline: [Pipeline], + element: [ElementBase, WithInputPads, WithOutputPads] + ] - # TODO find a proper way to describe types of measured metrics - @possible_flags [:init, :terminate_request, :setup, :playing, :link, :parent_notification] - @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) + @possible_handlers (for {elem, mods} <- @component_modules do + mods + |> Enum.flat_map(& &1.behaviour_info(:callbacks)) + |> Enum.map(&elem(&1, 0)) + |> Enum.filter(&String.starts_with?(to_string(&1), "handle_")) + |> then(&{elem, &1}) + end) + + @config Application.compile_env(:membrane_core, :telemetry_flags, []) @public_state_keys %{ Membrane.Core.Element.State => [ @@ -74,57 +93,62 @@ defmodule Membrane.Core.Telemetry do end end - defmacro report_metric(_, _), do: nil - - defmacro report_metric(_, _, _), do: nil + for {component, handlers} <- @config[:tracked_callbacks] || [] |> IO.inspect() do + case handlers do + :all -> + def handler_measured?(unquote(component), _), do: true + + nil -> + _ = @possible_handlers + def handler_measured?(unquote(component), _), do: false + + handler_names when is_list(handler_names) -> + for event <- handler_names do + if event not in @possible_handlers[component] do + raise """ + Invalid telemetry flag: #{inspect(event)}. + Possible values for #{component} are: #{inspect(@possible_handlers[component])} + """ + end - @doc """ - Sanitizes state data by removing keys that are meant to be internal-only. - """ - @spec sanitize_state_data(struct()) :: map() - def sanitize_state_data(state = %struct{}) do - Map.take(state, @public_state_keys[struct]) + def handler_measured?(unquote(component), unquote(event)), do: true + end + end end - defp get_public_pad_name(pad) do - quote bind_quoted: [pad: pad] do - case pad.pad_ref do - {:private, direction} -> direction - {Membrane.Pad, {:private, direction}, ref} -> {Membrane.Pad, direction, ref} - _pad -> pad.pad_ref + def handler_measured?(_, _), do: false + + case @config[:metrics] do + :all -> + def metric_measured?(_metric), do: true + + nil -> + def metric_measured?(_metric), do: false + + list when is_list(list) -> + for metric <- list do + def metric_measured?(unquote(metric)), do: true end - end + + def metric_measured?(_metric), do: false end @doc """ - Reports new link connection being initialized in pipeline. + Sanitizes state data by removing keys that are meant to be internal-only. """ - @spec report_link(Membrane.Pad.ref(), Membrane.Pad.ref()) :: Macro.t() - defmacro report_link(from, to) do - event = [:membrane, :link, :new] - - value = - quote do - %{ - from: unquote(from), - to: unquote(to), - pad_from: unquote(get_public_pad_name(from)), - pad_to: unquote(get_public_pad_name(to)) - } - end - - report_event(:link, event, value) + @spec sanitize_state_data(struct()) :: map() + def sanitize_state_data(state = %struct{}) do + Map.take(state, @public_state_keys[struct]) end @doc """ - Reports an arbitrary span consistent with span format in `:telementry` + Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ @spec report_span(module(), binary(), fun()) :: any() def report_span(component_type, event_type, f) do component_type = state_module_to_atom(component_type) - event_type = handler_to_event_name(event_type) - if event_enabled?(event_type) do + if handler_measured?(component_type, event_type) do :telemetry.span( [:membrane, component_type, event_type], %{ @@ -144,7 +168,7 @@ defmodule Membrane.Core.Telemetry do }} _other -> - raise "Unexpected telemetry span result. Use Telemetry.result/3 macro" + raise "Unexpected telemetry span result. Use Telemetry.state_result/3 instead" end end ) @@ -158,64 +182,15 @@ defmodule Membrane.Core.Telemetry do defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline - defp handler_to_event_name(a) when is_atom(a), do: handler_to_event_name(Atom.to_string(a)) - defp handler_to_event_name("handle_" <> r) when is_binary(r), do: String.to_atom(r) - def state_result(res = {_actions, new_internal_state}, old_internal_state, old_state) do {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} end - defp report_event(event_type, event_name, measurement, metadata \\ quote(do: %{})) do - if event_enabled?(event_type) do - quote do - :telemetry.execute( - unquote(event_name), - unquote(measurement), - %{ - log_metadata: Logger.metadata(), - path: ComponentPath.get() - } - |> Map.merge(unquote(metadata)) - ) - end + def report_metric(metric_name, measurement, metadata \\ %{}) do + if metric_measured?(metric_name) do + :telemetry.execute([:membrane, :metric, metric_name], %{value: measurement}, metadata) else - :ok + measurement end end - - case @telemetry_flags do - :all -> - def event_enabled?(_), do: true - - exclude: _, include: _ -> - raise """ - `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]] - """ - - include: _, exclude: _ -> - raise """ - `config :membrane_core, :telemetry_flags` should contain either :all, [include:[]] or [exclude:[]] - """ - - include: inc -> - for event <- inc do - if event not in @possible_flags do - raise """ - Invalid telemetry flag: #{inspect(event)}. - Possible values are: #{inspect(@possible_flags)} - """ - end - - def event_enabled?(unquote(event)), do: true - end - - def event_enabled?(_), do: false - - exclude: exc -> - for event <- exc do - def event_enabled?(unquote(event)), do: false - end - - def event_enabled?(_), do: true - end end diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index fe2877592..7dde2d40e 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -22,7 +22,7 @@ defmodule Membrane.TelemetryTest do @impl true def handle_parent_notification(:crash, _context, state) do - raise "Crash" + raise "Intended Crash Test" {[], state} end end @@ -45,7 +45,7 @@ defmodule Membrane.TelemetryTest do end @paths ~w[:filter :sink :source] - @spans [:init, :setup, :playing, :terminate_request] + @spans [:handle_init, :handle_setup, :handle_playing, :handle_terminate_request] @steps [:start, :stop] describe "Telemetry reports elements'" do @@ -113,21 +113,30 @@ defmodule Membrane.TelemetryTest do end test "lifecycle", %{ref: ref} do - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :start], value, %{}}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :pipeline, :handle_init, :start], value, %{}}} + assert value.monotonic_time != 0 - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], value, %{}}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :pipeline, :handle_init, :stop], value, %{}}} + assert value.duration > 0 - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :start], value, %{}}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :pipeline, :handle_setup, :start], value, %{}}} + assert value.monotonic_time != 0 - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :setup, :stop], value, %{}}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :pipeline, :handle_setup, :stop], value, %{}}} + assert value.duration > 0 end test "santized state and different internal states", %{ref: ref} do - assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :init, :stop], _value, meta}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :pipeline, :handle_init, :stop], _value, meta}} assert Map.has_key?(meta.old_state, :children) refute Map.has_key?(meta.old_state, :stalker) @@ -142,9 +151,9 @@ defmodule Membrane.TelemetryTest do spans = [ - [:membrane, :element, :parent_notification, :start], - [:membrane, :element, :parent_notification, :stop], - [:membrane, :element, :parent_notification, :exception] + [:membrane, :element, :handle_parent_notification, :start], + [:membrane, :element, :handle_parent_notification, :stop], + [:membrane, :element, :handle_parent_notification, :exception] ] :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ @@ -160,19 +169,19 @@ defmodule Membrane.TelemetryTest do test "in filter", %{ref: ref} do assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, :parent_notification, :start], _value, + {[:membrane, :element, :handle_parent_notification, :start], _value, %{path: [_, ":filter"]}}}, 1000 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, :parent_notification, :exception], value, + {[:membrane, :element, :handle_parent_notification, :exception], value, %{path: [_, ":filter"]}}}, 1000 assert value.duration > 0 refute_received {^ref, :telemetry_ack, - {[:membrane, :element, :parent_notification, :stop], _value, _}} + {[:membrane, :element, :handle_parent_notification, :stop], _value, _}} end end end From 66eea5a0d8709c07079ab76f16e4f88928f98014 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 16 Jan 2025 11:51:22 +0100 Subject: [PATCH 11/46] CQ --- config/config.exs | 3 +-- lib/membrane/core/element.ex | 1 - lib/membrane/core/telemetry.ex | 33 ++++++++++++++++++-------------- lib/membrane/telemetry.ex | 7 +++---- test/membrane/telemetry_test.exs | 11 +++++++---- 5 files changed, 30 insertions(+), 25 deletions(-) diff --git a/config/config.exs b/config/config.exs index b38b4915e..82f7ce0f1 100644 --- a/config/config.exs +++ b/config/config.exs @@ -14,6 +14,5 @@ if config_env() == :test do ], bin: :all, pipeline: :all - ], - metrics: :all + ] end diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index 71a5272e3..0d4cb466e 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -154,7 +154,6 @@ defmodule Membrane.Core.Element do |> PadSpecHandler.init_pads() state = LifecycleController.handle_init(options.user_options, state) - {:ok, state, {:continue, :setup}} end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 6fb108d71..a2db39bcc 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -16,6 +16,8 @@ defmodule Membrane.Core.Telemetry do alias Membrane.Element.WithInputPads alias Membrane.ComponentPath + @type telemetry_result() :: {:telemetry_result, {any(), map(), map(), map()}} + @component_modules [ bin: [Bin], pipeline: [Pipeline], @@ -30,6 +32,8 @@ defmodule Membrane.Core.Telemetry do |> then(&{elem, &1}) end) + _ = @possible_handlers + @config Application.compile_env(:membrane_core, :telemetry_flags, []) @public_state_keys %{ @@ -93,13 +97,12 @@ defmodule Membrane.Core.Telemetry do end end - for {component, handlers} <- @config[:tracked_callbacks] || [] |> IO.inspect() do + for {component, handlers} <- @config[:tracked_callbacks] || [] do case handlers do :all -> def handler_measured?(unquote(component), _), do: true nil -> - _ = @possible_handlers def handler_measured?(unquote(component), _), do: false handler_names when is_list(handler_names) -> @@ -134,17 +137,19 @@ defmodule Membrane.Core.Telemetry do end @doc """ - Sanitizes state data by removing keys that are meant to be internal-only. + Formats a telemetry result to be used in a report_span function. """ - @spec sanitize_state_data(struct()) :: map() - def sanitize_state_data(state = %struct{}) do - Map.take(state, @public_state_keys[struct]) + @spec state_result(result, {any(), map()}, map()) :: + telemetry_result() + when result: any() + def state_result(res = {_actions, new_internal_state}, old_internal_state, old_state) do + {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} end @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ - @spec report_span(module(), binary(), fun()) :: any() + @spec report_span(module(), atom(), (-> telemetry_result())) :: any() def report_span(component_type, event_type, f) do component_type = state_module_to_atom(component_type) @@ -160,9 +165,9 @@ defmodule Membrane.Core.Telemetry do {:telemetry_result, {r, new_intstate, old_intstate, old_state}} -> {r, %{new_state: new_intstate}, %{ - old_internal_state: old_intstate, - old_state: sanitize_state_data(old_state), - new_internal_state: new_intstate, + internal_state_before: old_intstate, + state_before: sanitize_state_data(old_state), + internal_state_after: new_intstate, log_metadata: Logger.metadata(), path: ComponentPath.get() }} @@ -178,14 +183,14 @@ defmodule Membrane.Core.Telemetry do end end + defp sanitize_state_data(state = %struct{}) do + Map.take(state, @public_state_keys[struct]) + end + defp state_module_to_atom(Membrane.Core.Element.State), do: :element defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline - def state_result(res = {_actions, new_internal_state}, old_internal_state, old_state) do - {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} - end - def report_metric(metric_name, measurement, metadata \\ %{}) do if metric_measured?(metric_name) do :telemetry.execute([:membrane, :metric, metric_name], %{value: measurement}, metadata) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 53e5c6d64..0fa763a51 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -41,12 +41,12 @@ defmodule Membrane.Telemetry do config :membrane_core, telemetry_flags: [ - include: [...] | exclude: [...] | :all - ] + tracked_callbacks: [ + [:handle_setup, ...] | :all + ] Available flags are (those are of a very low overhead): * `:links` - enables new links notifications - # TODO redact * `:inits_and_terminates` - enables notifications of `init` and `terminate` events for elements/bins/pipelines @@ -70,7 +70,6 @@ defmodule Membrane.Telemetry do """ @type instrument :: :element | :bin | :pipeline - @type event :: :init | :terminate | :setup | :playback_change @type event_name :: [atom() | list(atom())] @typedoc """ * component_path - element's or bin's path diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 7dde2d40e..f8259324b 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -138,10 +138,13 @@ defmodule Membrane.TelemetryTest do assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :handle_init, :stop], _value, meta}} - assert Map.has_key?(meta.old_state, :children) - refute Map.has_key?(meta.old_state, :stalker) + # :children is a publicly exposed key + assert Map.has_key?(meta.state_before, :children) - assert meta.old_internal_state != meta.new_internal_state + # :stalker is publicly hidden + refute Map.has_key?(meta.state_before, :stalker) + + assert meta.internal_state_before != meta.internal_state_after end end @@ -167,7 +170,7 @@ defmodule Membrane.TelemetryTest do [ref: ref] end - test "in filter", %{ref: ref} do + test "in element", %{ref: ref} do assert_receive {^ref, :telemetry_ack, {[:membrane, :element, :handle_parent_notification, :start], _value, %{path: [_, ":filter"]}}}, From 0e95d43cb53f93fc6548256df9651e1b8882b4fc Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 20 Jan 2025 13:08:02 +0100 Subject: [PATCH 12/46] Comments by @FelonEkonom adressed --- lib/membrane/core/telemetry.ex | 4 ++-- lib/membrane/telemetry.ex | 39 +++++++++++--------------------- test/membrane/telemetry_test.exs | 3 +-- 3 files changed, 16 insertions(+), 30 deletions(-) diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index a2db39bcc..86150a84f 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -86,7 +86,7 @@ defmodule Membrane.Core.Telemetry do ] } - # Verify at compile time that every key is actually present in Core.*.State + # Verify at compile time that every key is actually present in Membrane.Core.*.State for {mod, keys} <- @public_state_keys do case keys -- Map.keys(struct(mod)) do [] -> @@ -103,7 +103,7 @@ defmodule Membrane.Core.Telemetry do def handler_measured?(unquote(component), _), do: true nil -> - def handler_measured?(unquote(component), _), do: false + nil handler_names when is_list(handler_names) -> for event <- handler_names do diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 0fa763a51..c3f72f571 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -10,26 +10,14 @@ defmodule Membrane.Telemetry do ## Instrumentation The following events are published by Membrane's Core with following measurement types and metadata: - * `[:membrane, :metric, :value]` - used to report metrics, such as input buffer's size inside functions, incoming events and received stream format - * Measurement: `t:metric_event_value/0` - * Metadata: `%{}` - - * `[:membrane, :link, :new]` - to report new link connection being initialized in pipeline. - * Measurement: `t:link_event_value/0` - * Metadata: `%{}` - - * `[:membrane, :pipeline | :bin | :element, :init, :start | :stop | :exception]` - to report pipeline/element/bin initialization - * Measurement: `t:init_or_terminate_event_value/0` - * Metadata: `%{log_metadata: keyword()}`, includes Logger's metadata of created component - - * `[:membrane, :pipeline | :bin | :element, :setup, :start | :stop | :exception]` - to report pipeline/element/bin setup - * Measurement: `t:init_or_terminate_event_value/0` - * Metadata: `%{log_metadata: keyword()}`, includes Logger's metadata of created component - - * `[:membrane, :pipeline | :bin | :element, :terminate, :start | :stop | :exception]` - to report pipeline/element/bin termination - * Measurement: `t:init_or_terminate_event_value/0` - * Metadata: `%{}` + * `[:membrane, :element | :bin | :pipeline, handler, :start | :stop | :exception]` - + where handler is any possible handle_* function defined for a component. + * `:start` - when the handler begins execution + * `:stop` - when the handler finishes execution + * `:exception` - when the handler crashes during execution + * `[:membrane, :metric, metric]` - + where metric is any of the available metrics (see below) ## Enabling certain metrics/events A lot of events can happen hundreds times per second such as registering that a buffer has been sent/processed. @@ -39,11 +27,15 @@ defmodule Membrane.Telemetry do To enable a particular measurement one must recompile membrane core with the following snippet put inside user's application `config.exs` file: + ``` config :membrane_core, telemetry_flags: [ tracked_callbacks: [ [:handle_setup, ...] | :all ] + metrics: [:buffer, ...] | :all + ] + ``` Available flags are (those are of a very low overhead): * `:links` - enables new links notifications @@ -51,14 +43,9 @@ defmodule Membrane.Telemetry do Additionally one can control which metric values should get measured by passing an option of format : - `{:metrics, [list of metrics]}` - - Available spans are: - * `:init` - Time spent on executing components initialization handler - * `:terminate` - Time spent on executing components termination handler - * `:setup` - Time spent on executing components setup handler - * `:playing` - Time spent on executing components playing handler + `metrics: [list of metrics]` + # TODO revise possible metrics Available metrics are: * `:buffer` - number of buffers being sent from a particular element * `:bitrate` - total number of bits carried by the buffers mentioned above diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index f8259324b..60f150325 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -1,7 +1,7 @@ defmodule Membrane.TelemetryTest do @moduledoc """ Test suite for Membrane telemetry public API. It tests if telemetry events are reported - properly for all elements and pipelines upon attaching to the :telemetry system. + properly for all metrics and spans upon attaching to the :telemetry system. """ use ExUnit.Case, async: false @@ -15,7 +15,6 @@ defmodule Membrane.TelemetryTest do def_input_pad :input, accepted_format: _any def_output_pad :output, accepted_format: _any - def_options target: [spec: pid()] @impl true def handle_buffer(_pad, _buffer, _context, state), do: {[], state} From f6b5ce1eca16db25612ff485f44d142f7b320572 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 24 Jan 2025 12:38:12 +0100 Subject: [PATCH 13/46] Comments by @FelonEkonom adressed --- lib/membrane/component_path.ex | 4 +- lib/membrane/core/bin/state.ex | 4 +- lib/membrane/core/callback_handler.ex | 12 ++-- lib/membrane/core/element.ex | 6 +- lib/membrane/core/telemetry.ex | 88 ++++----------------------- lib/membrane/telemetry.ex | 53 +++++++++++++++- test/membrane/telemetry_test.exs | 57 +++++++---------- 7 files changed, 96 insertions(+), 128 deletions(-) diff --git a/lib/membrane/component_path.ex b/lib/membrane/component_path.ex index 7ef0cfe1b..e14846cd6 100644 --- a/lib/membrane/component_path.ex +++ b/lib/membrane/component_path.ex @@ -16,7 +16,7 @@ defmodule Membrane.ComponentPath do If path had already existed then replaces it. """ - @spec set(path) :: :ok + @spec set(path()) :: :ok def set(path) do Process.put(@key, path) :ok @@ -43,6 +43,6 @@ defmodule Membrane.ComponentPath do If path has not been set, empty list is returned. """ - @spec get() :: list(String.t()) + @spec get() :: path() def get(), do: Process.get(@key, []) end diff --git a/lib/membrane/core/bin/state.ex b/lib/membrane/core/bin/state.ex index 9355018a8..2a42eefd6 100644 --- a/lib/membrane/core/bin/state.ex +++ b/lib/membrane/core/bin/state.ex @@ -16,13 +16,13 @@ defmodule Membrane.Core.Bin.State do @type t :: %__MODULE__{ internal_state: Membrane.Bin.state() | nil, - module: module, + module: module(), children: ChildrenModel.children(), subprocess_supervisor: pid(), name: Membrane.Bin.name() | nil, pads_info: PadModel.pads_info() | nil, pads_data: PadModel.pads_data() | nil, - parent_pid: pid, + parent_pid: pid(), links: %{Link.id() => Link.t()}, crash_groups: %{CrashGroup.name() => CrashGroup.t()}, synchronization: %{ diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 0600ab4d1..3a7602bb7 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -137,14 +137,10 @@ defmodule Membrane.Core.CallbackHandler do callback_result = try do - Telemetry.report_span( - state.__struct__, - callback, - fn -> - apply(module, callback, args) - |> Telemetry.state_result(internal_state, state) - end - ) + Telemetry.report_span(state.__struct__, callback, fn -> + res = {_actions, new_internal_state} = apply(module, callback, args) + Telemetry.state_result(res, internal_state, new_internal_state, state) + end) rescue e in UndefinedFunctionError -> _ignored = diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index 0d4cb466e..fce15c74b 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -43,12 +43,12 @@ defmodule Membrane.Core.Element do require Membrane.Logger @type options :: %{ - module: module, + module: module(), name: Membrane.Element.name(), - node: node | nil, + node: node() | nil, user_options: Membrane.Element.options(), sync: Sync.t(), - parent: pid, + parent: pid(), parent_clock: Clock.t(), parent_path: Membrane.ComponentPath.path(), log_metadata: Logger.metadata(), diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 86150a84f..29f688226 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -11,6 +11,7 @@ defmodule Membrane.Core.Telemetry do require Membrane.Element.WithInputPads require Membrane.Pipeline, as: Pipeline require Membrane.Bin, as: Bin + require Membrane.Telemetry alias Membrane.Element.WithOutputPads alias Membrane.Element.WithInputPads @@ -36,67 +37,6 @@ defmodule Membrane.Core.Telemetry do @config Application.compile_env(:membrane_core, :telemetry_flags, []) - @public_state_keys %{ - Membrane.Core.Element.State => [ - :subprocess_supervisor, - :terminating?, - :setup_incomplete?, - :effective_flow_control, - :resource_guard, - :initialized?, - :playback, - :module, - :type, - :name, - :internal_state, - :pads_info, - :pads_data, - :parent_pid - ], - Membrane.Core.Bin.State => [ - :internal_state, - :module, - :children, - :subprocess_supervisor, - :name, - :pads_info, - :pads_data, - :parent_pid, - :links, - :crash_groups, - :children_log_metadata, - :playback, - :initialized?, - :terminating?, - :resource_guard, - :setup_incomplete? - ], - Membrane.Core.Pipeline.State => [ - :module, - :playback, - :internal_state, - :children, - :links, - :crash_groups, - :initialized?, - :terminating?, - :resource_guard, - :setup_incomplete?, - :subprocess_supervisor - ] - } - - # Verify at compile time that every key is actually present in Membrane.Core.*.State - for {mod, keys} <- @public_state_keys do - case keys -- Map.keys(struct(mod)) do - [] -> - :ok - - other -> - raise "Public telemetry keys #{inspect(other)} absent in #{mod}" - end - end - for {component, handlers} <- @config[:tracked_callbacks] || [] do case handlers do :all -> @@ -136,16 +76,6 @@ defmodule Membrane.Core.Telemetry do def metric_measured?(_metric), do: false end - @doc """ - Formats a telemetry result to be used in a report_span function. - """ - @spec state_result(result, {any(), map()}, map()) :: - telemetry_result() - when result: any() - def state_result(res = {_actions, new_internal_state}, old_internal_state, old_state) do - {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} - end - @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ @@ -166,7 +96,7 @@ defmodule Membrane.Core.Telemetry do {r, %{new_state: new_intstate}, %{ internal_state_before: old_intstate, - state_before: sanitize_state_data(old_state), + state_before: old_state, internal_state_after: new_intstate, log_metadata: Logger.metadata(), path: ComponentPath.get() @@ -183,14 +113,20 @@ defmodule Membrane.Core.Telemetry do end end - defp sanitize_state_data(state = %struct{}) do - Map.take(state, @public_state_keys[struct]) - end - defp state_module_to_atom(Membrane.Core.Element.State), do: :element defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline + @doc """ + Formats a telemetry result to be used in a report_span function. + """ + @spec state_result(any(), internal_state, internal_state, map()) :: + telemetry_result() + when internal_state: any() + def state_result(res, old_internal_state, new_internal_state, old_state) do + {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} + end + def report_metric(metric_name, measurement, metadata \\ %{}) do if metric_measured?(metric_name) do :telemetry.execute([:membrane, :metric, metric_name], %{value: measurement}, metadata) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index c3f72f571..ba27b96e7 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -58,13 +58,64 @@ defmodule Membrane.Telemetry do @type instrument :: :element | :bin | :pipeline @type event_name :: [atom() | list(atom())] + + @type element_state :: %{ + subprocess_supervisor: pid, + terminating?: boolean(), + setup_incomplete?: boolean(), + effective_flow_control: EffectiveFlowController.effective_flow_control(), + resource_guard: Membrane.ResourceGuard.t(), + initialized?: boolean(), + playback: Membrane.Playback.t(), + module: module, + type: Element.type(), + name: Element.name(), + internal_state: Element.state() | nil, + pads_info: PadModel.pads_info() | nil, + pads_data: PadModel.pads_data() | nil, + parent_pid: pid + } + + @type bin_state :: %{ + internal_state: Membrane.Bin.state() | nil, + module: module, + children: ChildrenModel.children(), + subprocess_supervisor: pid(), + name: Membrane.Bin.name() | nil, + pads_info: PadModel.pads_info() | nil, + pads_data: PadModel.pads_data() | nil, + parent_pid: pid, + links: %{Link.id() => Link.t()}, + crash_groups: %{CrashGroup.name() => CrashGroup.t()}, + children_log_metadata: Keyword.t(), + playback: Membrane.Playback.t(), + initialized?: boolean(), + terminating?: boolean(), + resource_guard: Membrane.ResourceGuard.t(), + setup_incomplete?: boolean() + } + + @type pipeline_state :: %{ + module: module, + playback: Membrane.Playback.t(), + internal_state: Membrane.Pipeline.state() | nil, + children: ChildrenModel.children(), + links: %{Link.id() => Link.t()}, + crash_groups: %{CrashGroup.name() => CrashGroup.t()}, + initialized?: boolean(), + terminating?: boolean(), + resource_guard: Membrane.ResourceGuard.t(), + setup_incomplete?: boolean(), + subprocess_supervisor: pid() + } + @typedoc """ * component_path - element's or bin's path * metric - metric's name * value - metric's value """ @type metric_event_value :: %{ - component_path: Membrane.ComponentPath.path(), + component_path: String.t(), metric: String.t(), value: integer() } diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 60f150325..9c76896f7 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -7,9 +7,9 @@ defmodule Membrane.TelemetryTest do use ExUnit.Case, async: false alias Membrane.Testing import Membrane.ChildrenSpec + import Membrane.Testing.Assertions require Logger - @moduletag :telemetry defmodule TestFilter do use Membrane.Filter @@ -17,7 +17,7 @@ defmodule Membrane.TelemetryTest do def_output_pad :output, accepted_format: _any @impl true - def handle_buffer(_pad, _buffer, _context, state), do: {[], state} + def handle_buffer(_pad, buffer, _context, state), do: {[buffer: {:output, buffer}], state} @impl true def handle_parent_notification(:crash, _context, state) do @@ -33,14 +33,12 @@ defmodule Membrane.TelemetryTest do end setup do - ref = make_ref() - child_spec = child(:source, %Testing.Source{output: [~c"a", ~c"b", ~c"c"]}) - |> child(:filter, %TestFilter{target: self()}) + |> child(:filter, TestFilter) |> child(:sink, Testing.Sink) - [child_spec: child_spec, ref: ref] + [child_spec: child_spec] end @paths ~w[:filter :sink :source] @@ -63,6 +61,7 @@ defmodule Membrane.TelemetryTest do }) pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) + assert_end_of_stream(pid, :sink) :ok = Testing.Pipeline.terminate(pid) [ref: ref] @@ -76,17 +75,16 @@ defmodule Membrane.TelemetryTest do event = unquote(event) assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :start], value, - %{path: [_, ^element_type]}}}, + {[:membrane, :element, ^event, :start], meta, %{path: [_, ^element_type]}}}, 1000 - assert value.system_time > 0 + assert meta.system_time > 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :stop], value, %{path: [_, ^element_type]}}}, + {[:membrane, :element, ^event, :stop], meta, %{path: [_, ^element_type]}}}, 1000 - assert value.duration > 0 + assert meta.duration > 0 end end end @@ -113,37 +111,24 @@ defmodule Membrane.TelemetryTest do test "lifecycle", %{ref: ref} do assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_init, :start], value, %{}}} + {[:membrane, :pipeline, :handle_init, :start], meta, %{}}} - assert value.monotonic_time != 0 + assert meta.monotonic_time != 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_init, :stop], value, %{}}} + {[:membrane, :pipeline, :handle_init, :stop], meta, %{}}} - assert value.duration > 0 + assert meta.duration > 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_setup, :start], value, %{}}} + {[:membrane, :pipeline, :handle_setup, :start], meta, %{}}} - assert value.monotonic_time != 0 + assert meta.monotonic_time != 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_setup, :stop], value, %{}}} - - assert value.duration > 0 - end - - test "santized state and different internal states", %{ref: ref} do - assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_init, :stop], _value, meta}} - - # :children is a publicly exposed key - assert Map.has_key?(meta.state_before, :children) - - # :stalker is publicly hidden - refute Map.has_key?(meta.state_before, :stalker) + {[:membrane, :pipeline, :handle_setup, :stop], meta, %{}}} - assert meta.internal_state_before != meta.internal_state_after + assert meta.duration > 0 end end @@ -171,19 +156,19 @@ defmodule Membrane.TelemetryTest do test "in element", %{ref: ref} do assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, :handle_parent_notification, :start], _value, + {[:membrane, :element, :handle_parent_notification, :start], _meta, %{path: [_, ":filter"]}}}, 1000 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, :handle_parent_notification, :exception], value, + {[:membrane, :element, :handle_parent_notification, :exception], meta, %{path: [_, ":filter"]}}}, 1000 - assert value.duration > 0 + assert meta.duration > 0 refute_received {^ref, :telemetry_ack, - {[:membrane, :element, :handle_parent_notification, :stop], _value, _}} + {[:membrane, :element, :handle_parent_notification, :stop], _meta, _}} end end end From db199953090ee81a3a1bb455485cfd10fa4d458a Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 24 Jan 2025 14:52:01 +0100 Subject: [PATCH 14/46] Old metrics revamped and adjusted to new telemetry implementation --- config/config.exs | 3 +- lib/membrane/component_path.ex | 1 + lib/membrane/core/callback_handler.ex | 13 ++- lib/membrane/core/element/action_handler.ex | 5 +- .../core/element/buffer_controller.ex | 3 +- lib/membrane/core/element/event_controller.ex | 2 +- .../manual_flow_controller/input_queue.ex | 4 +- lib/membrane/core/element/state.ex | 8 +- .../core/element/stream_format_controller.ex | 2 +- .../child_life_controller/link_utils.ex | 3 + lib/membrane/core/pipeline/state.ex | 2 +- lib/membrane/core/telemetry.ex | 56 +++++++++++-- lib/membrane/telemetry.ex | 44 +++++------ test/membrane/telemetry_test.exs | 79 ++++++++++++++++++- 14 files changed, 176 insertions(+), 49 deletions(-) diff --git a/config/config.exs b/config/config.exs index 82f7ce0f1..b38b4915e 100644 --- a/config/config.exs +++ b/config/config.exs @@ -14,5 +14,6 @@ if config_env() == :test do ], bin: :all, pipeline: :all - ] + ], + metrics: :all end diff --git a/lib/membrane/component_path.ex b/lib/membrane/component_path.ex index e14846cd6..31eb8be83 100644 --- a/lib/membrane/component_path.ex +++ b/lib/membrane/component_path.ex @@ -8,6 +8,7 @@ defmodule Membrane.ComponentPath do @typedoc @moduledoc @type path :: list(String.t()) + @type formatted_path :: String.t() @key :membrane_path diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 3a7602bb7..8a8521320 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -137,10 +137,15 @@ defmodule Membrane.Core.CallbackHandler do callback_result = try do - Telemetry.report_span(state.__struct__, callback, fn -> - res = {_actions, new_internal_state} = apply(module, callback, args) - Telemetry.state_result(res, internal_state, new_internal_state, state) - end) + Telemetry.component_span( + state.__struct__, + callback, + fn -> + res = {_actions, new_internal_state} = apply(module, callback, args) + + Telemetry.state_result(res, internal_state, new_internal_state, state) + end + ) rescue e in UndefinedFunctionError -> _ignored = diff --git a/lib/membrane/core/element/action_handler.ex b/lib/membrane/core/element/action_handler.ex index fafd2fd58..c238e7d36 100644 --- a/lib/membrane/core/element/action_handler.ex +++ b/lib/membrane/core/element/action_handler.ex @@ -27,7 +27,7 @@ defmodule Membrane.Core.Element.ActionHandler do StreamFormatController } - alias Membrane.Core.{Events, TimerController} + alias Membrane.Core.{Events, TimerController, Telemetry} alias Membrane.Element.Action require Membrane.Core.Child.PadModel, as: PadModel @@ -316,6 +316,9 @@ defmodule Membrane.Core.Element.ActionHandler do "Sending #{length(buffers)} buffer(s) through pad #{inspect(pad_ref)}" ) + Telemetry.report_buffer(length(buffers)) + Telemetry.report_bitrate(buffers) + Enum.each(buffers, fn %Buffer{} -> :ok value -> raise ElementError, "Tried to send an invalid buffer #{inspect(value)}" diff --git a/lib/membrane/core/element/buffer_controller.ex b/lib/membrane/core/element/buffer_controller.ex index 348e14649..4278226b5 100644 --- a/lib/membrane/core/element/buffer_controller.ex +++ b/lib/membrane/core/element/buffer_controller.ex @@ -105,7 +105,8 @@ defmodule Membrane.Core.Element.BufferController do """ @spec exec_buffer_callback(Pad.ref(), [Buffer.t()], State.t()) :: State.t() def exec_buffer_callback(pad_ref, buffers, %State{type: :filter} = state) do - Telemetry.report_metric(:buffer, 1, %{pad_ref: inspect(pad_ref)}) + Telemetry.report_buffer(length(List.wrap(buffers))) + Telemetry.report_bitrate(buffers) do_exec_buffer_callback(pad_ref, buffers, state) end diff --git a/lib/membrane/core/element/event_controller.ex b/lib/membrane/core/element/event_controller.ex index 28c28c814..a31319b77 100644 --- a/lib/membrane/core/element/event_controller.ex +++ b/lib/membrane/core/element/event_controller.ex @@ -39,7 +39,7 @@ defmodule Membrane.Core.Element.EventController do def handle_event(pad_ref, event, state) do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do - Telemetry.report_metric(:event, 1, %{pad_ref: inspect(pad_ref)}) + Telemetry.report_event(%{pad_ref: inspect(pad_ref)}) async? = Event.async?(event) diff --git a/lib/membrane/core/element/manual_flow_controller/input_queue.ex b/lib/membrane/core/element/manual_flow_controller/input_queue.ex index 76c8432ea..1921f0826 100644 --- a/lib/membrane/core/element/manual_flow_controller/input_queue.ex +++ b/lib/membrane/core/element/manual_flow_controller/input_queue.ex @@ -13,6 +13,7 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do alias Membrane.Event alias Membrane.Pad alias Membrane.StreamFormat + alias Membrane.Core.Telemetry require Membrane.Core.Stalker, as: Stalker require Membrane.Logger @@ -130,9 +131,10 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do def store(input_queue, :buffer, v), do: store(input_queue, :buffers, [v]) - def store(%__MODULE__{q: q, size: _size} = input_queue, type, v) + def store(%__MODULE__{q: q, size: size} = input_queue, type, v) when type in @non_buf_types do "Storing #{type}" |> mk_log(input_queue) |> Membrane.Logger.debug_verbose() + Telemetry.report_store(size, input_queue.log_tag) %__MODULE__{input_queue | q: q |> @qe.push({:non_buffer, type, v})} end diff --git a/lib/membrane/core/element/state.ex b/lib/membrane/core/element/state.ex index 1c4d2d898..0e03e4038 100644 --- a/lib/membrane/core/element/state.ex +++ b/lib/membrane/core/element/state.ex @@ -13,16 +13,14 @@ defmodule Membrane.Core.Element.State do alias Membrane.Core.Element.EffectiveFlowController alias Membrane.Core.Timer - require Membrane.Pad - @type t :: %__MODULE__{ - module: module, + module: module(), type: Element.type(), name: Element.name(), internal_state: Element.state() | nil, pads_info: PadModel.pads_info() | nil, pads_data: PadModel.pads_data() | nil, - parent_pid: pid, + parent_pid: pid(), delay_demands?: boolean(), delayed_demands: MapSet.t({Pad.ref(), :supply | :redemand}), handle_demand_loop_counter: non_neg_integer(), @@ -38,7 +36,7 @@ defmodule Membrane.Core.Element.State do playback: Membrane.Playback.t(), playback_queue: Membrane.Core.Element.PlaybackQueue.t(), resource_guard: Membrane.ResourceGuard.t(), - subprocess_supervisor: pid, + subprocess_supervisor: pid(), terminating?: boolean(), setup_incomplete?: boolean(), effective_flow_control: EffectiveFlowController.effective_flow_control(), diff --git a/lib/membrane/core/element/stream_format_controller.ex b/lib/membrane/core/element/stream_format_controller.ex index 9ba82fdb4..bbfff8a0e 100644 --- a/lib/membrane/core/element/stream_format_controller.ex +++ b/lib/membrane/core/element/stream_format_controller.ex @@ -33,7 +33,7 @@ defmodule Membrane.Core.Element.StreamFormatController do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do %{direction: :input} = data - Telemetry.report_metric(:stream_format, 1, %{pad_ref: inspect(pad_ref)}) + Telemetry.report_stream_format(%{pad_ref: inspect(pad_ref)}) queue = data.input_queue diff --git a/lib/membrane/core/parent/child_life_controller/link_utils.ex b/lib/membrane/core/parent/child_life_controller/link_utils.ex index b6baf4230..a7d1a9a41 100644 --- a/lib/membrane/core/parent/child_life_controller/link_utils.ex +++ b/lib/membrane/core/parent/child_life_controller/link_utils.ex @@ -5,6 +5,7 @@ defmodule Membrane.Core.Parent.ChildLifeController.LinkUtils do alias Membrane.Child alias Membrane.Core.{Bin, Message, Parent} + alias Membrane.Core.Telemetry alias Membrane.Core.Bin.PadController alias Membrane.Core.Parent.{ @@ -274,6 +275,8 @@ defmodule Membrane.Core.Parent.ChildLifeController.LinkUtils do end def link(%Link{from: from, to: to} = link, state) do + Telemetry.report_link(from, to) + if {Membrane.Bin, :itself} in [from.child, to.child] do state else diff --git a/lib/membrane/core/pipeline/state.ex b/lib/membrane/core/pipeline/state.ex index 37f24ea2d..cd9c2c9eb 100644 --- a/lib/membrane/core/pipeline/state.ex +++ b/lib/membrane/core/pipeline/state.ex @@ -13,7 +13,7 @@ defmodule Membrane.Core.Pipeline.State do alias Membrane.Core.Timer @type t :: %__MODULE__{ - module: module, + module: module(), playback: Membrane.Playback.t(), internal_state: Membrane.Pipeline.state() | nil, children: ChildrenModel.children(), diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 29f688226..0b55a8ff8 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -13,6 +13,7 @@ defmodule Membrane.Core.Telemetry do require Membrane.Bin, as: Bin require Membrane.Telemetry + alias Membrane.Pad alias Membrane.Element.WithOutputPads alias Membrane.Element.WithInputPads alias Membrane.ComponentPath @@ -79,8 +80,8 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ - @spec report_span(module(), atom(), (-> telemetry_result())) :: any() - def report_span(component_type, event_type, f) do + @spec component_span(module(), atom(), (-> telemetry_result())) :: any() + def component_span(component_type, event_type, f) do component_type = state_module_to_atom(component_type) if handler_measured?(component_type, event_type) do @@ -88,7 +89,8 @@ defmodule Membrane.Core.Telemetry do [:membrane, component_type, event_type], %{ log_metadata: Logger.metadata(), - path: ComponentPath.get() + path: ComponentPath.get(), + component_path: ComponentPath.get_formatted() }, fn -> case f.() do @@ -113,10 +115,6 @@ defmodule Membrane.Core.Telemetry do end end - defp state_module_to_atom(Membrane.Core.Element.State), do: :element - defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin - defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline - @doc """ Formats a telemetry result to be used in a report_span function. """ @@ -127,6 +125,46 @@ defmodule Membrane.Core.Telemetry do {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} end + def report_event(meta \\ %{}), do: report_metric(:event, 1, meta) + def report_link(), do: report_metric(:link, 1) + def report_store(size, log_tag), do: report_metric(:store, size, %{log_tag: log_tag}) + def report_stream_format(meta \\ %{}), do: report_metric(:stream_format, 1, meta) + + def report_buffer(length, meta \\ %{}) + + def report_buffer(length, meta) when is_integer(length), + do: report_metric(:buffer, length, meta) + + def report_buffer(buffers, meta) do + if metric_measured?(:buffer) do + value = length(List.wrap(buffers)) + :telemetry.execute([:membrane, :metric, :buffer], %{value: value}, meta) + end + end + + def report_bitrate(buffers, meta \\ %{}) do + if metric_measured?(:bitrate) do + value = Enum.reduce(List.wrap(buffers), 0, &(&2 + Membrane.Payload.size(&1.payload))) + :telemetry.execute([:membrane, :metric, :bitrate], %{value: value}, meta) + end + end + + def report_link(from, to) do + if metric_measured?(:link) do + meta = %{ + parent_path: ComponentPath.get_formatted(), + from: inspect(from.child), + to: inspect(to.child), + pad_from: Pad.name_by_ref(from.pad_ref) |> inspect(), + pad_to: Pad.name_by_ref(to.pad_ref) |> inspect() + } + + # For backwards compatibility + :telemetry.execute([:membrane, :link, :new], %{from: from, to: to}, meta) + :telemetry.execute([:membrane, :metric, :link], %{from: from, to: to}, meta) + end + end + def report_metric(metric_name, measurement, metadata \\ %{}) do if metric_measured?(metric_name) do :telemetry.execute([:membrane, :metric, metric_name], %{value: measurement}, metadata) @@ -134,4 +172,8 @@ defmodule Membrane.Core.Telemetry do measurement end end + + defp state_module_to_atom(Membrane.Core.Element.State), do: :element + defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin + defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline end diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index ba27b96e7..56e1b6439 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -53,58 +53,62 @@ defmodule Membrane.Telemetry do * `:stream_format` - indicates that given element has received new stream format, value always equals '1' * `:event` - indicates that given element has received a new event, value always equals '1' * `:store` - reports the current size of a input buffer when storing a new buffer - * `:take_and_demand` - reports the current size of a input buffer when taking buffers and making a new demand """ + alias Membrane.{Bin, ComponentPath, Element, Pipeline, Playback, ResourceGuard} + alias Membrane.Core.Child.PadModel + alias Membrane.Core.Element.EffectiveFlowController + alias Membrane.Core.Parent.{ChildrenModel, CrashGroup, Link} + @type instrument :: :element | :bin | :pipeline @type event_name :: [atom() | list(atom())] @type element_state :: %{ - subprocess_supervisor: pid, + subprocess_supervisor: pid(), terminating?: boolean(), setup_incomplete?: boolean(), effective_flow_control: EffectiveFlowController.effective_flow_control(), - resource_guard: Membrane.ResourceGuard.t(), + resource_guard: ResourceGuard.t(), initialized?: boolean(), - playback: Membrane.Playback.t(), - module: module, + playback: Playback.t(), + module: module(), type: Element.type(), name: Element.name(), internal_state: Element.state() | nil, pads_info: PadModel.pads_info() | nil, pads_data: PadModel.pads_data() | nil, - parent_pid: pid + parent_pid: pid() } @type bin_state :: %{ - internal_state: Membrane.Bin.state() | nil, - module: module, + internal_state: Bin.state() | nil, + module: module(), children: ChildrenModel.children(), subprocess_supervisor: pid(), - name: Membrane.Bin.name() | nil, + name: Bin.name() | nil, pads_info: PadModel.pads_info() | nil, pads_data: PadModel.pads_data() | nil, - parent_pid: pid, + parent_pid: pid(), links: %{Link.id() => Link.t()}, crash_groups: %{CrashGroup.name() => CrashGroup.t()}, children_log_metadata: Keyword.t(), - playback: Membrane.Playback.t(), + playback: Playback.t(), initialized?: boolean(), terminating?: boolean(), - resource_guard: Membrane.ResourceGuard.t(), + resource_guard: ResourceGuard.t(), setup_incomplete?: boolean() } @type pipeline_state :: %{ - module: module, - playback: Membrane.Playback.t(), - internal_state: Membrane.Pipeline.state() | nil, + module: module(), + playback: Playback.t(), + internal_state: Pipeline.state() | nil, children: ChildrenModel.children(), links: %{Link.id() => Link.t()}, crash_groups: %{CrashGroup.name() => CrashGroup.t()}, initialized?: boolean(), terminating?: boolean(), - resource_guard: Membrane.ResourceGuard.t(), + resource_guard: ResourceGuard.t(), setup_incomplete?: boolean(), subprocess_supervisor: pid() } @@ -115,18 +119,12 @@ defmodule Membrane.Telemetry do * value - metric's value """ @type metric_event_value :: %{ + path: ComponentPath.path(), component_path: String.t(), metric: String.t(), value: integer() } - @typedoc """ - * path - element's path - """ - @type init_or_terminate_event_value :: %{ - path: Membrane.ComponentPath.path() - } - @typedoc """ * parent_path - process path of link's parent * from - from element name diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 9c76896f7..c84987742 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -5,9 +5,11 @@ defmodule Membrane.TelemetryTest do """ use ExUnit.Case, async: false - alias Membrane.Testing + + import ExUnit.CaptureLog import Membrane.ChildrenSpec import Membrane.Testing.Assertions + alias Membrane.Testing require Logger defmodule TestFilter do @@ -34,7 +36,7 @@ defmodule Membrane.TelemetryTest do setup do child_spec = - child(:source, %Testing.Source{output: [~c"a", ~c"b", ~c"c"]}) + child(:source, %Testing.Source{output: ["a", "b", "c"]}) |> child(:filter, TestFilter) |> child(:sink, Testing.Sink) @@ -150,7 +152,11 @@ defmodule Membrane.TelemetryTest do pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) Process.flag(:trap_exit, true) - :ok = Testing.Pipeline.notify_child(pid, :filter, :crash) + + capture_log(fn -> + :ok = Testing.Pipeline.notify_child(pid, :filter, :crash) + end) + [ref: ref] end @@ -171,4 +177,71 @@ defmodule Membrane.TelemetryTest do {[:membrane, :element, :handle_parent_notification, :stop], _meta, _}} end end + + describe "Telemetry properly reports following metrics: " do + test "Link", %{child_spec: child_spec} do + ref = setup_pipeline_for(:link, child_spec) + + assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :link], _value, _metadata}} + end + + # test "Store", %{child_spec: child_spec} do + # ref = setup_pipeline_for(:store, child_spec) + + # assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :store], _value, _metadata}}, + # 1000 + # end + + # test "Take", %{child_spec: child_spec} do + # ref = setup_pipeline_for(:take, child_spec) + + # assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :take], _value, _metadata}} + # end + + test "Stream Format", %{child_spec: child_spec} do + ref = setup_pipeline_for(:stream_format, child_spec) + + assert_receive {^ref, :telemetry_ack, + {[:membrane, :metric, :stream_format], _value, _metadata}} + end + + test "Buffer", %{child_spec: child_spec} do + ref = setup_pipeline_for(:buffer, child_spec) + + assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :buffer], _value, _metadata}} + end + + test "Bitrate", %{child_spec: child_spec} do + ref = setup_pipeline_for(:bitrate, child_spec) + + assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :bitrate], _value, _metadata}} + end + + test "Event", %{child_spec: child_spec} do + ref = setup_pipeline_for(:event, child_spec) + + assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :event], _value, _metadata}} + end + + test "Queue Length", %{child_spec: child_spec} do + ref = setup_pipeline_for(:queue_len, child_spec) + + assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :queue_len], _value, _metadata}} + end + end + + defp setup_pipeline_for(metric, child_spec) do + ref = make_ref() + + :telemetry.attach( + ref, + [:membrane, :metric, metric], + &TelemetryListener.handle_event/4, + %{dest: self(), ref: ref} + ) + + Testing.Pipeline.start_link_supervised!(spec: child_spec) + + ref + end end From a442758df23a89183681bc0209282d0828b5eaf9 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 27 Jan 2025 10:42:28 +0100 Subject: [PATCH 15/46] Small changes to Telemetry.report_buffer/2 --- lib/membrane/core/element/action_handler.ex | 2 +- lib/membrane/core/element/buffer_controller.ex | 2 +- lib/membrane/core/telemetry.ex | 2 +- lib/membrane/telemetry.ex | 7 +------ 4 files changed, 4 insertions(+), 9 deletions(-) diff --git a/lib/membrane/core/element/action_handler.ex b/lib/membrane/core/element/action_handler.ex index c238e7d36..517b95c83 100644 --- a/lib/membrane/core/element/action_handler.ex +++ b/lib/membrane/core/element/action_handler.ex @@ -316,7 +316,7 @@ defmodule Membrane.Core.Element.ActionHandler do "Sending #{length(buffers)} buffer(s) through pad #{inspect(pad_ref)}" ) - Telemetry.report_buffer(length(buffers)) + Telemetry.report_buffer(buffers) Telemetry.report_bitrate(buffers) Enum.each(buffers, fn diff --git a/lib/membrane/core/element/buffer_controller.ex b/lib/membrane/core/element/buffer_controller.ex index 4278226b5..8195ef037 100644 --- a/lib/membrane/core/element/buffer_controller.ex +++ b/lib/membrane/core/element/buffer_controller.ex @@ -105,7 +105,7 @@ defmodule Membrane.Core.Element.BufferController do """ @spec exec_buffer_callback(Pad.ref(), [Buffer.t()], State.t()) :: State.t() def exec_buffer_callback(pad_ref, buffers, %State{type: :filter} = state) do - Telemetry.report_buffer(length(List.wrap(buffers))) + Telemetry.report_buffer(buffers) Telemetry.report_bitrate(buffers) do_exec_buffer_callback(pad_ref, buffers, state) diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 0b55a8ff8..fa4bee4a6 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -138,7 +138,7 @@ defmodule Membrane.Core.Telemetry do def report_buffer(buffers, meta) do if metric_measured?(:buffer) do value = length(List.wrap(buffers)) - :telemetry.execute([:membrane, :metric, :buffer], %{value: value}, meta) + report_buffer(value, meta) end end diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 56e1b6439..68a50feb7 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -37,16 +37,11 @@ defmodule Membrane.Telemetry do ] ``` - Available flags are (those are of a very low overhead): - * `:links` - enables new links notifications - * `:inits_and_terminates` - enables notifications of `init` and `terminate` events for elements/bins/pipelines - - Additionally one can control which metric values should get measured by passing an option of format : `metrics: [list of metrics]` - # TODO revise possible metrics Available metrics are: + * `:link` - reports the number of links created in the pipeline * `:buffer` - number of buffers being sent from a particular element * `:bitrate` - total number of bits carried by the buffers mentioned above * `:queue_len` - number of messages in element's message queue during GenServer's `handle_info` invocation From f970d20b91f207b034c78fa780a2adf18ea474cc Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 28 Jan 2025 16:14:17 +0100 Subject: [PATCH 16/46] Legacy telemetry revived and rerouted based on config usage --- config/config.exs | 20 +- lib/membrane/core/bin.ex | 5 +- lib/membrane/core/element.ex | 9 +- lib/membrane/core/element/action_handler.ex | 6 +- .../core/element/buffer_controller.ex | 7 +- lib/membrane/core/element/event_controller.ex | 2 +- .../core/element/stream_format_controller.ex | 2 +- lib/membrane/core/legacy_telemetry.ex | 185 ++++++++++++++++++ lib/membrane/core/pipeline.ex | 7 + lib/membrane/core/telemetry.ex | 179 +++++++++++------ lib/membrane/telemetry.ex | 27 ++- test/membrane/telemetry_test.exs | 67 +++---- 12 files changed, 390 insertions(+), 126 deletions(-) create mode 100644 lib/membrane/core/legacy_telemetry.ex diff --git a/config/config.exs b/config/config.exs index b38b4915e..3ee97d6bb 100644 --- a/config/config.exs +++ b/config/config.exs @@ -15,5 +15,23 @@ if config_env() == :test do bin: :all, pipeline: :all ], - metrics: :all + events: :all + + # config to legacy telemetry + # config :membrane_core, :telemetry_flags, [ + # :report_init, + # :report_terminate, + # :report_buffer, + # :report_queue, + # :report_link, + # metrics: [ + # :buffer, + # :bitrate, + # :queue_len, + # :stream_format, + # :event, + # :store, + # :take_and_demand + # ] + # ] end diff --git a/lib/membrane/core/bin.ex b/lib/membrane/core/bin.ex index e88bf8b69..8a21ff91b 100644 --- a/lib/membrane/core/bin.ex +++ b/lib/membrane/core/bin.ex @@ -20,7 +20,7 @@ defmodule Membrane.Core.Bin do require Membrane.Core.Utils, as: Utils require Membrane.Core.Message - require Membrane.Core.Telemetry + require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry require Membrane.Logger @type options :: %{ @@ -126,6 +126,9 @@ defmodule Membrane.Core.Bin do {:ok, resource_guard} = SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) + LegacyTelemetry.report_init(:bin) + ResourceGuard.register(resource_guard, fn -> LegacyTelemetry.report_terminate(:bin) end) + state = %State{ module: module, diff --git a/lib/membrane/core/element.ex b/lib/membrane/core/element.ex index fce15c74b..3631119e9 100644 --- a/lib/membrane/core/element.ex +++ b/lib/membrane/core/element.ex @@ -40,6 +40,7 @@ defmodule Membrane.Core.Element do require Membrane.Core.Message, as: Message require Membrane.Core.Stalker, as: Stalker require Membrane.Core.Telemetry, as: Telemetry + require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry require Membrane.Logger @type options :: %{ @@ -118,6 +119,9 @@ defmodule Membrane.Core.Element do {:ok, resource_guard} = SubprocessSupervisor.start_utility(options.subprocess_supervisor, {ResourceGuard, self()}) + LegacyTelemetry.report_init(:element) + ResourceGuard.register(resource_guard, fn -> LegacyTelemetry.report_terminate(:element) end) + self_pid = self() Stalker.register_metric_function(:message_queue_length, fn -> @@ -202,10 +206,7 @@ defmodule Membrane.Core.Element do @impl GenServer def handle_info(message, state) do Utils.log_on_error do - Telemetry.report_metric( - :queue_len, - :erlang.process_info(self(), :message_queue_len) |> elem(1) - ) + Telemetry.report_queue_len(self()) do_handle_info(message, state) end diff --git a/lib/membrane/core/element/action_handler.ex b/lib/membrane/core/element/action_handler.ex index 517b95c83..e4eb82b7f 100644 --- a/lib/membrane/core/element/action_handler.ex +++ b/lib/membrane/core/element/action_handler.ex @@ -27,12 +27,14 @@ defmodule Membrane.Core.Element.ActionHandler do StreamFormatController } - alias Membrane.Core.{Events, TimerController, Telemetry} + alias Membrane.Core.{Events, TimerController} alias Membrane.Element.Action require Membrane.Core.Child.PadModel, as: PadModel require Membrane.Core.Message, as: Message require Membrane.Logger + require Membrane.Core.Telemetry, as: Telemetry + require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry @impl CallbackHandler def transform_actions(actions, _callback, _handler_params, state) do @@ -316,8 +318,8 @@ defmodule Membrane.Core.Element.ActionHandler do "Sending #{length(buffers)} buffer(s) through pad #{inspect(pad_ref)}" ) + LegacyTelemetry.report_bitrate(buffers) Telemetry.report_buffer(buffers) - Telemetry.report_bitrate(buffers) Enum.each(buffers, fn %Buffer{} -> :ok diff --git a/lib/membrane/core/element/buffer_controller.ex b/lib/membrane/core/element/buffer_controller.ex index 8195ef037..4a53831f6 100644 --- a/lib/membrane/core/element/buffer_controller.ex +++ b/lib/membrane/core/element/buffer_controller.ex @@ -6,7 +6,7 @@ defmodule Membrane.Core.Element.BufferController do use Bunch alias Membrane.{Buffer, Pad} - alias Membrane.Core.{CallbackHandler, Telemetry} + alias Membrane.Core.CallbackHandler alias Membrane.Core.Child.PadModel alias Membrane.Core.Element.{ @@ -24,7 +24,8 @@ defmodule Membrane.Core.Element.BufferController do alias Membrane.Core.Telemetry require Membrane.Core.Child.PadModel - require Membrane.Core.Telemetry + require Membrane.Core.Telemetry, as: Telemetry + require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry @doc """ Handles incoming buffer: either stores it in InputQueue, or executes element's @@ -105,8 +106,8 @@ defmodule Membrane.Core.Element.BufferController do """ @spec exec_buffer_callback(Pad.ref(), [Buffer.t()], State.t()) :: State.t() def exec_buffer_callback(pad_ref, buffers, %State{type: :filter} = state) do + LegacyTelemetry.report_bitrate(buffers) Telemetry.report_buffer(buffers) - Telemetry.report_bitrate(buffers) do_exec_buffer_callback(pad_ref, buffers, state) end diff --git a/lib/membrane/core/element/event_controller.ex b/lib/membrane/core/element/event_controller.ex index a31319b77..c3e3a76c4 100644 --- a/lib/membrane/core/element/event_controller.ex +++ b/lib/membrane/core/element/event_controller.ex @@ -39,7 +39,7 @@ defmodule Membrane.Core.Element.EventController do def handle_event(pad_ref, event, state) do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do - Telemetry.report_event(%{pad_ref: inspect(pad_ref)}) + Telemetry.report_incoming_event(%{pad_ref: inspect(pad_ref)}) async? = Event.async?(event) diff --git a/lib/membrane/core/element/stream_format_controller.ex b/lib/membrane/core/element/stream_format_controller.ex index bbfff8a0e..cb4f4f7cf 100644 --- a/lib/membrane/core/element/stream_format_controller.ex +++ b/lib/membrane/core/element/stream_format_controller.ex @@ -33,7 +33,7 @@ defmodule Membrane.Core.Element.StreamFormatController do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do %{direction: :input} = data - Telemetry.report_stream_format(%{pad_ref: inspect(pad_ref)}) + Telemetry.report_stream_format(stream_format, %{pad_ref: inspect(pad_ref)}) queue = data.input_queue diff --git a/lib/membrane/core/legacy_telemetry.ex b/lib/membrane/core/legacy_telemetry.ex new file mode 100644 index 000000000..92058e7aa --- /dev/null +++ b/lib/membrane/core/legacy_telemetry.ex @@ -0,0 +1,185 @@ +defmodule Membrane.Core.LegacyTelemetry do + @moduledoc false + # This module provides a way to gather events from running Membrane components, as well + # as exposing these events in a format idiomatic to [Telemetry](https://hexdocs.pm/telemetry/) + # library. It uses compile time flags from `config.exs` to determine which events should be + # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. + + alias Membrane.ComponentPath + + require Membrane.Pad + + @telemetry_flags Application.compile_env(:membrane_core, :telemetry_flags, []) + + @doc """ + Reports metrics such as input buffer's size inside functions, incoming events and received stream format. + """ + def report_metric(metric, value, log_tag \\ nil) do + event = + quote do + [:membrane, :metric, :value] + end + + value = + quote do + %{ + component_path: ComponentPath.get_formatted() <> "/" <> (unquote(log_tag) || ""), + metric: Atom.to_string(unquote(metric)), + value: unquote(value) + } + end + + report_event( + event, + value, + Keyword.get(@telemetry_flags, :metrics, []) |> Enum.find(&(&1 == metric)) != nil + ) + end + + @doc """ + Given list of buffers (or a single buffer) calculates total size of their payloads in bits + and reports it. + """ + def report_bitrate(buffers) do + event = + quote do + [:membrane, :metric, :value] + end + + value = + quote do + %{ + component_path: ComponentPath.get_formatted() <> "/", + metric: "bitrate", + value: + 8 * + Enum.reduce( + List.wrap(unquote(buffers)), + 0, + &(Membrane.Core.LegacyTelemetry.get_payload_size(&1.payload) + &2) + ) + } + end + + report_event( + event, + value, + Keyword.get(@telemetry_flags, :metrics, []) |> Enum.find(&(&1 == :bitrate)) != nil + ) + end + + def get_payload_size(payload) when is_bitstring(payload) do + Membrane.Payload.size(payload) + end + + def get_payload_size(_payload), do: 0 + + @doc false + @spec __get_public_pad_name__(Membrane.Pad.ref()) :: Membrane.Pad.ref() + def __get_public_pad_name__(pad) do + case pad do + {:private, direction} -> direction + {Membrane.Pad, {:private, direction}, ref} -> {Membrane.Pad, direction, ref} + _pad -> pad + end + end + + @doc """ + Reports new link connection being initialized in pipeline. + """ + def report_link(from, to) do + event = + quote do + [:membrane, :link, :new] + end + + value = + quote do + %{ + parent_path: Membrane.ComponentPath.get_formatted(), + from: inspect(unquote(from).child), + to: inspect(unquote(to).child), + pad_from: + Membrane.Core.LegacyTelemetry.__get_public_pad_name__(unquote(from).pad_ref) + |> inspect(), + pad_to: + Membrane.Core.LegacyTelemetry.__get_public_pad_name__(unquote(to).pad_ref) + |> inspect() + } + end + + report_event(event, value, Enum.find(@telemetry_flags, &(&1 == :links)) != nil) + end + + @doc """ + Reports a pipeline/bin/element initialization. + """ + def report_init(type) when type in [:pipeline, :bin, :element] do + event = + quote do + [:membrane, unquote(type), :init] + end + + value = + quote do + %{path: ComponentPath.get_formatted()} + end + + metadata = + quote do + %{log_metadata: Logger.metadata()} + end + + report_event( + event, + value, + Enum.find(@telemetry_flags, &(&1 == :inits_and_terminates)) != nil, + metadata + ) + end + + @doc """ + Reports a pipeline/bin/element termination. + """ + def report_terminate(type) when type in [:pipeline, :bin, :element] do + event = + quote do + [:membrane, unquote(type), :terminate] + end + + value = + quote do + %{path: ComponentPath.get_formatted()} + end + + report_event( + event, + value, + Enum.find(@telemetry_flags, &(&1 == :inits_and_terminates)) != nil + ) + end + + # Conditional event reporting of telemetry events + defp report_event(event_name, measurement, enable, metadata \\ nil) do + if enable do + quote do + :telemetry.execute( + unquote(event_name), + unquote(measurement), + unquote(metadata) || %{} + ) + end + else + # A hack to suppress the 'unused variable' warnings + quote do + _fn = fn -> + _unused = unquote(event_name) + _unused = unquote(measurement) + _unused = unquote(metadata) + end + + :ok + end + end + end +end diff --git a/lib/membrane/core/pipeline.ex b/lib/membrane/core/pipeline.ex index 850e82537..a20a5bfe1 100644 --- a/lib/membrane/core/pipeline.ex +++ b/lib/membrane/core/pipeline.ex @@ -12,6 +12,7 @@ defmodule Membrane.Core.Pipeline do require Membrane.Core.Utils, as: Utils require Membrane.Core.Message, as: Message require Membrane.Core.Component + require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry @spec get_stalker(pipeline :: pid()) :: Membrane.Core.Stalker.t() def get_stalker(pipeline) do @@ -42,6 +43,12 @@ defmodule Membrane.Core.Pipeline do {:ok, resource_guard} = SubprocessSupervisor.start_utility(subprocess_supervisor, {ResourceGuard, self()}) + LegacyTelemetry.report_init(:pipeline) + + ResourceGuard.register(resource_guard, fn -> + LegacyTelemetry.report_terminate(:pipeline) + end) + {:ok, clock_proxy} = SubprocessSupervisor.start_utility( params.subprocess_supervisor, diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index fa4bee4a6..7ba36d84f 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -1,8 +1,8 @@ defmodule Membrane.Core.Telemetry do @moduledoc false - # This module provides a way to gather metrics from running Membrane components, as well - # as exposing these metrics in a format idiomatic to [Telemetry](https://hexdocs.pm/telemetry/) - # library. It uses compile time flags from `config.exs` to determine which metrics should be + # This module provides a way to gather events from running Membrane components, as well + # as exposing these events in a format idiomatic to [Telemetry](https://hexdocs.pm/telemetry/) + # library. It uses compile time flags from `config.exs` to determine which events should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. require Logger @@ -11,13 +11,14 @@ defmodule Membrane.Core.Telemetry do require Membrane.Element.WithInputPads require Membrane.Pipeline, as: Pipeline require Membrane.Bin, as: Bin - require Membrane.Telemetry alias Membrane.Pad alias Membrane.Element.WithOutputPads alias Membrane.Element.WithInputPads alias Membrane.ComponentPath + require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry + @type telemetry_result() :: {:telemetry_result, {any(), map(), map(), map()}} @component_modules [ @@ -26,55 +27,114 @@ defmodule Membrane.Core.Telemetry do element: [ElementBase, WithInputPads, WithOutputPads] ] - @possible_handlers (for {elem, mods} <- @component_modules do - mods - |> Enum.flat_map(& &1.behaviour_info(:callbacks)) - |> Enum.map(&elem(&1, 0)) - |> Enum.filter(&String.starts_with?(to_string(&1), "handle_")) - |> then(&{elem, &1}) - end) + @possible_callbacks (for {elem, mods} <- @component_modules do + mods + |> Enum.flat_map(& &1.behaviour_info(:callbacks)) + |> Enum.map(&elem(&1, 0)) + |> Enum.filter(&String.starts_with?(to_string(&1), "handle_")) + |> then(&{elem, &1}) + end) - _ = @possible_handlers + _ = @possible_callbacks @config Application.compile_env(:membrane_core, :telemetry_flags, []) + @legacy? Enum.any?(@config, &is_atom(&1)) || Keyword.has_key?(@config, :metrics) + + if @legacy? do + Logger.warning(""" + Legacy telemetry is deprecated and will be removed in the next major release. + Please update your configuration to use the new telemetry system. + """) + end + + def legacy?(), do: @legacy? - for {component, handlers} <- @config[:tracked_callbacks] || [] do - case handlers do + # Functions below are telemetry events that were measured before but differ in how they were emitted + defp do_legacy_telemetry(:link, _metadata, lazy_block) do + LegacyTelemetry.report_link( + quote(do: unquote(lazy_block)[:from]), + quote(do: unquote(lazy_block)[:to]) + ) + end + + defp do_legacy_telemetry(metric_name, metadata, lazy_block) do + LegacyTelemetry.report_metric(metric_name, lazy_block, quote(do: unquote(metadata)[:log_tag])) + end + + for {component, callbacks} <- @config[:tracked_callbacks] || [] do + case callbacks do :all -> - def handler_measured?(unquote(component), _), do: true + def handler_reported?(unquote(component), _), do: true nil -> nil - handler_names when is_list(handler_names) -> - for event <- handler_names do - if event not in @possible_handlers[component] do + callbacks_list when is_list(callbacks_list) -> + for event <- callbacks_list do + if event not in @possible_callbacks[component] do raise """ Invalid telemetry flag: #{inspect(event)}. - Possible values for #{component} are: #{inspect(@possible_handlers[component])} + Possible values for #{component} are: #{inspect(@possible_callbacks[component])} """ end - def handler_measured?(unquote(component), unquote(event)), do: true + def handler_reported?(unquote(component), unquote(event)), do: true end end end - def handler_measured?(_, _), do: false + def handler_reported?(_, _), do: false - case @config[:metrics] do - :all -> - def metric_measured?(_metric), do: true + def event_gathered?(event) do + events = @config[:events] + events && (events == :all || event in events) + end - nil -> - def metric_measured?(_metric), do: false + defmacrop report_event(event_name, metadata, do: lazy_block) do + unless Macro.quoted_literal?(event_name), do: raise("Event type must be a literal") - list when is_list(list) -> - for metric <- list do - def metric_measured?(unquote(metric)), do: true + if @legacy? do + do_legacy_telemetry(event_name, metadata, lazy_block) + else + if event_gathered?(event_name) do + quote do + value = unquote(lazy_block) + + :telemetry.execute( + [:membrane, :event, unquote(event_name)], + %{value: value}, + unquote(metadata) + ) + end + else + quote do + _fn = fn -> + _unused = unquote(event_name) + _unused = unquote(metadata) + _unused = unquote(lazy_block) + end + end end + end + end - def metric_measured?(_metric), do: false + def tracked_callbacks_available do + @possible_callbacks + end + + def tracked_callbacks do + for {component, callbacks} <- @config[:tracked_callbacks] || [] do + case callbacks do + :all -> + {component, @possible_callbacks[component]} + + nil -> + {component, []} + + callbacks_list when is_list(callbacks_list) -> + {component, callbacks_list} + end + end end @doc """ @@ -84,11 +144,11 @@ defmodule Membrane.Core.Telemetry do def component_span(component_type, event_type, f) do component_type = state_module_to_atom(component_type) - if handler_measured?(component_type, event_type) do + if handler_reported?(component_type, event_type) do :telemetry.span( [:membrane, component_type, event_type], %{ - log_metadata: Logger.metadata(), + event_metadata: Logger.metadata(), path: ComponentPath.get(), component_path: ComponentPath.get_formatted() }, @@ -100,7 +160,7 @@ defmodule Membrane.Core.Telemetry do internal_state_before: old_intstate, state_before: old_state, internal_state_after: new_intstate, - log_metadata: Logger.metadata(), + event_metadata: Logger.metadata(), path: ComponentPath.get() }} @@ -125,51 +185,42 @@ defmodule Membrane.Core.Telemetry do {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} end - def report_event(meta \\ %{}), do: report_metric(:event, 1, meta) - def report_link(), do: report_metric(:link, 1) - def report_store(size, log_tag), do: report_metric(:store, size, %{log_tag: log_tag}) - def report_stream_format(meta \\ %{}), do: report_metric(:stream_format, 1, meta) + def report_incoming_event(meta \\ %{}), do: report_event(:event, meta, do: 1) + + def report_stream_format(format, meta \\ %{}), + do: report_event(:stream_format, meta, do: format) def report_buffer(length, meta \\ %{}) def report_buffer(length, meta) when is_integer(length), - do: report_metric(:buffer, length, meta) + do: report_event(:buffer, meta, do: length) def report_buffer(buffers, meta) do - if metric_measured?(:buffer) do - value = length(List.wrap(buffers)) - report_buffer(value, meta) - end + report_event(:buffer, meta, do: length(buffers)) end - def report_bitrate(buffers, meta \\ %{}) do - if metric_measured?(:bitrate) do - value = Enum.reduce(List.wrap(buffers), 0, &(&2 + Membrane.Payload.size(&1.payload))) - :telemetry.execute([:membrane, :metric, :bitrate], %{value: value}, meta) + def report_store(size, log_tag) do + report_event :store, %{log_tag: log_tag} do + size end end - def report_link(from, to) do - if metric_measured?(:link) do - meta = %{ - parent_path: ComponentPath.get_formatted(), - from: inspect(from.child), - to: inspect(to.child), - pad_from: Pad.name_by_ref(from.pad_ref) |> inspect(), - pad_to: Pad.name_by_ref(to.pad_ref) |> inspect() - } - - # For backwards compatibility - :telemetry.execute([:membrane, :link, :new], %{from: from, to: to}, meta) - :telemetry.execute([:membrane, :metric, :link], %{from: from, to: to}, meta) + def report_queue_len(pid, meta \\ %{}) do + report_event :queue_len, meta do + {:message_queue_len, len} = Process.info(pid, :message_queue_len) + len end end - def report_metric(metric_name, measurement, metadata \\ %{}) do - if metric_measured?(metric_name) do - :telemetry.execute([:membrane, :metric, metric_name], %{value: measurement}, metadata) - else - measurement + def report_link(from, to) do + report_event :link, %{ + parent_path: ComponentPath.get_formatted(), + from: inspect(from.child), + to: inspect(to.child), + pad_from: Pad.name_by_ref(from.pad_ref) |> inspect(), + pad_to: Pad.name_by_ref(to.pad_ref) |> inspect() + } do + %{from: from, to: to} end end diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 68a50feb7..fe7ea8812 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -4,7 +4,7 @@ defmodule Membrane.Telemetry do Membrane uses [Telemetry Package](https://hex.pm/packages/telemetry) for instrumentation and does not store or save any measurements by itself. - It is user's responsibility to use some sort of metrics reporter + It is user's responsibility to use some sort of event consumer that will be attached to `:telemetry` package to consume and process generated measurements. ## Instrumentation @@ -16,14 +16,14 @@ defmodule Membrane.Telemetry do * `:stop` - when the handler finishes execution * `:exception` - when the handler crashes during execution - * `[:membrane, :metric, metric]` - - where metric is any of the available metrics (see below) + * `[:membrane, :event, event_type]` - + where event_type is any of the available event types (see below) - ## Enabling certain metrics/events + ## Enabling certain events A lot of events can happen hundreds times per second such as registering that a buffer has been sent/processed. This behaviour can come with a great performance penalties but may be helpful for certain discoveries. To avoid any runtime overhead - when the reporting is not necessary all metrics/events are hidden behind a compile-time feature flags. + when the reporting is not necessary all events/events are hidden behind a compile-time feature flags. To enable a particular measurement one must recompile membrane core with the following snippet put inside user's application `config.exs` file: @@ -33,17 +33,16 @@ defmodule Membrane.Telemetry do tracked_callbacks: [ [:handle_setup, ...] | :all ] - metrics: [:buffer, ...] | :all + events: [:buffer, ...] | :all ] ``` - Additionally one can control which metric values should get measured by passing an option of format : - `metrics: [list of metrics]` + Additionally one can control which event types should be gathered by passing an option of format : + `events: [list of events]` - Available metrics are: + Available events are: * `:link` - reports the number of links created in the pipeline * `:buffer` - number of buffers being sent from a particular element - * `:bitrate` - total number of bits carried by the buffers mentioned above * `:queue_len` - number of messages in element's message queue during GenServer's `handle_info` invocation * `:stream_format` - indicates that given element has received new stream format, value always equals '1' * `:event` - indicates that given element has received a new event, value always equals '1' @@ -110,13 +109,13 @@ defmodule Membrane.Telemetry do @typedoc """ * component_path - element's or bin's path - * metric - metric's name - * value - metric's value + * event - event's name + * value - events's value """ - @type metric_event_value :: %{ + @type event_value :: %{ path: ComponentPath.path(), component_path: String.t(), - metric: String.t(), + event: String.t(), value: integer() } diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index c84987742..42c04d514 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -1,7 +1,7 @@ defmodule Membrane.TelemetryTest do @moduledoc """ Test suite for Membrane telemetry public API. It tests if telemetry events are reported - properly for all metrics and spans upon attaching to the :telemetry system. + properly for all event types and span types upon attaching to the :telemetry system. """ use ExUnit.Case, async: false @@ -9,9 +9,12 @@ defmodule Membrane.TelemetryTest do import ExUnit.CaptureLog import Membrane.ChildrenSpec import Membrane.Testing.Assertions + alias Membrane.Core.Telemetry alias Membrane.Testing require Logger + @moduletag if Telemetry.legacy?(), do: :skip, else: nil + defmodule TestFilter do use Membrane.Filter @@ -35,12 +38,16 @@ defmodule Membrane.TelemetryTest do end setup do - child_spec = - child(:source, %Testing.Source{output: ["a", "b", "c"]}) - |> child(:filter, TestFilter) - |> child(:sink, Testing.Sink) - - [child_spec: child_spec] + if Telemetry.legacy?() do + [skip: true] + else + child_spec = + child(:source, %Testing.Source{output: ["a", "b", "c"]}) + |> child(:filter, TestFilter) + |> child(:sink, Testing.Sink) + + [child_spec: child_spec] + end end @paths ~w[:filter :sink :source] @@ -52,9 +59,9 @@ defmodule Membrane.TelemetryTest do ref = make_ref() spans = - for event <- @spans, + for handler <- @spans, step <- @steps do - [:membrane, :element, event, step] + [:membrane, :element, handler, step] end :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ @@ -178,64 +185,54 @@ defmodule Membrane.TelemetryTest do end end - describe "Telemetry properly reports following metrics: " do + describe "Telemetry properly reports following events: " do test "Link", %{child_spec: child_spec} do ref = setup_pipeline_for(:link, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :link], _value, _metadata}} + assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :link], _measurement, _metadata}} end - # test "Store", %{child_spec: child_spec} do - # ref = setup_pipeline_for(:store, child_spec) - - # assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :store], _value, _metadata}}, - # 1000 - # end - - # test "Take", %{child_spec: child_spec} do - # ref = setup_pipeline_for(:take, child_spec) - - # assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :take], _value, _metadata}} - # end - test "Stream Format", %{child_spec: child_spec} do ref = setup_pipeline_for(:stream_format, child_spec) assert_receive {^ref, :telemetry_ack, - {[:membrane, :metric, :stream_format], _value, _metadata}} + {[:membrane, :event, :stream_format], measurement, _metadata}} + + assert measurement.value.type == :bytestream end test "Buffer", %{child_spec: child_spec} do ref = setup_pipeline_for(:buffer, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :buffer], _value, _metadata}} - end - - test "Bitrate", %{child_spec: child_spec} do - ref = setup_pipeline_for(:bitrate, child_spec) + for _ <- 1..3 do + assert_receive {^ref, :telemetry_ack, + {[:membrane, :event, :buffer], measurement, _metadata}} - assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :bitrate], _value, _metadata}} + assert measurement.value != 0 + end end test "Event", %{child_spec: child_spec} do ref = setup_pipeline_for(:event, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :event], _value, _metadata}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :event, :event], _measurement, _metadata}} end test "Queue Length", %{child_spec: child_spec} do ref = setup_pipeline_for(:queue_len, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :metric, :queue_len], _value, _metadata}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :event, :queue_len], _measurement, _metadata}} end end - defp setup_pipeline_for(metric, child_spec) do + defp setup_pipeline_for(event, child_spec) do ref = make_ref() :telemetry.attach( ref, - [:membrane, :metric, metric], + [:membrane, :event, event], &TelemetryListener.handle_event/4, %{dest: self(), ref: ref} ) From 2b1a47476af38a35c1dac531831e54d1a7e90a45 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 28 Jan 2025 17:34:47 +0100 Subject: [PATCH 17/46] Tests and documentation for measured events and their metadata --- lib/membrane/core/callback_handler.ex | 2 +- lib/membrane/core/telemetry.ex | 134 ++++++++++++++------------ lib/membrane/telemetry.ex | 56 ++++++++--- test/membrane/telemetry_test.exs | 48 +++++++-- 4 files changed, 156 insertions(+), 84 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 8a8521320..856651b22 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -143,7 +143,7 @@ defmodule Membrane.Core.CallbackHandler do fn -> res = {_actions, new_internal_state} = apply(module, callback, args) - Telemetry.state_result(res, internal_state, new_internal_state, state) + Telemetry.state_result(res, args, internal_state, new_internal_state, state) end ) rescue diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 7ba36d84f..3be6505d4 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -5,7 +5,7 @@ defmodule Membrane.Core.Telemetry do # library. It uses compile time flags from `config.exs` to determine which events should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. - require Logger + require Membrane.Logger require Membrane.Element.Base, as: ElementBase require Membrane.Element.WithOutputPads require Membrane.Element.WithInputPads @@ -19,7 +19,7 @@ defmodule Membrane.Core.Telemetry do require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry - @type telemetry_result() :: {:telemetry_result, {any(), map(), map(), map()}} + @type telemetry_result() :: {:telemetry_result, {any(), list(), map(), map(), map()}} @component_modules [ bin: [Bin], @@ -49,16 +49,16 @@ defmodule Membrane.Core.Telemetry do def legacy?(), do: @legacy? - # Functions below are telemetry events that were measured before but differ in how they were emitted - defp do_legacy_telemetry(:link, _metadata, lazy_block) do + # Handles telemetry events that were measured before but differ in how they were emitted + defp do_legacy_telemetry(:link, lazy_block) do LegacyTelemetry.report_link( quote(do: unquote(lazy_block)[:from]), quote(do: unquote(lazy_block)[:to]) ) end - defp do_legacy_telemetry(metric_name, metadata, lazy_block) do - LegacyTelemetry.report_metric(metric_name, lazy_block, quote(do: unquote(metadata)[:log_tag])) + defp do_legacy_telemetry(metric_name, lazy_block) do + LegacyTelemetry.report_metric(metric_name, lazy_block) end for {component, callbacks} <- @config[:tracked_callbacks] || [] do @@ -85,16 +85,36 @@ defmodule Membrane.Core.Telemetry do def handler_reported?(_, _), do: false + @spec event_gathered?(any()) :: false | nil | true def event_gathered?(event) do events = @config[:events] events && (events == :all || event in events) end - defmacrop report_event(event_name, metadata, do: lazy_block) do + def tracked_callbacks_available do + @possible_callbacks + end + + def tracked_callbacks do + for {component, callbacks} <- @config[:tracked_callbacks] || [] do + case callbacks do + :all -> + {component, @possible_callbacks[component]} + + nil -> + {component, []} + + callbacks_list when is_list(callbacks_list) -> + {component, callbacks_list} + end + end + end + + defmacrop report_event(event_name, do: lazy_block) do unless Macro.quoted_literal?(event_name), do: raise("Event type must be a literal") if @legacy? do - do_legacy_telemetry(event_name, metadata, lazy_block) + do_legacy_telemetry(event_name, lazy_block) else if event_gathered?(event_name) do quote do @@ -103,14 +123,17 @@ defmodule Membrane.Core.Telemetry do :telemetry.execute( [:membrane, :event, unquote(event_name)], %{value: value}, - unquote(metadata) + %{ + event: unquote(event_name), + component_path: ComponentPath.get(), + component_metadata: Logger.metadata() + } ) end else quote do _fn = fn -> _unused = unquote(event_name) - _unused = unquote(metadata) _unused = unquote(lazy_block) end end @@ -118,48 +141,33 @@ defmodule Membrane.Core.Telemetry do end end - def tracked_callbacks_available do - @possible_callbacks - end - - def tracked_callbacks do - for {component, callbacks} <- @config[:tracked_callbacks] || [] do - case callbacks do - :all -> - {component, @possible_callbacks[component]} - - nil -> - {component, []} - - callbacks_list when is_list(callbacks_list) -> - {component, callbacks_list} - end - end - end - @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ @spec component_span(module(), atom(), (-> telemetry_result())) :: any() - def component_span(component_type, event_type, f) do + def component_span(component_type, callback, f) do component_type = state_module_to_atom(component_type) - if handler_reported?(component_type, event_type) do + if handler_reported?(component_type, callback) do :telemetry.span( - [:membrane, component_type, event_type], + [:membrane, component_type, callback], %{ event_metadata: Logger.metadata(), - path: ComponentPath.get(), - component_path: ComponentPath.get_formatted() + path: ComponentPath.get() }, fn -> case f.() do - {:telemetry_result, {r, new_intstate, old_intstate, old_state}} -> - {r, %{new_state: new_intstate}, + {:telemetry_result, {r, args, new_intstate, old_intstate, old_state}} -> + {r, %{}, %{ - internal_state_before: old_intstate, - state_before: old_state, - internal_state_after: new_intstate, + callback: callback, + component_type: component_type, + component_metadata: %{ + component_state: old_state, + internal_state_before: old_intstate, + internal_state_after: new_intstate + }, + callback_args: args, event_metadata: Logger.metadata(), path: ComponentPath.get() }} @@ -170,7 +178,7 @@ defmodule Membrane.Core.Telemetry do end ) else - {:telemetry_result, {result, _, _, _}} = f.() + {:telemetry_result, {result, _, _, _, _}} = f.() result end end @@ -178,49 +186,49 @@ defmodule Membrane.Core.Telemetry do @doc """ Formats a telemetry result to be used in a report_span function. """ - @spec state_result(any(), internal_state, internal_state, map()) :: + @spec state_result(any(), list(), internal_state, internal_state, map()) :: telemetry_result() when internal_state: any() - def state_result(res, old_internal_state, new_internal_state, old_state) do - {:telemetry_result, {res, new_internal_state, old_internal_state, old_state}} + def state_result(res, args, old_internal_state, new_internal_state, old_state) do + {:telemetry_result, {res, args, new_internal_state, old_internal_state, old_state}} end - def report_incoming_event(meta \\ %{}), do: report_event(:event, meta, do: 1) + def report_incoming_event(pad_ref), do: report_event(:event, do: pad_ref) - def report_stream_format(format, meta \\ %{}), - do: report_event(:stream_format, meta, do: format) + def report_stream_format(format, pad_ref), + do: report_event(:stream_format, do: %{format: format, pad_ref: pad_ref}) - def report_buffer(length, meta \\ %{}) + def report_buffer(length) - def report_buffer(length, meta) when is_integer(length), - do: report_event(:buffer, meta, do: length) + def report_buffer(length) when is_integer(length), + do: report_event(:buffer, do: length) - def report_buffer(buffers, meta) do - report_event(:buffer, meta, do: length(buffers)) + def report_buffer(buffers) do + report_event(:buffer, do: length(buffers)) end def report_store(size, log_tag) do - report_event :store, %{log_tag: log_tag} do - size + report_event :store do + %{value: size, log_tag: log_tag} end end - def report_queue_len(pid, meta \\ %{}) do - report_event :queue_len, meta do + def report_queue_len(pid) do + report_event :queue_len do {:message_queue_len, len} = Process.info(pid, :message_queue_len) len end end def report_link(from, to) do - report_event :link, %{ - parent_path: ComponentPath.get_formatted(), - from: inspect(from.child), - to: inspect(to.child), - pad_from: Pad.name_by_ref(from.pad_ref) |> inspect(), - pad_to: Pad.name_by_ref(to.pad_ref) |> inspect() - } do - %{from: from, to: to} + report_event :link do + %{ + parent_path: ComponentPath.get_formatted(), + from: inspect(from.child), + to: inspect(to.child), + pad_from: Pad.name_by_ref(from.pad_ref) |> inspect(), + pad_to: Pad.name_by_ref(to.pad_ref) |> inspect() + } end end diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index fe7ea8812..02722ca04 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -4,8 +4,8 @@ defmodule Membrane.Telemetry do Membrane uses [Telemetry Package](https://hex.pm/packages/telemetry) for instrumentation and does not store or save any measurements by itself. - It is user's responsibility to use some sort of event consumer - that will be attached to `:telemetry` package to consume and process generated measurements. + It is user's responsibility to use some sort of event consumer and metric reporter + that will be attached to `:telemetry` package to process generated measurements. ## Instrumentation The following events are published by Membrane's Core with following measurement types and metadata: @@ -19,12 +19,12 @@ defmodule Membrane.Telemetry do * `[:membrane, :event, event_type]` - where event_type is any of the available event types (see below) - ## Enabling certain events + ## Enabling specific events A lot of events can happen hundreds times per second such as registering that a buffer has been sent/processed. This behaviour can come with a great performance penalties but may be helpful for certain discoveries. To avoid any runtime overhead when the reporting is not necessary all events/events are hidden behind a compile-time feature flags. - To enable a particular measurement one must recompile membrane core with the following snippet put inside + To enable a particular measurement one must recompile membrane core with the following config put inside user's application `config.exs` file: ``` @@ -37,9 +37,6 @@ defmodule Membrane.Telemetry do ] ``` - Additionally one can control which event types should be gathered by passing an option of format : - `events: [list of events]` - Available events are: * `:link` - reports the number of links created in the pipeline * `:buffer` - number of buffers being sent from a particular element @@ -54,8 +51,35 @@ defmodule Membrane.Telemetry do alias Membrane.Core.Element.EffectiveFlowController alias Membrane.Core.Parent.{ChildrenModel, CrashGroup, Link} - @type instrument :: :element | :bin | :pipeline - @type event_name :: [atom() | list(atom())] + @typedoc """ + Types of telemetry events reported by Membrane Core + """ + @type event_type :: :link | :buffer | :queue_len | :stream_format | :event | :store + + @typedoc """ + Atom representation of Membrane components subject to telemetry reports + """ + @type component :: :element | :bin | :pipeline + + @typedoc """ + Component metadata included in each `t:callback_event_metadata/0` + Internal state is gathered before and after each handler callback. + State only represents component's state at the start of the callback + """ + @type component_metadata :: %{ + component_state: element_state() | bin_state() | pipeline_state(), + internal_state_after: Element.state() | Bin.state() | Pipeline.state(), + internal_state_before: Element.state() | Bin.state() | Pipeline.state() + } + @typedoc """ + Metadata included with each telemetry component's handler profiled + """ + @type callback_event_metadata :: %{ + callback: atom(), + callback_args: [any()], + component_metadata: component_metadata(), + component_type: component() + } @type element_state :: %{ subprocess_supervisor: pid(), @@ -113,10 +137,12 @@ defmodule Membrane.Telemetry do * value - events's value """ @type event_value :: %{ - path: ComponentPath.path(), - component_path: String.t(), - event: String.t(), - value: integer() + value: any() + } + @type event_metadata :: %{ + event: event_type(), + component_path: ComponentPath.path(), + component_metadata: any() } @typedoc """ @@ -133,4 +159,8 @@ defmodule Membrane.Telemetry do pad_from: String.t(), pad_to: String.t() } + + defdelegate event_gathered?(event_type), to: Membrane.Core.Telemetry + defdelegate tracked_callbacks, to: Membrane.Core.Telemetry + defdelegate tracked_callbacks_available, to: Membrane.Core.Telemetry end diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 42c04d514..dd5f272fe 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -189,16 +189,38 @@ defmodule Membrane.TelemetryTest do test "Link", %{child_spec: child_spec} do ref = setup_pipeline_for(:link, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :link], _measurement, _metadata}} + assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :link], link1, metadata}} + assert_event_metadata(metadata) + + assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :link], link2, metadata}} + assert_event_metadata(metadata) + + assert [ + %{ + from: ":filter", + pad_from: ":output", + pad_to: ":input", + parent_path: _, + to: ":sink" + }, + %{ + from: ":source", + pad_from: ":output", + pad_to: ":input", + parent_path: _, + to: ":filter" + } + ] = Enum.sort([link1.value, link2.value]) end test "Stream Format", %{child_spec: child_spec} do ref = setup_pipeline_for(:stream_format, child_spec) assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :stream_format], measurement, _metadata}} + {[:membrane, :event, :stream_format], measurement, metadata}} - assert measurement.value.type == :bytestream + assert measurement.value.format.type == :bytestream + assert_event_metadata(metadata) end test "Buffer", %{child_spec: child_spec} do @@ -206,27 +228,39 @@ defmodule Membrane.TelemetryTest do for _ <- 1..3 do assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :buffer], measurement, _metadata}} + {[:membrane, :event, :buffer], measurement, metadata}} assert measurement.value != 0 + assert_event_metadata(metadata) end end test "Event", %{child_spec: child_spec} do ref = setup_pipeline_for(:event, child_spec) - assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :event], _measurement, _metadata}} + assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :event], measurement, metadata}} + + assert measurement.value.pad_ref == ":input" + assert_event_metadata(metadata) end test "Queue Length", %{child_spec: child_spec} do ref = setup_pipeline_for(:queue_len, child_spec) assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :queue_len], _measurement, _metadata}} + {[:membrane, :event, :queue_len], measurement, metadata}} + + assert measurement.value + assert_event_metadata(metadata) end end + def assert_event_metadata(metadata) do + assert is_atom(metadata.event) + assert is_list(metadata.component_path) + assert metadata.component_metadata + end + defp setup_pipeline_for(event, child_spec) do ref = make_ref() From b00b8c92dd00c51f7adc81e750900dea2a4d114d Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 28 Jan 2025 18:03:31 +0100 Subject: [PATCH 18/46] Final touches --- config/config.exs | 2 +- lib/membrane/telemetry.ex | 38 +++++++++++++++++++++++++++----- test/membrane/telemetry_test.exs | 27 +++++++++++------------ 3 files changed, 47 insertions(+), 20 deletions(-) diff --git a/config/config.exs b/config/config.exs index 3ee97d6bb..c6bc705b3 100644 --- a/config/config.exs +++ b/config/config.exs @@ -17,7 +17,7 @@ if config_env() == :test do ], events: :all - # config to legacy telemetry + # config to test legacy version of telemetry # config :membrane_core, :telemetry_flags, [ # :report_init, # :report_terminate, diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 02722ca04..956920fbd 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -132,13 +132,15 @@ defmodule Membrane.Telemetry do } @typedoc """ - * component_path - element's or bin's path - * event - event's name - * value - events's value + Value of the specific event gathered """ @type event_value :: %{ - value: any() + value: map() } + + @typedoc """ + Metadata included with each telemetry event + """ @type event_metadata :: %{ event: event_type(), component_path: ComponentPath.path(), @@ -146,6 +148,7 @@ defmodule Membrane.Telemetry do } @typedoc """ + Value of the link event * parent_path - process path of link's parent * from - from element name * to - to element name @@ -159,8 +162,33 @@ defmodule Membrane.Telemetry do pad_from: String.t(), pad_to: String.t() } - + @type buffer_event_value :: integer() + @type queue_len_event_value :: integer() + @type stream_format_event_value :: %{format: map(), pad_ref: String.t()} + @type incoming_event_value :: String.t() + @type store_event_value :: %{value: integer(), log_tag: String.t()} + + @doc """ + Returns if the event type is configured to be gathered by Membrane's Core telemetry + """ + @spec event_gathered?(any()) :: boolean() defdelegate event_gathered?(event_type), to: Membrane.Core.Telemetry + + @doc """ + Lists all components and their callbacks tracked by Membrane's Core telemetry + """ + @spec tracked_callbacks() :: [ + {:bin, [atom(), ...]} | {:element, [atom(), ...]} | {:pipeline, [atom(), ...]}, + ... + ] defdelegate tracked_callbacks, to: Membrane.Core.Telemetry + + @doc """ + Lists all possible components and their callbacks that can be gathered when telemetry is enabled + """ + @spec tracked_callbacks_available() :: [ + {:bin, [atom(), ...]} | {:element, [atom(), ...]} | {:pipeline, [atom(), ...]}, + ... + ] defdelegate tracked_callbacks_available, to: Membrane.Core.Telemetry end diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index dd5f272fe..d57d62e50 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -64,14 +64,7 @@ defmodule Membrane.TelemetryTest do [:membrane, :element, handler, step] end - :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ - dest: self(), - ref: ref - }) - - pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) - assert_end_of_stream(pid, :sink) - :ok = Testing.Pipeline.terminate(pid) + setup_pipeline_for_callbacks(spans, child_spec, ref) [ref: ref] end @@ -108,13 +101,8 @@ defmodule Membrane.TelemetryTest do [:membrane, :pipeline, event, step] end - :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ - dest: self(), - ref: ref - }) + setup_pipeline_for_callbacks(spans, child_spec, ref) - pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) - :ok = Testing.Pipeline.terminate(pid) [ref: ref] end @@ -275,4 +263,15 @@ defmodule Membrane.TelemetryTest do ref end + + defp setup_pipeline_for_callbacks(spans, child_spec, ref) do + :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ + dest: self(), + ref: ref + }) + + pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) + assert_end_of_stream(pid, :sink) + :ok = Testing.Pipeline.terminate(pid) + end end From e50824094d99c8808a53a5b6206ef802e712fa7d Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 12:17:36 +0100 Subject: [PATCH 19/46] Update lib/membrane/telemetry.ex MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com> --- lib/membrane/telemetry.ex | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 956920fbd..229b5f711 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -178,8 +178,9 @@ defmodule Membrane.Telemetry do Lists all components and their callbacks tracked by Membrane's Core telemetry """ @spec tracked_callbacks() :: [ - {:bin, [atom(), ...]} | {:element, [atom(), ...]} | {:pipeline, [atom(), ...]}, - ... + pipeline: [atom()], + bin: [atom()], + element: [atom()] ] defdelegate tracked_callbacks, to: Membrane.Core.Telemetry From 9c65c71eee9b19facf41c8a8d98d7ad2c9a276ee Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 12:20:34 +0100 Subject: [PATCH 20/46] Update lib/membrane/telemetry.ex MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com> --- lib/membrane/telemetry.ex | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 229b5f711..2bc369c25 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -188,8 +188,9 @@ defmodule Membrane.Telemetry do Lists all possible components and their callbacks that can be gathered when telemetry is enabled """ @spec tracked_callbacks_available() :: [ - {:bin, [atom(), ...]} | {:element, [atom(), ...]} | {:pipeline, [atom(), ...]}, - ... + pipeline: [atom()], + bin: [atom()], + element: [atom()] ] defdelegate tracked_callbacks_available, to: Membrane.Core.Telemetry end From d53708b72f83c7f5f69059c361a5262d671dc2e2 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 12:23:48 +0100 Subject: [PATCH 21/46] Update lib/membrane/telemetry.ex MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com> --- lib/membrane/telemetry.ex | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 2bc369c25..0f7161771 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -4,7 +4,7 @@ defmodule Membrane.Telemetry do Membrane uses [Telemetry Package](https://hex.pm/packages/telemetry) for instrumentation and does not store or save any measurements by itself. - It is user's responsibility to use some sort of event consumer and metric reporter + It is user's responsibility to use some sort of event handler and metric reporter that will be attached to `:telemetry` package to process generated measurements. ## Instrumentation From ec80e2a306e4d48c80c3808f2b02123f3bed499a Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 13:27:11 +0100 Subject: [PATCH 22/46] PR and CI Comments addressed --- .../manual_flow_controller/input_queue.ex | 1 + lib/membrane/core/legacy_telemetry.ex | 11 ++- lib/membrane/core/telemetry.ex | 88 +++++++++++++------ lib/membrane/telemetry.ex | 3 +- test/membrane/telemetry_test.exs | 37 ++++---- 5 files changed, 91 insertions(+), 49 deletions(-) diff --git a/lib/membrane/core/element/manual_flow_controller/input_queue.ex b/lib/membrane/core/element/manual_flow_controller/input_queue.ex index 1921f0826..d30c83ddc 100644 --- a/lib/membrane/core/element/manual_flow_controller/input_queue.ex +++ b/lib/membrane/core/element/manual_flow_controller/input_queue.ex @@ -174,6 +174,7 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do input_queue = maybe_increase_atomic_demand(input_queue) %{size: size, stalker_metrics: stalker_metrics} = input_queue + Telemetry.report_take(size, input_queue.log_tag) :atomics.put(stalker_metrics.size, 1, size) {out, input_queue} diff --git a/lib/membrane/core/legacy_telemetry.ex b/lib/membrane/core/legacy_telemetry.ex index 92058e7aa..6f807e056 100644 --- a/lib/membrane/core/legacy_telemetry.ex +++ b/lib/membrane/core/legacy_telemetry.ex @@ -1,5 +1,10 @@ defmodule Membrane.Core.LegacyTelemetry do @moduledoc false + + # This module is deprecated and will be removed in the next major release (2.0) + # All contents below starting from the next comment are from Legacy Telemetry system + # to retain compatibility with the old telemetry system in case of outdated configuration. + # This module provides a way to gather events from running Membrane components, as well # as exposing these events in a format idiomatic to [Telemetry](https://hexdocs.pm/telemetry/) # library. It uses compile time flags from `config.exs` to determine which events should be @@ -56,7 +61,7 @@ defmodule Membrane.Core.LegacyTelemetry do Enum.reduce( List.wrap(unquote(buffers)), 0, - &(Membrane.Core.LegacyTelemetry.get_payload_size(&1.payload) + &2) + &(unquote(__MODULE__).get_payload_size(&1.payload) + &2) ) } end @@ -100,10 +105,10 @@ defmodule Membrane.Core.LegacyTelemetry do from: inspect(unquote(from).child), to: inspect(unquote(to).child), pad_from: - Membrane.Core.LegacyTelemetry.__get_public_pad_name__(unquote(from).pad_ref) + unquote(__MODULE__).__get_public_pad_name__(unquote(from).pad_ref) |> inspect(), pad_to: - Membrane.Core.LegacyTelemetry.__get_public_pad_name__(unquote(to).pad_ref) + unquote(__MODULE__).__get_public_pad_name__(unquote(to).pad_ref) |> inspect() } end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 3be6505d4..aa577ec4b 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -19,7 +19,15 @@ defmodule Membrane.Core.Telemetry do require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry - @type telemetry_result() :: {:telemetry_result, {any(), list(), map(), map(), map()}} + @type telemetry_result() :: + {:telemetry_result, + { + result :: any(), + arguments :: list(), + new_internal_state :: map(), + old_internal_state :: map(), + state :: map() + }} @component_modules [ bin: [Bin], @@ -35,7 +43,7 @@ defmodule Membrane.Core.Telemetry do |> then(&{elem, &1}) end) - _ = @possible_callbacks + _callbacks = @possible_callbacks @config Application.compile_env(:membrane_core, :telemetry_flags, []) @legacy? Enum.any?(@config, &is_atom(&1)) || Keyword.has_key?(@config, :metrics) @@ -61,10 +69,11 @@ defmodule Membrane.Core.Telemetry do LegacyTelemetry.report_metric(metric_name, lazy_block) end + @spec handler_reported?(atom(), atom()) :: boolean() for {component, callbacks} <- @config[:tracked_callbacks] || [] do case callbacks do :all -> - def handler_reported?(unquote(component), _), do: true + def handler_reported?(unquote(component), _callback), do: true nil -> nil @@ -83,7 +92,7 @@ defmodule Membrane.Core.Telemetry do end end - def handler_reported?(_, _), do: false + def handler_reported?(_component, _callback), do: false @spec event_gathered?(any()) :: false | nil | true def event_gathered?(event) do @@ -91,10 +100,20 @@ defmodule Membrane.Core.Telemetry do events && (events == :all || event in events) end + @spec tracked_callbacks_available() :: [ + pipeline: [atom()], + bin: [atom()], + element: [atom()] + ] def tracked_callbacks_available do @possible_callbacks end + @spec tracked_callbacks() :: [ + pipeline: [atom()], + bin: [atom()], + element: [atom()] + ] def tracked_callbacks do for {component, callbacks} <- @config[:tracked_callbacks] || [] do case callbacks do @@ -155,34 +174,36 @@ defmodule Membrane.Core.Telemetry do event_metadata: Logger.metadata(), path: ComponentPath.get() }, - fn -> - case f.() do - {:telemetry_result, {r, args, new_intstate, old_intstate, old_state}} -> - {r, %{}, - %{ - callback: callback, - component_type: component_type, - component_metadata: %{ - component_state: old_state, - internal_state_before: old_intstate, - internal_state_after: new_intstate - }, - callback_args: args, - event_metadata: Logger.metadata(), - path: ComponentPath.get() - }} - - _other -> - raise "Unexpected telemetry span result. Use Telemetry.state_result/3 instead" - end - end + fn -> unpack_state_result(f, component_type, callback) end ) else - {:telemetry_result, {result, _, _, _, _}} = f.() + {:telemetry_result, {result, _args, _new_intstate, _old_intstate, _old_state}} = f.() result end end + defp unpack_state_result(fun, component_type, callback) do + case fun.() do + {:telemetry_result, {r, args, new_intstate, old_intstate, old_state}} -> + {r, %{}, + %{ + callback: callback, + component_type: component_type, + component_metadata: %{ + component_state: old_state, + internal_state_before: old_intstate, + internal_state_after: new_intstate + }, + callback_args: args, + event_metadata: Logger.metadata(), + path: ComponentPath.get() + }} + + _other -> + raise "Unexpected telemetry span result. Use Telemetry.state_result/3 instead" + end + end + @doc """ Formats a telemetry result to be used in a report_span function. """ @@ -193,11 +214,14 @@ defmodule Membrane.Core.Telemetry do {:telemetry_result, {res, args, new_internal_state, old_internal_state, old_state}} end - def report_incoming_event(pad_ref), do: report_event(:event, do: pad_ref) + @spec report_incoming_event(%{pad_ref: String.t()}) :: :ok + def report_incoming_event(meta), do: report_event(:event, do: meta) + @spec report_stream_format(Membrane.StreamFormat.t(), String.t()) :: :ok def report_stream_format(format, pad_ref), do: report_event(:stream_format, do: %{format: format, pad_ref: pad_ref}) + @spec report_buffer(integer() | list()) :: :ok def report_buffer(length) def report_buffer(length) when is_integer(length), @@ -207,12 +231,21 @@ defmodule Membrane.Core.Telemetry do report_event(:buffer, do: length(buffers)) end + @spec report_store(integer(), String.t()) :: :ok def report_store(size, log_tag) do report_event :store do %{value: size, log_tag: log_tag} end end + @spec report_take(integer(), String.t()) :: :ok + def report_take(size, log_tag) do + report_event :take do + %{value: size, log_tag: log_tag} + end + end + + @spec report_queue_len(integer()) :: :ok def report_queue_len(pid) do report_event :queue_len do {:message_queue_len, len} = Process.info(pid, :message_queue_len) @@ -220,6 +253,7 @@ defmodule Membrane.Core.Telemetry do end end + @spec report_link(Membrane.Pad.ref(), Membrane.Pad.ref()) :: :ok def report_link(from, to) do report_event :link do %{ diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 0f7161771..44cb1f185 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -14,7 +14,7 @@ defmodule Membrane.Telemetry do where handler is any possible handle_* function defined for a component. * `:start` - when the handler begins execution * `:stop` - when the handler finishes execution - * `:exception` - when the handler crashes during execution + * `:exception` - when the component's handler crashes during execution * `[:membrane, :event, event_type]` - where event_type is any of the available event types (see below) @@ -44,6 +44,7 @@ defmodule Membrane.Telemetry do * `:stream_format` - indicates that given element has received new stream format, value always equals '1' * `:event` - indicates that given element has received a new event, value always equals '1' * `:store` - reports the current size of a input buffer when storing a new buffer + * `:take` - reports the number of buffers taken from the input buffer """ alias Membrane.{Bin, ComponentPath, Element, Pipeline, Playback, ResourceGuard} diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index d57d62e50..00e6417cc 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -77,16 +77,18 @@ defmodule Membrane.TelemetryTest do event = unquote(event) assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :start], meta, %{path: [_, ^element_type]}}}, + {[:membrane, :element, ^event, :start], results, + %{path: [_, ^element_type]}}}, 1000 - assert meta.system_time > 0 + assert results.system_time >= 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :stop], meta, %{path: [_, ^element_type]}}}, + {[:membrane, :element, ^event, :stop], results, + %{path: [_, ^element_type]}}}, 1000 - assert meta.duration > 0 + assert results.duration >= 0 end end end @@ -108,24 +110,24 @@ defmodule Membrane.TelemetryTest do test "lifecycle", %{ref: ref} do assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_init, :start], meta, %{}}} + {[:membrane, :pipeline, :handle_init, :start], results, %{}}} - assert meta.monotonic_time != 0 + assert results.monotonic_time != 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_init, :stop], meta, %{}}} + {[:membrane, :pipeline, :handle_init, :stop], results, %{}}} - assert meta.duration > 0 + assert results.duration >= 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_setup, :start], meta, %{}}} + {[:membrane, :pipeline, :handle_setup, :start], results, %{}}} - assert meta.monotonic_time != 0 + assert results.monotonic_time != 0 assert_receive {^ref, :telemetry_ack, - {[:membrane, :pipeline, :handle_setup, :stop], meta, %{}}} + {[:membrane, :pipeline, :handle_setup, :stop], results, %{}}} - assert meta.duration > 0 + assert results.duration >= 0 end end @@ -145,8 +147,7 @@ defmodule Membrane.TelemetryTest do ref: ref }) - pid = Testing.Pipeline.start_link_supervised!(spec: child_spec) - Process.flag(:trap_exit, true) + pid = Testing.Pipeline.start_supervised!(spec: child_spec) capture_log(fn -> :ok = Testing.Pipeline.notify_child(pid, :filter, :crash) @@ -157,19 +158,19 @@ defmodule Membrane.TelemetryTest do test "in element", %{ref: ref} do assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, :handle_parent_notification, :start], _meta, + {[:membrane, :element, :handle_parent_notification, :start], _results, %{path: [_, ":filter"]}}}, 1000 assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, :handle_parent_notification, :exception], meta, + {[:membrane, :element, :handle_parent_notification, :exception], results, %{path: [_, ":filter"]}}}, 1000 - assert meta.duration > 0 + assert results.duration >= 0 refute_received {^ref, :telemetry_ack, - {[:membrane, :element, :handle_parent_notification, :stop], _meta, _}} + {[:membrane, :element, :handle_parent_notification, :stop], _results, _}} end end From f910961c3f36a3fd185c55b3975513f2f12314d1 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 13:35:07 +0100 Subject: [PATCH 23/46] Credo changes --- CHANGELOG.md | 1 + .../element/manual_flow_controller/input_queue.ex | 2 +- lib/membrane/core/legacy_telemetry.ex | 6 ++++++ .../parent/child_life_controller/link_utils.ex | 2 +- lib/membrane/core/telemetry.ex | 14 ++++++++------ test/membrane/telemetry_test.exs | 3 ++- 6 files changed, 19 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 53a69d32f..27d720595 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,7 @@ * Implement `Membrane.Connector`. [#904](https://github.com/membraneframework/membrane_core/pull/904) * Implememnt diamonds detection. [#909](https://github.com/membraneframework/membrane_core/pull/909) * Incorporate `Membrane.Funnel`, `Membrane.Tee` and `Membane.Fake.Sink`. [#922](https://github.com/membraneframework/membrane_core/issues/922) + * Added new, revised Telemetry system [#905](https://github.com/membraneframework/membrane_core/pull/918) ## 1.1.2 * Add new callback `handle_child_terminated/3` along with new assertions. [#894](https://github.com/membraneframework/membrane_core/pull/894) diff --git a/lib/membrane/core/element/manual_flow_controller/input_queue.ex b/lib/membrane/core/element/manual_flow_controller/input_queue.ex index d30c83ddc..e968ba1b0 100644 --- a/lib/membrane/core/element/manual_flow_controller/input_queue.ex +++ b/lib/membrane/core/element/manual_flow_controller/input_queue.ex @@ -10,10 +10,10 @@ defmodule Membrane.Core.Element.ManualFlowController.InputQueue do alias Membrane.Buffer alias Membrane.Core.Element.AtomicDemand + alias Membrane.Core.Telemetry alias Membrane.Event alias Membrane.Pad alias Membrane.StreamFormat - alias Membrane.Core.Telemetry require Membrane.Core.Stalker, as: Stalker require Membrane.Logger diff --git a/lib/membrane/core/legacy_telemetry.ex b/lib/membrane/core/legacy_telemetry.ex index 6f807e056..217ab5130 100644 --- a/lib/membrane/core/legacy_telemetry.ex +++ b/lib/membrane/core/legacy_telemetry.ex @@ -19,6 +19,7 @@ defmodule Membrane.Core.LegacyTelemetry do @doc """ Reports metrics such as input buffer's size inside functions, incoming events and received stream format. """ + @spec report_metric(atom(), any(), log_tag :: nil | String.t()) :: :ok def report_metric(metric, value, log_tag \\ nil) do event = quote do @@ -45,6 +46,7 @@ defmodule Membrane.Core.LegacyTelemetry do Given list of buffers (or a single buffer) calculates total size of their payloads in bits and reports it. """ + @spec report_bitrate([Membrane.Buffer.t()]) :: Macro.t() def report_bitrate(buffers) do event = quote do @@ -73,6 +75,7 @@ defmodule Membrane.Core.LegacyTelemetry do ) end + @spec get_payload_size(any()) :: non_neg_integer() def get_payload_size(payload) when is_bitstring(payload) do Membrane.Payload.size(payload) end @@ -89,6 +92,7 @@ defmodule Membrane.Core.LegacyTelemetry do end end + @spec report_link(any(), any()) :: Macro.t() @doc """ Reports new link connection being initialized in pipeline. """ @@ -119,6 +123,7 @@ defmodule Membrane.Core.LegacyTelemetry do @doc """ Reports a pipeline/bin/element initialization. """ + @spec report_init(atom()) :: Macro.t() def report_init(type) when type in [:pipeline, :bin, :element] do event = quote do @@ -146,6 +151,7 @@ defmodule Membrane.Core.LegacyTelemetry do @doc """ Reports a pipeline/bin/element termination. """ + @spec report_terminate(atom()) :: Macro.t() def report_terminate(type) when type in [:pipeline, :bin, :element] do event = quote do diff --git a/lib/membrane/core/parent/child_life_controller/link_utils.ex b/lib/membrane/core/parent/child_life_controller/link_utils.ex index a7d1a9a41..5d56be0b4 100644 --- a/lib/membrane/core/parent/child_life_controller/link_utils.ex +++ b/lib/membrane/core/parent/child_life_controller/link_utils.ex @@ -5,8 +5,8 @@ defmodule Membrane.Core.Parent.ChildLifeController.LinkUtils do alias Membrane.Child alias Membrane.Core.{Bin, Message, Parent} - alias Membrane.Core.Telemetry alias Membrane.Core.Bin.PadController + alias Membrane.Core.Telemetry alias Membrane.Core.Parent.{ ChildLifeController, diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index aa577ec4b..7bf80a1b3 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -5,17 +5,18 @@ defmodule Membrane.Core.Telemetry do # library. It uses compile time flags from `config.exs` to determine which events should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. + alias Membrane.ComponentPath + alias Membrane.Element.WithInputPads + alias Membrane.Element.WithOutputPads + alias Membrane.Pad + require Membrane.Logger + + require Membrane.Bin, as: Bin require Membrane.Element.Base, as: ElementBase require Membrane.Element.WithOutputPads require Membrane.Element.WithInputPads require Membrane.Pipeline, as: Pipeline - require Membrane.Bin, as: Bin - - alias Membrane.Pad - alias Membrane.Element.WithOutputPads - alias Membrane.Element.WithInputPads - alias Membrane.ComponentPath require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry @@ -55,6 +56,7 @@ defmodule Membrane.Core.Telemetry do """) end + @spec legacy?() :: boolean() def legacy?(), do: @legacy? # Handles telemetry events that were measured before but differ in how they were emitted diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 00e6417cc..69be7f909 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -32,6 +32,7 @@ defmodule Membrane.TelemetryTest do end defmodule TelemetryListener do + @spec handle_event(atom(), any(), map(), map()) :: :ok def handle_event(name, value, metadata, %{dest: pid, ref: ref}) do pid |> send({ref, :telemetry_ack, {name, value, metadata}}) end @@ -244,7 +245,7 @@ defmodule Membrane.TelemetryTest do end end - def assert_event_metadata(metadata) do + defp assert_event_metadata(metadata) do assert is_atom(metadata.event) assert is_list(metadata.component_path) assert metadata.component_metadata From 083f65eb7adb2c53b3db388a56d8007373758eac Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 14:28:27 +0100 Subject: [PATCH 24/46] Unnecessary element and bin state fields removed --- lib/membrane/telemetry.ex | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 44cb1f185..3b875b943 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -94,8 +94,7 @@ defmodule Membrane.Telemetry do type: Element.type(), name: Element.name(), internal_state: Element.state() | nil, - pads_info: PadModel.pads_info() | nil, - pads_data: PadModel.pads_data() | nil, + pads_data: Membrane.Element.PadData.t() | nil, parent_pid: pid() } @@ -105,8 +104,7 @@ defmodule Membrane.Telemetry do children: ChildrenModel.children(), subprocess_supervisor: pid(), name: Bin.name() | nil, - pads_info: PadModel.pads_info() | nil, - pads_data: PadModel.pads_data() | nil, + pads_data: Membrane.Bin.PadData.t() | nil, parent_pid: pid(), links: %{Link.id() => Link.t()}, crash_groups: %{CrashGroup.name() => CrashGroup.t()}, From 95bdab1b1d552cbfcd6cbe12781641fe8909dafd Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 14:32:39 +0100 Subject: [PATCH 25/46] Credo satisfied --- lib/membrane/telemetry.ex | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 3b875b943..931619a36 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -48,7 +48,6 @@ defmodule Membrane.Telemetry do """ alias Membrane.{Bin, ComponentPath, Element, Pipeline, Playback, ResourceGuard} - alias Membrane.Core.Child.PadModel alias Membrane.Core.Element.EffectiveFlowController alias Membrane.Core.Parent.{ChildrenModel, CrashGroup, Link} From c905ec56f115ae7b4ba46a16f74ddb974f0f59a5 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 16:51:18 +0100 Subject: [PATCH 26/46] Changed component context and added tests reflecting the changes --- lib/membrane/core/telemetry.ex | 52 ++++++++------- lib/membrane/telemetry.ex | 111 ++++++++++--------------------- test/membrane/telemetry_test.exs | 14 ++-- 3 files changed, 69 insertions(+), 108 deletions(-) diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 7bf80a1b3..7882316d8 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -20,14 +20,14 @@ defmodule Membrane.Core.Telemetry do require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry - @type telemetry_result() :: + @type telemetry_callback_result() :: {:telemetry_result, { result :: any(), arguments :: list(), new_internal_state :: map(), old_internal_state :: map(), - state :: map() + context :: Membrane.Telemetry.callback_event_metadata() }} @component_modules [ @@ -134,10 +134,11 @@ defmodule Membrane.Core.Telemetry do defmacrop report_event(event_name, do: lazy_block) do unless Macro.quoted_literal?(event_name), do: raise("Event type must be a literal") - if @legacy? do - do_legacy_telemetry(event_name, lazy_block) - else - if event_gathered?(event_name) do + cond do + @legacy? -> + do_legacy_telemetry(event_name, lazy_block) + + event_gathered?(event_name) -> quote do value = unquote(lazy_block) @@ -151,21 +152,21 @@ defmodule Membrane.Core.Telemetry do } ) end - else + + true -> quote do _fn = fn -> _unused = unquote(event_name) _unused = unquote(lazy_block) end end - end end end @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ - @spec component_span(module(), atom(), (-> telemetry_result())) :: any() + @spec component_span(module(), atom(), (-> telemetry_callback_result())) :: any() def component_span(component_type, callback, f) do component_type = state_module_to_atom(component_type) @@ -173,10 +174,11 @@ defmodule Membrane.Core.Telemetry do :telemetry.span( [:membrane, component_type, callback], %{ - event_metadata: Logger.metadata(), - path: ComponentPath.get() + component_path: ComponentPath.get(), + callback: callback, + component_type: component_type }, - fn -> unpack_state_result(f, component_type, callback) end + fn -> unpack_state_result(f, callback, component_type) end ) else {:telemetry_result, {result, _args, _new_intstate, _old_intstate, _old_state}} = f.() @@ -184,21 +186,21 @@ defmodule Membrane.Core.Telemetry do end end - defp unpack_state_result(fun, component_type, callback) do + defp unpack_state_result(fun, callback, component_type) do case fun.() do {:telemetry_result, {r, args, new_intstate, old_intstate, old_state}} -> {r, %{}, %{ + callback_args: args, + component_path: ComponentPath.get(), callback: callback, - component_type: component_type, component_metadata: %{ - component_state: old_state, + component_type: component_type, + component_context: old_state, + component_module: old_state.module, internal_state_before: old_intstate, internal_state_after: new_intstate - }, - callback_args: args, - event_metadata: Logger.metadata(), - path: ComponentPath.get() + } }} _other -> @@ -210,7 +212,7 @@ defmodule Membrane.Core.Telemetry do Formats a telemetry result to be used in a report_span function. """ @spec state_result(any(), list(), internal_state, internal_state, map()) :: - telemetry_result() + telemetry_callback_result() when internal_state: any() def state_result(res, args, old_internal_state, new_internal_state, old_state) do {:telemetry_result, {res, args, new_internal_state, old_internal_state, old_state}} @@ -236,22 +238,22 @@ defmodule Membrane.Core.Telemetry do @spec report_store(integer(), String.t()) :: :ok def report_store(size, log_tag) do report_event :store do - %{value: size, log_tag: log_tag} + %{size: size, log_tag: log_tag} end end @spec report_take(integer(), String.t()) :: :ok def report_take(size, log_tag) do report_event :take do - %{value: size, log_tag: log_tag} + %{size: size, log_tag: log_tag} end end - @spec report_queue_len(integer()) :: :ok + @spec report_queue_len(pid()) :: :ok def report_queue_len(pid) do report_event :queue_len do {:message_queue_len, len} = Process.info(pid, :message_queue_len) - len + %{len: len} end end @@ -259,7 +261,7 @@ defmodule Membrane.Core.Telemetry do def report_link(from, to) do report_event :link do %{ - parent_path: ComponentPath.get_formatted(), + parent_component_path: ComponentPath.get_formatted(), from: inspect(from.child), to: inspect(to.child), pad_from: Pad.name_by_ref(from.pad_ref) |> inspect(), diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 931619a36..56e028afb 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -47,19 +47,12 @@ defmodule Membrane.Telemetry do * `:take` - reports the number of buffers taken from the input buffer """ - alias Membrane.{Bin, ComponentPath, Element, Pipeline, Playback, ResourceGuard} - alias Membrane.Core.Element.EffectiveFlowController - alias Membrane.Core.Parent.{ChildrenModel, CrashGroup, Link} - - @typedoc """ - Types of telemetry events reported by Membrane Core - """ - @type event_type :: :link | :buffer | :queue_len | :stream_format | :event | :store + alias Membrane.{Bin, ComponentPath, Element, Pipeline} @typedoc """ Atom representation of Membrane components subject to telemetry reports """ - @type component :: :element | :bin | :pipeline + @type component_type :: :element | :bin | :pipeline @typedoc """ Component metadata included in each `t:callback_event_metadata/0` @@ -67,9 +60,12 @@ defmodule Membrane.Telemetry do State only represents component's state at the start of the callback """ @type component_metadata :: %{ - component_state: element_state() | bin_state() | pipeline_state(), - internal_state_after: Element.state() | Bin.state() | Pipeline.state(), - internal_state_before: Element.state() | Bin.state() | Pipeline.state() + component_context: + Element.CallbackContext.t() | Bin.CallbackContext.t() | Pipeline.CallbackContext.t(), + component_module: module(), + component_path: ComponentPath.path(), + internal_state_before: Element.state() | Bin.state() | Pipeline.state(), + internal_state_after: Element.state() | Bin.state() | Pipeline.state() } @typedoc """ Metadata included with each telemetry component's handler profiled @@ -78,83 +74,24 @@ defmodule Membrane.Telemetry do callback: atom(), callback_args: [any()], component_metadata: component_metadata(), - component_type: component() - } - - @type element_state :: %{ - subprocess_supervisor: pid(), - terminating?: boolean(), - setup_incomplete?: boolean(), - effective_flow_control: EffectiveFlowController.effective_flow_control(), - resource_guard: ResourceGuard.t(), - initialized?: boolean(), - playback: Playback.t(), - module: module(), - type: Element.type(), - name: Element.name(), - internal_state: Element.state() | nil, - pads_data: Membrane.Element.PadData.t() | nil, - parent_pid: pid() - } - - @type bin_state :: %{ - internal_state: Bin.state() | nil, - module: module(), - children: ChildrenModel.children(), - subprocess_supervisor: pid(), - name: Bin.name() | nil, - pads_data: Membrane.Bin.PadData.t() | nil, - parent_pid: pid(), - links: %{Link.id() => Link.t()}, - crash_groups: %{CrashGroup.name() => CrashGroup.t()}, - children_log_metadata: Keyword.t(), - playback: Playback.t(), - initialized?: boolean(), - terminating?: boolean(), - resource_guard: ResourceGuard.t(), - setup_incomplete?: boolean() - } - - @type pipeline_state :: %{ - module: module(), - playback: Playback.t(), - internal_state: Pipeline.state() | nil, - children: ChildrenModel.children(), - links: %{Link.id() => Link.t()}, - crash_groups: %{CrashGroup.name() => CrashGroup.t()}, - initialized?: boolean(), - terminating?: boolean(), - resource_guard: ResourceGuard.t(), - setup_incomplete?: boolean(), - subprocess_supervisor: pid() + component_type: component_type() } @typedoc """ - Value of the specific event gathered + Types of telemetry events reported by Membrane Core """ - @type event_value :: %{ - value: map() - } - - @typedoc """ - Metadata included with each telemetry event - """ - @type event_metadata :: %{ - event: event_type(), - component_path: ComponentPath.path(), - component_metadata: any() - } + @type event_type :: :link | :buffer | :queue_len | :stream_format | :event | :store | :take @typedoc """ Value of the link event - * parent_path - process path of link's parent + * parent_component_path - process path of link's parent * from - from element name * to - to element name * pad_from - from's pad name * pad_to - to's pad name """ @type link_event_value :: %{ - parent_path: String.t(), + parent_component_path: String.t(), from: String.t(), to: String.t(), pad_from: String.t(), @@ -166,6 +103,28 @@ defmodule Membrane.Telemetry do @type incoming_event_value :: String.t() @type store_event_value :: %{value: integer(), log_tag: String.t()} + @typedoc """ + Value of the specific event gathered + """ + @type event_value :: %{ + value: + buffer_event_value() + | queue_len_event_value() + | stream_format_event_value() + | incoming_event_value() + | store_event_value() + | integer() + } + + @typedoc """ + Metadata included with each telemetry event + """ + @type event_metadata :: %{ + event: event_type(), + component_path: ComponentPath.path(), + component_metadata: any() + } + @doc """ Returns if the event type is configured to be gathered by Membrane's Core telemetry """ diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 69be7f909..573b85b46 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -79,14 +79,14 @@ defmodule Membrane.TelemetryTest do assert_receive {^ref, :telemetry_ack, {[:membrane, :element, ^event, :start], results, - %{path: [_, ^element_type]}}}, + %{component_path: [_, ^element_type]}}}, 1000 - assert results.system_time >= 0 + assert results.monotonic_time < 0 assert_receive {^ref, :telemetry_ack, {[:membrane, :element, ^event, :stop], results, - %{path: [_, ^element_type]}}}, + %{component_path: [_, ^element_type]}}}, 1000 assert results.duration >= 0 @@ -160,12 +160,12 @@ defmodule Membrane.TelemetryTest do test "in element", %{ref: ref} do assert_receive {^ref, :telemetry_ack, {[:membrane, :element, :handle_parent_notification, :start], _results, - %{path: [_, ":filter"]}}}, + %{component_path: [_, ":filter"]}}}, 1000 assert_receive {^ref, :telemetry_ack, {[:membrane, :element, :handle_parent_notification, :exception], results, - %{path: [_, ":filter"]}}}, + %{component_path: [_, ":filter"]}}}, 1000 assert results.duration >= 0 @@ -190,14 +190,14 @@ defmodule Membrane.TelemetryTest do from: ":filter", pad_from: ":output", pad_to: ":input", - parent_path: _, + parent_component_path: _, to: ":sink" }, %{ from: ":source", pad_from: ":output", pad_to: ":input", - parent_path: _, + parent_component_path: _, to: ":filter" } ] = Enum.sort([link1.value, link2.value]) From b1a9627440e82003f23b86c12b42c2e4e6d64cc9 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 17:18:13 +0100 Subject: [PATCH 27/46] LegacyTelemetry sometimes didn't work properly --- lib/membrane/core/legacy_telemetry.ex | 15 +++++---------- lib/membrane/core/telemetry.ex | 9 +++++---- 2 files changed, 10 insertions(+), 14 deletions(-) diff --git a/lib/membrane/core/legacy_telemetry.ex b/lib/membrane/core/legacy_telemetry.ex index 217ab5130..6d7145a52 100644 --- a/lib/membrane/core/legacy_telemetry.ex +++ b/lib/membrane/core/legacy_telemetry.ex @@ -19,8 +19,7 @@ defmodule Membrane.Core.LegacyTelemetry do @doc """ Reports metrics such as input buffer's size inside functions, incoming events and received stream format. """ - @spec report_metric(atom(), any(), log_tag :: nil | String.t()) :: :ok - def report_metric(metric, value, log_tag \\ nil) do + defmacro report_metric(metric, value, log_tag \\ nil) do event = quote do [:membrane, :metric, :value] @@ -46,8 +45,7 @@ defmodule Membrane.Core.LegacyTelemetry do Given list of buffers (or a single buffer) calculates total size of their payloads in bits and reports it. """ - @spec report_bitrate([Membrane.Buffer.t()]) :: Macro.t() - def report_bitrate(buffers) do + defmacro report_bitrate(buffers) do event = quote do [:membrane, :metric, :value] @@ -92,11 +90,10 @@ defmodule Membrane.Core.LegacyTelemetry do end end - @spec report_link(any(), any()) :: Macro.t() @doc """ Reports new link connection being initialized in pipeline. """ - def report_link(from, to) do + defmacro report_link(from, to) do event = quote do [:membrane, :link, :new] @@ -123,8 +120,7 @@ defmodule Membrane.Core.LegacyTelemetry do @doc """ Reports a pipeline/bin/element initialization. """ - @spec report_init(atom()) :: Macro.t() - def report_init(type) when type in [:pipeline, :bin, :element] do + defmacro report_init(type) when type in [:pipeline, :bin, :element] do event = quote do [:membrane, unquote(type), :init] @@ -151,8 +147,7 @@ defmodule Membrane.Core.LegacyTelemetry do @doc """ Reports a pipeline/bin/element termination. """ - @spec report_terminate(atom()) :: Macro.t() - def report_terminate(type) when type in [:pipeline, :bin, :element] do + defmacro report_terminate(type) when type in [:pipeline, :bin, :element] do event = quote do [:membrane, unquote(type), :terminate] diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 7882316d8..5ef3b7f8a 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -61,10 +61,9 @@ defmodule Membrane.Core.Telemetry do # Handles telemetry events that were measured before but differ in how they were emitted defp do_legacy_telemetry(:link, lazy_block) do - LegacyTelemetry.report_link( - quote(do: unquote(lazy_block)[:from]), - quote(do: unquote(lazy_block)[:to]) - ) + quote do + LegacyTelemetry.report_link(unquote(lazy_block)[:from], unquote(lazy_block)[:to]) + end end defp do_legacy_telemetry(metric_name, lazy_block) do @@ -159,6 +158,8 @@ defmodule Membrane.Core.Telemetry do _unused = unquote(event_name) _unused = unquote(lazy_block) end + + :ok end end end From 8a01d9bbd5cac31cf33f09085459786ca25cafb5 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 30 Jan 2025 17:27:22 +0100 Subject: [PATCH 28/46] Dialyzer fix --- lib/membrane/core/element/stream_format_controller.ex | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/membrane/core/element/stream_format_controller.ex b/lib/membrane/core/element/stream_format_controller.ex index cb4f4f7cf..3b9bfd238 100644 --- a/lib/membrane/core/element/stream_format_controller.ex +++ b/lib/membrane/core/element/stream_format_controller.ex @@ -33,7 +33,7 @@ defmodule Membrane.Core.Element.StreamFormatController do withl pad: {:ok, data} <- PadModel.get_data(state, pad_ref), playback: %State{playback: :playing} <- state do %{direction: :input} = data - Telemetry.report_stream_format(stream_format, %{pad_ref: inspect(pad_ref)}) + Telemetry.report_stream_format(stream_format, inspect(pad_ref)) queue = data.input_queue From fe9e359f5f71c5ee698f3a29fd7dd7459ab07a16 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 31 Jan 2025 11:10:21 +0100 Subject: [PATCH 29/46] Dialyzer satisfied --- lib/membrane/core/telemetry.ex | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 5ef3b7f8a..dc67ea1fc 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -60,13 +60,14 @@ defmodule Membrane.Core.Telemetry do def legacy?(), do: @legacy? # Handles telemetry events that were measured before but differ in how they were emitted - defp do_legacy_telemetry(:link, lazy_block) do + # It's public to avoid dialyzer warnings. Not intended for external use + def do_legacy_telemetry(:link, lazy_block) do quote do LegacyTelemetry.report_link(unquote(lazy_block)[:from], unquote(lazy_block)[:to]) end end - defp do_legacy_telemetry(metric_name, lazy_block) do + def do_legacy_telemetry(metric_name, lazy_block) do LegacyTelemetry.report_metric(metric_name, lazy_block) end From 6c7b0913c65cd0f447b65353979bed0f7e465b9b Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 31 Jan 2025 11:18:47 +0100 Subject: [PATCH 30/46] Appeasing the dialyzer --- lib/membrane/core/telemetry.ex | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index dc67ea1fc..89edd70a1 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -6,6 +6,7 @@ defmodule Membrane.Core.Telemetry do # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. alias Membrane.ComponentPath + alias Membrane.Core.Parent.Link alias Membrane.Element.WithInputPads alias Membrane.Element.WithOutputPads alias Membrane.Pad @@ -259,7 +260,7 @@ defmodule Membrane.Core.Telemetry do end end - @spec report_link(Membrane.Pad.ref(), Membrane.Pad.ref()) :: :ok + @spec report_link(Link.Endpoint.t(), Link.Endpoint.t()) :: :ok def report_link(from, to) do report_event :link do %{ From 4bc4c258a6f6554de8f1d40461181ca2a3450f68 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 31 Jan 2025 12:06:05 +0100 Subject: [PATCH 31/46] Credo --- lib/membrane/core/telemetry.ex | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 89edd70a1..b56762b0d 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -62,6 +62,7 @@ defmodule Membrane.Core.Telemetry do # Handles telemetry events that were measured before but differ in how they were emitted # It's public to avoid dialyzer warnings. Not intended for external use + @spec do_legacy_telemetry(atom(), Macro.t()) :: Macro.t() def do_legacy_telemetry(:link, lazy_block) do quote do LegacyTelemetry.report_link(unquote(lazy_block)[:from], unquote(lazy_block)[:to]) From d7f083a873753b434b5c298c2b287184753d5bc8 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Fri, 31 Jan 2025 13:10:57 +0100 Subject: [PATCH 32/46] Context instead of state --- lib/membrane/core/callback_handler.ex | 11 ++++-- lib/membrane/core/telemetry.ex | 50 +++++++++++++++------------ lib/membrane/telemetry.ex | 6 ++-- 3 files changed, 40 insertions(+), 27 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 856651b22..a916940ca 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -133,7 +133,8 @@ defmodule Membrane.Core.CallbackHandler do %{context: context_fun}, %{module: module, internal_state: internal_state} = state ) do - args = args ++ [context_fun.(state), internal_state] + context = context_fun.(state) + args = args ++ [context, internal_state] callback_result = try do @@ -143,7 +144,13 @@ defmodule Membrane.Core.CallbackHandler do fn -> res = {_actions, new_internal_state} = apply(module, callback, args) - Telemetry.state_result(res, args, internal_state, new_internal_state, state) + Telemetry.state_result(res, %{ + args: args, + module: module, + internal_state_before: internal_state, + internal_state_after: new_internal_state, + component_context: context + }) end ) rescue diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index b56762b0d..144ec108b 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -21,15 +21,13 @@ defmodule Membrane.Core.Telemetry do require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry - @type telemetry_callback_result() :: - {:telemetry_result, - { - result :: any(), - arguments :: list(), - new_internal_state :: map(), - old_internal_state :: map(), - context :: Membrane.Telemetry.callback_event_metadata() - }} + @type telemetry_callback_metadata() :: %{ + args: list(any()), + module: module(), + internal_state_before: any(), + internal_state_after: any(), + component_context: Membrane.Telemetry.component_context() + } @component_modules [ bin: [Bin], @@ -170,7 +168,8 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ - @spec component_span(module(), atom(), (-> telemetry_callback_result())) :: any() + @spec component_span(module(), atom(), (-> {:telemetry, telemetry_callback_metadata()})) :: + any() def component_span(component_type, callback, f) do component_type = state_module_to_atom(component_type) @@ -185,25 +184,27 @@ defmodule Membrane.Core.Telemetry do fn -> unpack_state_result(f, callback, component_type) end ) else - {:telemetry_result, {result, _args, _new_intstate, _old_intstate, _old_state}} = f.() + {:telemetry_result, {result, _meta}} = + f.() + result end end defp unpack_state_result(fun, callback, component_type) do case fun.() do - {:telemetry_result, {r, args, new_intstate, old_intstate, old_state}} -> - {r, %{}, + {:telemetry_result, {result, metadata}} -> + {result, %{}, %{ - callback_args: args, + callback_args: metadata.args, component_path: ComponentPath.get(), callback: callback, component_metadata: %{ component_type: component_type, - component_context: old_state, - component_module: old_state.module, - internal_state_before: old_intstate, - internal_state_after: new_intstate + component_context: metadata.component_context, + component_module: metadata.module, + internal_state_before: metadata.internal_state_before, + internal_state_after: metadata.internal_state_after } }} @@ -215,11 +216,14 @@ defmodule Membrane.Core.Telemetry do @doc """ Formats a telemetry result to be used in a report_span function. """ - @spec state_result(any(), list(), internal_state, internal_state, map()) :: - telemetry_callback_result() - when internal_state: any() - def state_result(res, args, old_internal_state, new_internal_state, old_state) do - {:telemetry_result, {res, args, new_internal_state, old_internal_state, old_state}} + @spec state_result( + result :: result, + metadata :: telemetry_callback_metadata() + ) :: + {:telemetry_result, {result, telemetry_callback_metadata()}} + when result: any() + def state_result(result, metadata) do + {:telemetry_result, {result, metadata}} end @spec report_incoming_event(%{pad_ref: String.t()}) :: :ok diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 56e028afb..154ee6829 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -54,14 +54,16 @@ defmodule Membrane.Telemetry do """ @type component_type :: :element | :bin | :pipeline + @type component_context :: + Element.CallbackContext.t() | Bin.CallbackContext.t() | Pipeline.CallbackContext.t() + @typedoc """ Component metadata included in each `t:callback_event_metadata/0` Internal state is gathered before and after each handler callback. State only represents component's state at the start of the callback """ @type component_metadata :: %{ - component_context: - Element.CallbackContext.t() | Bin.CallbackContext.t() | Pipeline.CallbackContext.t(), + component_context: component_context(), component_module: module(), component_path: ComponentPath.path(), internal_state_before: Element.state() | Bin.state() | Pipeline.state(), From 66cdefdb501a8159f7999f040e7feea946692c72 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 3 Feb 2025 15:41:21 +0100 Subject: [PATCH 33/46] Simpler(?) telemetry private API --- lib/membrane/bin/callback_context.ex | 6 +- lib/membrane/core/bin/callback_context.ex | 4 +- lib/membrane/core/callback_handler.ex | 35 ++++---- lib/membrane/core/element/callback_context.ex | 2 + .../core/pipeline/callback_context.ex | 2 + lib/membrane/core/telemetry.ex | 90 ++++++------------- lib/membrane/element/callback_context.ex | 6 +- lib/membrane/pipeline/callback_context.ex | 4 +- lib/membrane/telemetry.ex | 39 ++++---- test/membrane/telemetry_test.exs | 6 +- 10 files changed, 85 insertions(+), 109 deletions(-) diff --git a/lib/membrane/bin/callback_context.ex b/lib/membrane/bin/callback_context.ex index c6aa09527..aaebc1bc4 100644 --- a/lib/membrane/bin/callback_context.ex +++ b/lib/membrane/bin/callback_context.ex @@ -16,13 +16,15 @@ defmodule Membrane.Bin.CallbackContext do `c:Membrane.Bin.handle_crash_group_down/3`. """ @type t :: %{ + :children => %{Membrane.Child.name() => Membrane.ChildEntry.t()}, :clock => Membrane.Clock.t(), :parent_clock => Membrane.Clock.t(), - :pads => %{Membrane.Pad.ref() => Membrane.Bin.PadData.t()}, + :module => module(), :name => Membrane.Bin.name(), - :children => %{Membrane.Child.name() => Membrane.ChildEntry.t()}, + :pads => %{Membrane.Pad.ref() => Membrane.Bin.PadData.t()}, :playback => Membrane.Playback.t(), :resource_guard => Membrane.ResourceGuard.t(), + :setup_incomplete? => boolean(), :utility_supervisor => Membrane.UtilitySupervisor.t(), optional(:pad_options) => map(), optional(:members) => [Membrane.Child.name()], diff --git a/lib/membrane/core/bin/callback_context.ex b/lib/membrane/core/bin/callback_context.ex index 205e90c2a..bf5272e4a 100644 --- a/lib/membrane/core/bin/callback_context.ex +++ b/lib/membrane/core/bin/callback_context.ex @@ -15,13 +15,15 @@ defmodule Membrane.Core.Bin.CallbackContext do def from_state(state, optional_fields \\ []) do Map.new(optional_fields) |> Map.merge(%{ + children: state.children, clock: state.synchronization.clock, parent_clock: state.synchronization.parent_clock, pads: state.pads_data, + module: state.module, name: state.name, - children: state.children, playback: state.playback, resource_guard: state.resource_guard, + setup_incomplete?: state.setup_incomplete?, utility_supervisor: state.subprocess_supervisor }) end diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index a916940ca..46e0928be 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -8,6 +8,7 @@ defmodule Membrane.Core.CallbackHandler do use Bunch alias Membrane.CallbackError + alias Membrane.ComponentPath require Membrane.Logger require Membrane.Core.Telemetry, as: Telemetry @@ -138,21 +139,8 @@ defmodule Membrane.Core.CallbackHandler do callback_result = try do - Telemetry.component_span( - state.__struct__, - callback, - fn -> - res = {_actions, new_internal_state} = apply(module, callback, args) - - Telemetry.state_result(res, %{ - args: args, - module: module, - internal_state_before: internal_state, - internal_state_after: new_internal_state, - component_context: context - }) - end - ) + fn -> apply(module, callback, args) end + |> report_telemetry(callback, args, state, context) rescue e in UndefinedFunctionError -> _ignored = @@ -182,6 +170,23 @@ defmodule Membrane.Core.CallbackHandler do end end + defp report_telemetry(f, callback, args, state, context) do + Telemetry.span_component_callback( + f, + state.__struct__, + callback, + %{ + callback: callback, + callback_args: args, + callback_context: context, + component_type: state.module, + component_path: ComponentPath.get(), + internal_state_before: state.internal_state, + internal_state_after: nil + } + ) + end + @spec handle_callback_result( {actions :: Keyword.t(), internal_state}, callback :: atom, diff --git a/lib/membrane/core/element/callback_context.ex b/lib/membrane/core/element/callback_context.ex index 71cee7c9b..19daa0dbf 100644 --- a/lib/membrane/core/element/callback_context.ex +++ b/lib/membrane/core/element/callback_context.ex @@ -15,9 +15,11 @@ defmodule Membrane.Core.Element.CallbackContext do pads: state.pads_data, clock: state.synchronization.clock, parent_clock: state.synchronization.parent_clock, + module: state.module, name: state.name, playback: state.playback, resource_guard: state.resource_guard, + setup_incomplete?: state.setup_incomplete?, utility_supervisor: state.subprocess_supervisor }) end diff --git a/lib/membrane/core/pipeline/callback_context.ex b/lib/membrane/core/pipeline/callback_context.ex index 0414147a6..f48fe59b4 100644 --- a/lib/membrane/core/pipeline/callback_context.ex +++ b/lib/membrane/core/pipeline/callback_context.ex @@ -17,8 +17,10 @@ defmodule Membrane.Core.Pipeline.CallbackContext do |> Map.merge(%{ clock: state.synchronization.clock_proxy, children: state.children, + module: state.module, playback: state.playback, resource_guard: state.resource_guard, + setup_incomplete?: state.setup_incomplete?, utility_supervisor: state.subprocess_supervisor }) end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 144ec108b..a6129ad8e 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -5,11 +5,15 @@ defmodule Membrane.Core.Telemetry do # library. It uses compile time flags from `config.exs` to determine which events should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. - alias Membrane.ComponentPath + require Logger + alias Membrane.Core.CallbackHandler alias Membrane.Core.Parent.Link + + alias Membrane.ComponentPath alias Membrane.Element.WithInputPads alias Membrane.Element.WithOutputPads alias Membrane.Pad + alias Membrane.Telemetry require Membrane.Logger @@ -21,14 +25,6 @@ defmodule Membrane.Core.Telemetry do require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry - @type telemetry_callback_metadata() :: %{ - args: list(any()), - module: module(), - internal_state_before: any(), - internal_state_after: any(), - component_context: Membrane.Telemetry.component_context() - } - @component_modules [ bin: [Bin], pipeline: [Pipeline], @@ -168,62 +164,34 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` """ - @spec component_span(module(), atom(), (-> {:telemetry, telemetry_callback_metadata()})) :: - any() - def component_span(component_type, callback, f) do - component_type = state_module_to_atom(component_type) + @spec span_component_callback( + (-> CallbackHandler.callback_return() | any()), + module(), + atom(), + Telemetry.callback_event_metadata() + ) :: CallbackHandler.callback_return() | any() + def span_component_callback(f, component_module, callback, meta) do + component_type = state_module_to_atom(component_module) if handler_reported?(component_type, callback) do - :telemetry.span( - [:membrane, component_type, callback], - %{ - component_path: ComponentPath.get(), - callback: callback, - component_type: component_type - }, - fn -> unpack_state_result(f, callback, component_type) end - ) + :telemetry.span([:membrane, component_type, callback], meta, fn -> report_span(f, meta) end) else - {:telemetry_result, {result, _meta}} = - f.() - - result + f.() end end - defp unpack_state_result(fun, callback, component_type) do - case fun.() do - {:telemetry_result, {result, metadata}} -> - {result, %{}, - %{ - callback_args: metadata.args, - component_path: ComponentPath.get(), - callback: callback, - component_metadata: %{ - component_type: component_type, - component_context: metadata.component_context, - component_module: metadata.module, - internal_state_before: metadata.internal_state_before, - internal_state_after: metadata.internal_state_after - } - }} - - _other -> - raise "Unexpected telemetry span result. Use Telemetry.state_result/3 instead" - end - end + defp report_span(f, meta) do + case f.() do + {_actions, int_state} = res -> + {res, %{meta | internal_state_after: int_state}} - @doc """ - Formats a telemetry result to be used in a report_span function. - """ - @spec state_result( - result :: result, - metadata :: telemetry_callback_metadata() - ) :: - {:telemetry_result, {result, telemetry_callback_metadata()}} - when result: any() - def state_result(result, metadata) do - {:telemetry_result, {result, metadata}} + other -> + Logger.warning( + "Telemetry span_component_callback failed due to incorrect callback return type" + ) + + {other, %{}} + end end @spec report_incoming_event(%{pad_ref: String.t()}) :: :ok @@ -278,7 +246,7 @@ defmodule Membrane.Core.Telemetry do end end - defp state_module_to_atom(Membrane.Core.Element.State), do: :element - defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin - defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline + def state_module_to_atom(Membrane.Core.Element.State), do: :element + def state_module_to_atom(Membrane.Core.Bin.State), do: :bin + def state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline end diff --git a/lib/membrane/element/callback_context.ex b/lib/membrane/element/callback_context.ex index 8e7a783fd..de6289842 100644 --- a/lib/membrane/element/callback_context.ex +++ b/lib/membrane/element/callback_context.ex @@ -19,12 +19,14 @@ defmodule Membrane.Element.CallbackContext do `c:Membrane.Element.WithInputPads.handle_stream_format/4`. """ @type t :: %{ - :pads => %{Membrane.Pad.ref() => Membrane.Element.PadData.t()}, :clock => Membrane.Clock.t() | nil, - :parent_clock => Membrane.Clock.t() | nil, + :module => module(), :name => Membrane.Element.name(), + :pads => %{Membrane.Pad.ref() => Membrane.Element.PadData.t()}, + :parent_clock => Membrane.Clock.t() | nil, :playback => Membrane.Playback.t(), :resource_guard => Membrane.ResourceGuard.t(), + :setup_incomplete? => boolean(), :utility_supervisor => Membrane.UtilitySupervisor.t(), optional(:incoming_demand) => non_neg_integer(), optional(:pad_options) => map(), diff --git a/lib/membrane/pipeline/callback_context.ex b/lib/membrane/pipeline/callback_context.ex index 3c5a6fa6d..962bd912a 100644 --- a/lib/membrane/pipeline/callback_context.ex +++ b/lib/membrane/pipeline/callback_context.ex @@ -15,10 +15,12 @@ defmodule Membrane.Pipeline.CallbackContext do `c:Membrane.Pipeline.handle_crash_group_down/3`. """ @type t :: %{ - :clock => Membrane.Clock.t(), :children => %{Membrane.Child.name() => Membrane.ChildEntry.t()}, + :clock => Membrane.Clock.t(), + :module => module(), :playback => Membrane.Playback.t(), :resource_guard => Membrane.ResourceGuard.t(), + :setup_incomplete? => boolean(), :utility_supervisor => Membrane.UtilitySupervisor.t(), optional(:from) => [GenServer.from()], optional(:members) => [Membrane.Child.name()], diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 154ee6829..a64fa813c 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -54,29 +54,20 @@ defmodule Membrane.Telemetry do """ @type component_type :: :element | :bin | :pipeline - @type component_context :: + @type callback_context :: Element.CallbackContext.t() | Bin.CallbackContext.t() | Pipeline.CallbackContext.t() @typedoc """ - Component metadata included in each `t:callback_event_metadata/0` - Internal state is gathered before and after each handler callback. - State only represents component's state at the start of the callback - """ - @type component_metadata :: %{ - component_context: component_context(), - component_module: module(), - component_path: ComponentPath.path(), - internal_state_before: Element.state() | Bin.state() | Pipeline.state(), - internal_state_after: Element.state() | Bin.state() | Pipeline.state() - } - @typedoc """ Metadata included with each telemetry component's handler profiled """ @type callback_event_metadata :: %{ callback: atom(), callback_args: [any()], - component_metadata: component_metadata(), - component_type: component_type() + callback_context: callback_context(), + component_path: ComponentPath.path(), + component_type: component_type(), + internal_state_before: Element.state() | Bin.state() | Pipeline.state(), + internal_state_after: Element.state() | Bin.state() | Pipeline.state() | nil } @typedoc """ @@ -84,6 +75,15 @@ defmodule Membrane.Telemetry do """ @type event_type :: :link | :buffer | :queue_len | :stream_format | :event | :store | :take + @typedoc """ + Metadata included with each telemetry event + """ + @type event_metadata :: %{ + event: event_type(), + component_path: ComponentPath.path(), + component_type: component_type() + } + @typedoc """ Value of the link event * parent_component_path - process path of link's parent @@ -118,15 +118,6 @@ defmodule Membrane.Telemetry do | integer() } - @typedoc """ - Metadata included with each telemetry event - """ - @type event_metadata :: %{ - event: event_type(), - component_path: ComponentPath.path(), - component_metadata: any() - } - @doc """ Returns if the event type is configured to be gathered by Membrane's Core telemetry """ diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 573b85b46..6ca21d614 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -82,7 +82,7 @@ defmodule Membrane.TelemetryTest do %{component_path: [_, ^element_type]}}}, 1000 - assert results.monotonic_time < 0 + assert results.monotonic_time assert_receive {^ref, :telemetry_ack, {[:membrane, :element, ^event, :stop], results, @@ -113,7 +113,7 @@ defmodule Membrane.TelemetryTest do assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :handle_init, :start], results, %{}}} - assert results.monotonic_time != 0 + assert results.monotonic_time assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :handle_init, :stop], results, %{}}} @@ -123,7 +123,7 @@ defmodule Membrane.TelemetryTest do assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :handle_setup, :start], results, %{}}} - assert results.monotonic_time != 0 + assert results.monotonic_time assert_receive {^ref, :telemetry_ack, {[:membrane, :pipeline, :handle_setup, :stop], results, %{}}} From 24f6cb6c2aac4fd7a658fa49a21c90987d305c82 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 3 Feb 2025 15:48:47 +0100 Subject: [PATCH 34/46] Documentation of metadata passed to and from telemetry modules --- lib/membrane/core/callback_handler.ex | 2 +- lib/membrane/core/telemetry.ex | 3 ++- lib/membrane/telemetry.ex | 7 +++++++ 3 files changed, 10 insertions(+), 2 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 46e0928be..6506b92f3 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -179,8 +179,8 @@ defmodule Membrane.Core.CallbackHandler do callback: callback, callback_args: args, callback_context: context, - component_type: state.module, component_path: ComponentPath.get(), + component_type: state.module, internal_state_before: state.internal_state, internal_state_after: nil } diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index a6129ad8e..72a9bc611 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -162,7 +162,7 @@ defmodule Membrane.Core.Telemetry do end @doc """ - Reports an arbitrary span of a function consistent with `span/3` format in `:telementry` + Reports a span of a compoment callback function in a format consistent with `span/3` in `:telementry` """ @spec span_component_callback( (-> CallbackHandler.callback_return() | any()), @@ -183,6 +183,7 @@ defmodule Membrane.Core.Telemetry do defp report_span(f, meta) do case f.() do {_actions, int_state} = res -> + # Append the internal state returned from the callback to the metadata {res, %{meta | internal_state_after: int_state}} other -> diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index a64fa813c..10e154c62 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -59,6 +59,13 @@ defmodule Membrane.Telemetry do @typedoc """ Metadata included with each telemetry component's handler profiled + * callback - name of the callback function + * callback_args - arguments passed to the callback + * callback_context - context of the callback consistent with Membrane.*.CallbackContext + * component_path - path of the component in the pipeline consistent with t:ComponentPath.path/0 + * component_type - atom representation of the base component type + * internal_state_before - state of the component before the callback execution + * internal_state_after - state of the component after the callback execution, it's `nil` on :start and :exception events """ @type callback_event_metadata :: %{ callback: atom(), From 7041bf9aee13958e5d24b271c7100d30631058d8 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 3 Feb 2025 15:55:46 +0100 Subject: [PATCH 35/46] Satisfy FilterAggregator.Context --- lib/membrane/core/filter_aggregator/context.ex | 2 ++ lib/membrane/core/telemetry.ex | 10 ++++------ 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/lib/membrane/core/filter_aggregator/context.ex b/lib/membrane/core/filter_aggregator/context.ex index e1e42463f..2ddf6b8b4 100644 --- a/lib/membrane/core/filter_aggregator/context.ex +++ b/lib/membrane/core/filter_aggregator/context.ex @@ -37,12 +37,14 @@ defmodule Membrane.Core.FilterAggregator.Context do |> Map.new(fn {name, description} -> {name, build_pad_data(description)} end) %{ + module: module, pads: pads_data, clock: nil, name: name, parent_clock: nil, playback: :stopped, resource_guard: agg_ctx.resource_guard, + setup_incomplete?: true, utility_supervisor: agg_ctx.utility_supervisor } end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 72a9bc611..320b74ea2 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -5,7 +5,6 @@ defmodule Membrane.Core.Telemetry do # library. It uses compile time flags from `config.exs` to determine which events should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. - require Logger alias Membrane.Core.CallbackHandler alias Membrane.Core.Parent.Link @@ -15,13 +14,12 @@ defmodule Membrane.Core.Telemetry do alias Membrane.Pad alias Membrane.Telemetry - require Membrane.Logger - require Membrane.Bin, as: Bin require Membrane.Element.Base, as: ElementBase require Membrane.Element.WithOutputPads require Membrane.Element.WithInputPads require Membrane.Pipeline, as: Pipeline + require Logger require Membrane.Core.LegacyTelemetry, as: LegacyTelemetry @@ -247,7 +245,7 @@ defmodule Membrane.Core.Telemetry do end end - def state_module_to_atom(Membrane.Core.Element.State), do: :element - def state_module_to_atom(Membrane.Core.Bin.State), do: :bin - def state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline + defp state_module_to_atom(Membrane.Core.Element.State), do: :element + defp state_module_to_atom(Membrane.Core.Bin.State), do: :bin + defp state_module_to_atom(Membrane.Core.Pipeline.State), do: :pipeline end From 72ca1be0d31aab4e9623a5502d12a4534fc0fe1c Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 3 Feb 2025 16:39:50 +0100 Subject: [PATCH 36/46] Documentation of metadata passed to and from telemetry modules --- config/config.exs | 2 +- lib/membrane/core/callback_handler.ex | 60 +++++++++++---------- lib/membrane/core/telemetry.ex | 76 ++++++++++++--------------- lib/membrane/telemetry.ex | 58 ++++++++++---------- test/membrane/telemetry_test.exs | 28 +++++----- 5 files changed, 109 insertions(+), 115 deletions(-) diff --git a/config/config.exs b/config/config.exs index c6bc705b3..71fec8e6f 100644 --- a/config/config.exs +++ b/config/config.exs @@ -15,7 +15,7 @@ if config_env() == :test do bin: :all, pipeline: :all ], - events: :all + datapoints: :all # config to test legacy version of telemetry # config :membrane_core, :telemetry_flags, [ diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 6506b92f3..c29688cd6 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -127,7 +127,7 @@ defmodule Membrane.Core.CallbackHandler do end @spec exec_callback(callback :: atom, args :: list, handler_params, state) :: - {list, internal_state} + {list, internal_state} | no_return() defp exec_callback( callback, args, @@ -137,37 +137,39 @@ defmodule Membrane.Core.CallbackHandler do context = context_fun.(state) args = args ++ [context, internal_state] - callback_result = - try do - fn -> apply(module, callback, args) end - |> report_telemetry(callback, args, state, context) - rescue - e in UndefinedFunctionError -> - _ignored = - with %{module: ^module, function: ^callback, arity: arity} <- e do - reraise CallbackError, - [ - kind: :not_implemented, - callback: {module, callback}, - arity: arity, - args: args - ], - __STACKTRACE__ - end - - reraise e, __STACKTRACE__ + try do + fn -> + apply(module, callback, args) + |> validate_callback_result!(module, callback) end + |> report_telemetry(callback, args, state, context) + rescue + e in UndefinedFunctionError -> + _ignored = + with %{module: ^module, function: ^callback, arity: arity} <- e do + reraise CallbackError, + [ + kind: :not_implemented, + callback: {module, callback}, + arity: arity, + args: args + ], + __STACKTRACE__ + end + + reraise e, __STACKTRACE__ + end + end - case callback_result do - {actions, _state} when is_list(actions) -> - callback_result + defp validate_callback_result!({actions, _state} = callback_result) when is_list(actions) do + callback_result + end - _result -> - raise CallbackError, - kind: :bad_return, - callback: {module, callback}, - value: callback_result - end + defp validate_callback_result!(callback_result, module, callback) do + raise CallbackError, + kind: :bad_return, + callback: {module, callback}, + value: callback_result end defp report_telemetry(f, callback, args, state, context) do diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 320b74ea2..12942d46f 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -1,6 +1,6 @@ defmodule Membrane.Core.Telemetry do @moduledoc false - # This module provides a way to gather events from running Membrane components, as well + # This module provides a way to gather datapoints and spans from running Membrane components, as well # as exposing these events in a format idiomatic to [Telemetry](https://hexdocs.pm/telemetry/) # library. It uses compile time flags from `config.exs` to determine which events should be # collected and propagated. This avoids unnecessary runtime overhead when telemetry is not needed. @@ -52,7 +52,7 @@ defmodule Membrane.Core.Telemetry do @spec legacy?() :: boolean() def legacy?(), do: @legacy? - # Handles telemetry events that were measured before but differ in how they were emitted + # Handles telemetry datapoints that were measured before but differ in how they were emitted # It's public to avoid dialyzer warnings. Not intended for external use @spec do_legacy_telemetry(atom(), Macro.t()) :: Macro.t() def do_legacy_telemetry(:link, lazy_block) do @@ -75,25 +75,25 @@ defmodule Membrane.Core.Telemetry do nil callbacks_list when is_list(callbacks_list) -> - for event <- callbacks_list do - if event not in @possible_callbacks[component] do + for callback <- callbacks_list do + if callback not in @possible_callbacks[component] do raise """ - Invalid telemetry flag: #{inspect(event)}. + Invalid telemetry flag: #{inspect(callback)}. Possible values for #{component} are: #{inspect(@possible_callbacks[component])} """ end - def handler_reported?(unquote(component), unquote(event)), do: true + def handler_reported?(unquote(component), unquote(callback)), do: true end end end def handler_reported?(_component, _callback), do: false - @spec event_gathered?(any()) :: false | nil | true - def event_gathered?(event) do - events = @config[:events] - events && (events == :all || event in events) + @spec datapoint_gathered?(any()) :: false | nil | true + def datapoint_gathered?(datapoint) do + datapoints = @config[:datapoints] + datapoints && (datapoints == :all || datapoint in datapoints) end @spec tracked_callbacks_available() :: [ @@ -125,22 +125,22 @@ defmodule Membrane.Core.Telemetry do end end - defmacrop report_event(event_name, do: lazy_block) do - unless Macro.quoted_literal?(event_name), do: raise("Event type must be a literal") + defmacrop report_datapoint(datapoint_name, do: lazy_block) do + unless Macro.quoted_literal?(datapoint_name), do: raise("Datapoint type must be a literal") cond do @legacy? -> - do_legacy_telemetry(event_name, lazy_block) + do_legacy_telemetry(datapoint_name, lazy_block) - event_gathered?(event_name) -> + datapoint_gathered?(datapoint_name) -> quote do value = unquote(lazy_block) :telemetry.execute( - [:membrane, :event, unquote(event_name)], + [:membrane, :datapoint, unquote(datapoint_name)], %{value: value}, %{ - event: unquote(event_name), + datapoint: unquote(datapoint_name), component_path: ComponentPath.get(), component_metadata: Logger.metadata() } @@ -150,7 +150,7 @@ defmodule Membrane.Core.Telemetry do true -> quote do _fn = fn -> - _unused = unquote(event_name) + _unused = unquote(datapoint_name) _unused = unquote(lazy_block) end @@ -163,70 +163,60 @@ defmodule Membrane.Core.Telemetry do Reports a span of a compoment callback function in a format consistent with `span/3` in `:telementry` """ @spec span_component_callback( - (-> CallbackHandler.callback_return() | any()), + (-> CallbackHandler.callback_return() | no_return()), module(), atom(), - Telemetry.callback_event_metadata() - ) :: CallbackHandler.callback_return() | any() + Telemetry.callback_span_metadata() + ) :: CallbackHandler.callback_return() | no_return() def span_component_callback(f, component_module, callback, meta) do component_type = state_module_to_atom(component_module) if handler_reported?(component_type, callback) do - :telemetry.span([:membrane, component_type, callback], meta, fn -> report_span(f, meta) end) - else - f.() - end - end + :telemetry.span([:membrane, component_type, callback], meta, fn -> + {_actions, int_state} = res = f.() - defp report_span(f, meta) do - case f.() do - {_actions, int_state} = res -> # Append the internal state returned from the callback to the metadata {res, %{meta | internal_state_after: int_state}} - - other -> - Logger.warning( - "Telemetry span_component_callback failed due to incorrect callback return type" - ) - - {other, %{}} + end) + else + f.() end end @spec report_incoming_event(%{pad_ref: String.t()}) :: :ok - def report_incoming_event(meta), do: report_event(:event, do: meta) + def report_incoming_event(meta), do: report_datapoint(:event, do: meta) @spec report_stream_format(Membrane.StreamFormat.t(), String.t()) :: :ok def report_stream_format(format, pad_ref), - do: report_event(:stream_format, do: %{format: format, pad_ref: pad_ref}) + do: report_datapoint(:stream_format, do: %{format: format, pad_ref: pad_ref}) @spec report_buffer(integer() | list()) :: :ok def report_buffer(length) def report_buffer(length) when is_integer(length), - do: report_event(:buffer, do: length) + do: report_datapoint(:buffer, do: length) def report_buffer(buffers) do - report_event(:buffer, do: length(buffers)) + report_datapoint(:buffer, do: length(buffers)) end @spec report_store(integer(), String.t()) :: :ok def report_store(size, log_tag) do - report_event :store do + report_datapoint :store do %{size: size, log_tag: log_tag} end end @spec report_take(integer(), String.t()) :: :ok def report_take(size, log_tag) do - report_event :take do + report_datapoint :take do %{size: size, log_tag: log_tag} end end @spec report_queue_len(pid()) :: :ok def report_queue_len(pid) do - report_event :queue_len do + report_datapoint :queue_len do {:message_queue_len, len} = Process.info(pid, :message_queue_len) %{len: len} end @@ -234,7 +224,7 @@ defmodule Membrane.Core.Telemetry do @spec report_link(Link.Endpoint.t(), Link.Endpoint.t()) :: :ok def report_link(from, to) do - report_event :link do + report_datapoint :link do %{ parent_component_path: ComponentPath.get_formatted(), from: inspect(from.child), diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 10e154c62..b4d7169a5 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -8,7 +8,7 @@ defmodule Membrane.Telemetry do that will be attached to `:telemetry` package to process generated measurements. ## Instrumentation - The following events are published by Membrane's Core with following measurement types and metadata: + The following telemetric events are published by Membrane's Core components: * `[:membrane, :element | :bin | :pipeline, handler, :start | :stop | :exception]` - where handler is any possible handle_* function defined for a component. @@ -16,14 +16,14 @@ defmodule Membrane.Telemetry do * `:stop` - when the handler finishes execution * `:exception` - when the component's handler crashes during execution - * `[:membrane, :event, event_type]` - - where event_type is any of the available event types (see below) + * `[:membrane, :datapoint, datapoint_type]` - + where datapoint_type is any of the available datapoint types (see below) - ## Enabling specific events - A lot of events can happen hundreds times per second such as registering that a buffer has been sent/processed. + ## Enabling specific datapoints + A lot of datapoints can happen hundreds times per second such as registering that a buffer has been sent/processed. This behaviour can come with a great performance penalties but may be helpful for certain discoveries. To avoid any runtime overhead - when the reporting is not necessary all events/events are hidden behind a compile-time feature flags. + when the reporting is not necessary all spans/datapoints are hidden behind a compile-time feature flags. To enable a particular measurement one must recompile membrane core with the following config put inside user's application `config.exs` file: @@ -31,13 +31,15 @@ defmodule Membrane.Telemetry do config :membrane_core, telemetry_flags: [ tracked_callbacks: [ - [:handle_setup, ...] | :all - ] - events: [:buffer, ...] | :all + bin: [:handle_setup, ...] | :all, + element: [:handle_init, ...] | :all, + pipeline: [:handle_init, ...] | :all + ], + datapoints: [:buffer, ...] | :all ] ``` - Available events are: + Available datapoints are: * `:link` - reports the number of links created in the pipeline * `:buffer` - number of buffers being sent from a particular element * `:queue_len` - number of messages in element's message queue during GenServer's `handle_info` invocation @@ -67,7 +69,7 @@ defmodule Membrane.Telemetry do * internal_state_before - state of the component before the callback execution * internal_state_after - state of the component after the callback execution, it's `nil` on :start and :exception events """ - @type callback_event_metadata :: %{ + @type callback_span_metadata :: %{ callback: atom(), callback_args: [any()], callback_context: callback_context(), @@ -78,50 +80,50 @@ defmodule Membrane.Telemetry do } @typedoc """ - Types of telemetry events reported by Membrane Core + Types of telemetry datapoints reported by Membrane Core """ - @type event_type :: :link | :buffer | :queue_len | :stream_format | :event | :store | :take + @type datapoint_type :: :link | :buffer | :queue_len | :stream_format | :event | :store | :take @typedoc """ Metadata included with each telemetry event """ - @type event_metadata :: %{ - event: event_type(), + @type datapoint_metadata :: %{ + datapoint: datapoint_type(), component_path: ComponentPath.path(), component_type: component_type() } @typedoc """ - Value of the link event + Value of the link datapoint * parent_component_path - process path of link's parent * from - from element name * to - to element name * pad_from - from's pad name * pad_to - to's pad name """ - @type link_event_value :: %{ + @type link_datapoint_value :: %{ parent_component_path: String.t(), from: String.t(), to: String.t(), pad_from: String.t(), pad_to: String.t() } - @type buffer_event_value :: integer() - @type queue_len_event_value :: integer() - @type stream_format_event_value :: %{format: map(), pad_ref: String.t()} - @type incoming_event_value :: String.t() - @type store_event_value :: %{value: integer(), log_tag: String.t()} + @type buffer_datapoint_value :: integer() + @type queue_len_datapoint_value :: integer() + @type stream_format_datapoint_value :: %{format: map(), pad_ref: String.t()} + @type incoming_datapoint_value :: String.t() + @type store_datapoint_value :: %{value: integer(), log_tag: String.t()} @typedoc """ Value of the specific event gathered """ - @type event_value :: %{ + @type datapoint_value :: %{ value: - buffer_event_value() - | queue_len_event_value() - | stream_format_event_value() - | incoming_event_value() - | store_event_value() + buffer_datapoint_value() + | queue_len_datapoint_value() + | stream_format_datapoint_value() + | incoming_datapoint_value() + | store_datapoint_value() | integer() } diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 6ca21d614..f4f58b2cf 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -1,6 +1,6 @@ defmodule Membrane.TelemetryTest do @moduledoc """ - Test suite for Membrane telemetry public API. It tests if telemetry events are reported + Test suite for Membrane telemetry public API. It tests if telemetry datapoints are reported properly for all event types and span types upon attaching to the :telemetry system. """ @@ -32,8 +32,8 @@ defmodule Membrane.TelemetryTest do end defmodule TelemetryListener do - @spec handle_event(atom(), any(), map(), map()) :: :ok - def handle_event(name, value, metadata, %{dest: pid, ref: ref}) do + @spec handle_measurements(atom(), any(), map(), map()) :: :ok + def handle_measurements(name, value, metadata, %{dest: pid, ref: ref}) do pid |> send({ref, :telemetry_ack, {name, value, metadata}}) end end @@ -72,20 +72,20 @@ defmodule Membrane.TelemetryTest do # Test each lifecycle step for each element type for element_type <- @paths, - event <- @spans do - test "#{element_type}/#{event}", %{ref: ref} do + span <- @spans do + test "#{element_type}/#{span}", %{ref: ref} do element_type = unquote(element_type) - event = unquote(event) + span = unquote(span) assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :start], results, + {[:membrane, :element, ^span, :start], results, %{component_path: [_, ^element_type]}}}, 1000 assert results.monotonic_time assert_receive {^ref, :telemetry_ack, - {[:membrane, :element, ^event, :stop], results, + {[:membrane, :element, ^span, :stop], results, %{component_path: [_, ^element_type]}}}, 1000 @@ -99,9 +99,9 @@ defmodule Membrane.TelemetryTest do ref = make_ref() spans = - for event <- @spans, + for span <- @spans, step <- @steps do - [:membrane, :pipeline, event, step] + [:membrane, :pipeline, span, step] end setup_pipeline_for_callbacks(spans, child_spec, ref) @@ -143,7 +143,7 @@ defmodule Membrane.TelemetryTest do [:membrane, :element, :handle_parent_notification, :exception] ] - :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ + :telemetry.attach_many(ref, spans, &TelemetryListener.handle_measurements/4, %{ dest: self(), ref: ref }) @@ -175,7 +175,7 @@ defmodule Membrane.TelemetryTest do end end - describe "Telemetry properly reports following events: " do + describe "Telemetry properly reports following datapoints: " do test "Link", %{child_spec: child_spec} do ref = setup_pipeline_for(:link, child_spec) @@ -257,7 +257,7 @@ defmodule Membrane.TelemetryTest do :telemetry.attach( ref, [:membrane, :event, event], - &TelemetryListener.handle_event/4, + &TelemetryListener.handle_measurements/4, %{dest: self(), ref: ref} ) @@ -267,7 +267,7 @@ defmodule Membrane.TelemetryTest do end defp setup_pipeline_for_callbacks(spans, child_spec, ref) do - :telemetry.attach_many(ref, spans, &TelemetryListener.handle_event/4, %{ + :telemetry.attach_many(ref, spans, &TelemetryListener.handle_measurements/4, %{ dest: self(), ref: ref }) From fe86693369bf82e32fa037ffa2800f7b9f252e45 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Mon, 3 Feb 2025 16:52:32 +0100 Subject: [PATCH 37/46] Event -> Datapoint --- lib/membrane/core/callback_handler.ex | 3 ++- lib/membrane/telemetry.ex | 4 ++-- test/membrane/telemetry_test.exs | 17 +++++++++-------- 3 files changed, 13 insertions(+), 11 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index c29688cd6..8f317cb2f 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -161,7 +161,8 @@ defmodule Membrane.Core.CallbackHandler do end end - defp validate_callback_result!({actions, _state} = callback_result) when is_list(actions) do + defp validate_callback_result!({actions, _state} = callback_result, _module, _cb) + when is_list(actions) do callback_result end diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index b4d7169a5..eeb540960 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -130,8 +130,8 @@ defmodule Membrane.Telemetry do @doc """ Returns if the event type is configured to be gathered by Membrane's Core telemetry """ - @spec event_gathered?(any()) :: boolean() - defdelegate event_gathered?(event_type), to: Membrane.Core.Telemetry + @spec datapoint_gathered?(any()) :: boolean() + defdelegate datapoint_gathered?(event_type), to: Membrane.Core.Telemetry @doc """ Lists all components and their callbacks tracked by Membrane's Core telemetry diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index f4f58b2cf..29bca69fc 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -179,10 +179,10 @@ defmodule Membrane.TelemetryTest do test "Link", %{child_spec: child_spec} do ref = setup_pipeline_for(:link, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :link], link1, metadata}} + assert_receive {^ref, :telemetry_ack, {[:membrane, :datapoint, :link], link1, metadata}} assert_event_metadata(metadata) - assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :link], link2, metadata}} + assert_receive {^ref, :telemetry_ack, {[:membrane, :datapoint, :link], link2, metadata}} assert_event_metadata(metadata) assert [ @@ -207,7 +207,7 @@ defmodule Membrane.TelemetryTest do ref = setup_pipeline_for(:stream_format, child_spec) assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :stream_format], measurement, metadata}} + {[:membrane, :datapoint, :stream_format], measurement, metadata}} assert measurement.value.format.type == :bytestream assert_event_metadata(metadata) @@ -218,7 +218,7 @@ defmodule Membrane.TelemetryTest do for _ <- 1..3 do assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :buffer], measurement, metadata}} + {[:membrane, :datapoint, :buffer], measurement, metadata}} assert measurement.value != 0 assert_event_metadata(metadata) @@ -228,7 +228,8 @@ defmodule Membrane.TelemetryTest do test "Event", %{child_spec: child_spec} do ref = setup_pipeline_for(:event, child_spec) - assert_receive {^ref, :telemetry_ack, {[:membrane, :event, :event], measurement, metadata}} + assert_receive {^ref, :telemetry_ack, + {[:membrane, :datapoint, :event], measurement, metadata}} assert measurement.value.pad_ref == ":input" assert_event_metadata(metadata) @@ -238,7 +239,7 @@ defmodule Membrane.TelemetryTest do ref = setup_pipeline_for(:queue_len, child_spec) assert_receive {^ref, :telemetry_ack, - {[:membrane, :event, :queue_len], measurement, metadata}} + {[:membrane, :datapoint, :queue_len], measurement, metadata}} assert measurement.value assert_event_metadata(metadata) @@ -246,7 +247,7 @@ defmodule Membrane.TelemetryTest do end defp assert_event_metadata(metadata) do - assert is_atom(metadata.event) + assert is_atom(metadata.datapoint) assert is_list(metadata.component_path) assert metadata.component_metadata end @@ -256,7 +257,7 @@ defmodule Membrane.TelemetryTest do :telemetry.attach( ref, - [:membrane, :event, event], + [:membrane, :datapoint, event], &TelemetryListener.handle_measurements/4, %{dest: self(), ref: ref} ) From 17dfe2798fd809274ffec6de83c275d1662e467a Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 4 Feb 2025 16:03:25 +0100 Subject: [PATCH 38/46] Update lib/membrane/telemetry.ex MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com> --- lib/membrane/telemetry.ex | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index eeb540960..c8265414d 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -12,9 +12,9 @@ defmodule Membrane.Telemetry do * `[:membrane, :element | :bin | :pipeline, handler, :start | :stop | :exception]` - where handler is any possible handle_* function defined for a component. - * `:start` - when the handler begins execution - * `:stop` - when the handler finishes execution - * `:exception` - when the component's handler crashes during execution + * `:start` - when the components begins callback's execution + * `:stop` - when the components finishes callback's execution + * `:exception` - when the component crashes during callback's execution * `[:membrane, :datapoint, datapoint_type]` - where datapoint_type is any of the available datapoint types (see below) From cf8efa1eea77be892176a1e5b1596b3b919626cf Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 4 Feb 2025 16:27:44 +0100 Subject: [PATCH 39/46] Comments addressed --- lib/membrane/core/callback_handler.ex | 18 +++++++---------- lib/membrane/core/telemetry.ex | 28 ++++++++++++++++++++++++--- lib/membrane/telemetry.ex | 10 +++++----- 3 files changed, 37 insertions(+), 19 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 8f317cb2f..9b418cbde 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -8,7 +8,6 @@ defmodule Membrane.Core.CallbackHandler do use Bunch alias Membrane.CallbackError - alias Membrane.ComponentPath require Membrane.Logger require Membrane.Core.Telemetry, as: Telemetry @@ -174,19 +173,16 @@ defmodule Membrane.Core.CallbackHandler do end defp report_telemetry(f, callback, args, state, context) do - Telemetry.span_component_callback( + Telemetry.track_component_callback( f, state.__struct__, callback, - %{ - callback: callback, - callback_args: args, - callback_context: context, - component_path: ComponentPath.get(), - component_type: state.module, - internal_state_before: state.internal_state, - internal_state_after: nil - } + Telemetry.callback_meta( + state, + callback, + args, + context + ) ) end diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 12942d46f..508bea5d9 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -9,6 +9,7 @@ defmodule Membrane.Core.Telemetry do alias Membrane.Core.Parent.Link alias Membrane.ComponentPath + alias Membrane.Element alias Membrane.Element.WithInputPads alias Membrane.Element.WithOutputPads alias Membrane.Pad @@ -162,13 +163,13 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports a span of a compoment callback function in a format consistent with `span/3` in `:telementry` """ - @spec span_component_callback( + @spec track_component_callback( (-> CallbackHandler.callback_return() | no_return()), module(), atom(), Telemetry.callback_span_metadata() ) :: CallbackHandler.callback_return() | no_return() - def span_component_callback(f, component_module, callback, meta) do + def track_component_callback(f, component_module, callback, meta) do component_type = state_module_to_atom(component_module) if handler_reported?(component_type, callback) do @@ -176,13 +177,34 @@ defmodule Membrane.Core.Telemetry do {_actions, int_state} = res = f.() # Append the internal state returned from the callback to the metadata - {res, %{meta | internal_state_after: int_state}} + {res, %{meta | state_after_callback: int_state}} end) else f.() end end + @doc """ + Formats metadata for a span of a component callback function + """ + @spec callback_meta( + Element.state() | Bin.state() | Pipeline.state(), + atom(), + [any()], + Telemetry.callback_context() + ) :: Telemetry.callback_span_metadata() + def callback_meta(state, callback, args, context) do + %{ + callback: callback, + callback_args: args, + callback_context: context, + component_path: ComponentPath.get(), + component_type: state.module, + state_before_callback: state.internal_state, + state_after_callback: nil + } + end + @spec report_incoming_event(%{pad_ref: String.t()}) :: :ok def report_incoming_event(meta), do: report_datapoint(:event, do: meta) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index c8265414d..38ed27282 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -66,8 +66,8 @@ defmodule Membrane.Telemetry do * callback_context - context of the callback consistent with Membrane.*.CallbackContext * component_path - path of the component in the pipeline consistent with t:ComponentPath.path/0 * component_type - atom representation of the base component type - * internal_state_before - state of the component before the callback execution - * internal_state_after - state of the component after the callback execution, it's `nil` on :start and :exception events + * state_before_callback - state of the component before the callback execution + * state_after_callback - state of the component after the callback execution, it's `nil` on :start and :exception events """ @type callback_span_metadata :: %{ callback: atom(), @@ -75,8 +75,8 @@ defmodule Membrane.Telemetry do callback_context: callback_context(), component_path: ComponentPath.path(), component_type: component_type(), - internal_state_before: Element.state() | Bin.state() | Pipeline.state(), - internal_state_after: Element.state() | Bin.state() | Pipeline.state() | nil + state_before_callback: Element.state() | Bin.state() | Pipeline.state(), + state_after_callback: Element.state() | Bin.state() | Pipeline.state() | nil } @typedoc """ @@ -131,7 +131,7 @@ defmodule Membrane.Telemetry do Returns if the event type is configured to be gathered by Membrane's Core telemetry """ @spec datapoint_gathered?(any()) :: boolean() - defdelegate datapoint_gathered?(event_type), to: Membrane.Core.Telemetry + defdelegate datapoint_gathered?(type), to: Membrane.Core.Telemetry @doc """ Lists all components and their callbacks tracked by Membrane's Core telemetry From fe9d0ebb70c332b26a43bad84749ee8cc41ba536 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 4 Feb 2025 16:29:22 +0100 Subject: [PATCH 40/46] Track callback handler name --- lib/membrane/core/callback_handler.ex | 2 +- lib/membrane/core/telemetry.ex | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index 9b418cbde..de0162bbc 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -173,7 +173,7 @@ defmodule Membrane.Core.CallbackHandler do end defp report_telemetry(f, callback, args, state, context) do - Telemetry.track_component_callback( + Telemetry.track_callback_handler( f, state.__struct__, callback, diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 508bea5d9..72ed3a6f7 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -163,13 +163,13 @@ defmodule Membrane.Core.Telemetry do @doc """ Reports a span of a compoment callback function in a format consistent with `span/3` in `:telementry` """ - @spec track_component_callback( + @spec track_callback_handler( (-> CallbackHandler.callback_return() | no_return()), module(), atom(), Telemetry.callback_span_metadata() ) :: CallbackHandler.callback_return() | no_return() - def track_component_callback(f, component_module, callback, meta) do + def track_callback_handler(f, component_module, callback, meta) do component_type = state_module_to_atom(component_module) if handler_reported?(component_type, callback) do From 70cc188dd28e022bb2cec75319c0bddd6c7a11c7 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Tue, 4 Feb 2025 16:54:12 +0100 Subject: [PATCH 41/46] Config cleanup --- config/config.exs | 18 ------------------ test/membrane/telemetry_test.exs | 24 ++++++++++++++++++++++++ 2 files changed, 24 insertions(+), 18 deletions(-) diff --git a/config/config.exs b/config/config.exs index 71fec8e6f..c73f8283a 100644 --- a/config/config.exs +++ b/config/config.exs @@ -16,22 +16,4 @@ if config_env() == :test do pipeline: :all ], datapoints: :all - - # config to test legacy version of telemetry - # config :membrane_core, :telemetry_flags, [ - # :report_init, - # :report_terminate, - # :report_buffer, - # :report_queue, - # :report_link, - # metrics: [ - # :buffer, - # :bitrate, - # :queue_len, - # :stream_format, - # :event, - # :store, - # :take_and_demand - # ] - # ] end diff --git a/test/membrane/telemetry_test.exs b/test/membrane/telemetry_test.exs index 29bca69fc..8d3dee49e 100644 --- a/test/membrane/telemetry_test.exs +++ b/test/membrane/telemetry_test.exs @@ -2,6 +2,30 @@ defmodule Membrane.TelemetryTest do @moduledoc """ Test suite for Membrane telemetry public API. It tests if telemetry datapoints are reported properly for all event types and span types upon attaching to the :telemetry system. + + + Remove below with 2.0.0 release: + In case of a need to test legacy telemetry paste the following snippet into the config file: + + # config to test legacy version of telemetry + # config :membrane_core, :telemetry_flags, [ + # :report_init, + # :report_terminate, + # :report_buffer, + # :report_queue, + # :report_link, + # metrics: [ + # :buffer, + # :bitrate, + # :queue_len, + # :stream_format, + # :event, + # :store, + # :take_and_demand + # ] + # ] + + ``` """ use ExUnit.Case, async: false From e846d7ada4551d1aed4e46f64a698a6966484fd8 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Wed, 5 Feb 2025 15:15:40 +0100 Subject: [PATCH 42/46] Faulty f+r --- lib/membrane/telemetry.ex | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 38ed27282..d8f76011e 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -111,7 +111,7 @@ defmodule Membrane.Telemetry do @type buffer_datapoint_value :: integer() @type queue_len_datapoint_value :: integer() @type stream_format_datapoint_value :: %{format: map(), pad_ref: String.t()} - @type incoming_datapoint_value :: String.t() + @type incoming_event_datapoint_value :: String.t() @type store_datapoint_value :: %{value: integer(), log_tag: String.t()} @typedoc """ @@ -122,7 +122,7 @@ defmodule Membrane.Telemetry do buffer_datapoint_value() | queue_len_datapoint_value() | stream_format_datapoint_value() - | incoming_datapoint_value() + | incoming_event_datapoint_value() | store_datapoint_value() | integer() } From 9583a5d3d482e13554965f3dd592dff790084136 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 6 Feb 2025 10:43:23 +0100 Subject: [PATCH 43/46] Better public API --- lib/membrane/core/callback_handler.ex | 16 +-------------- lib/membrane/core/telemetry.ex | 28 +++++++++++++-------------- 2 files changed, 15 insertions(+), 29 deletions(-) diff --git a/lib/membrane/core/callback_handler.ex b/lib/membrane/core/callback_handler.ex index de0162bbc..dfb565372 100644 --- a/lib/membrane/core/callback_handler.ex +++ b/lib/membrane/core/callback_handler.ex @@ -141,7 +141,7 @@ defmodule Membrane.Core.CallbackHandler do apply(module, callback, args) |> validate_callback_result!(module, callback) end - |> report_telemetry(callback, args, state, context) + |> Telemetry.track_callback_handler(callback, args, state, context) rescue e in UndefinedFunctionError -> _ignored = @@ -172,20 +172,6 @@ defmodule Membrane.Core.CallbackHandler do value: callback_result end - defp report_telemetry(f, callback, args, state, context) do - Telemetry.track_callback_handler( - f, - state.__struct__, - callback, - Telemetry.callback_meta( - state, - callback, - args, - context - ) - ) - end - @spec handle_callback_result( {actions :: Keyword.t(), internal_state}, callback :: atom, diff --git a/lib/membrane/core/telemetry.ex b/lib/membrane/core/telemetry.ex index 72ed3a6f7..0b610dc8d 100644 --- a/lib/membrane/core/telemetry.ex +++ b/lib/membrane/core/telemetry.ex @@ -165,12 +165,21 @@ defmodule Membrane.Core.Telemetry do """ @spec track_callback_handler( (-> CallbackHandler.callback_return() | no_return()), - module(), atom(), - Telemetry.callback_span_metadata() + list(), + Element.state() | Bin.state() | Pipeline.state(), + Telemetry.callback_context() ) :: CallbackHandler.callback_return() | no_return() - def track_callback_handler(f, component_module, callback, meta) do - component_type = state_module_to_atom(component_module) + def track_callback_handler(f, callback, args, state, context) do + meta = + callback_meta( + state, + callback, + args, + context + ) + + component_type = state_module_to_atom(state.__struct__) if handler_reported?(component_type, callback) do :telemetry.span([:membrane, component_type, callback], meta, fn -> @@ -184,16 +193,7 @@ defmodule Membrane.Core.Telemetry do end end - @doc """ - Formats metadata for a span of a component callback function - """ - @spec callback_meta( - Element.state() | Bin.state() | Pipeline.state(), - atom(), - [any()], - Telemetry.callback_context() - ) :: Telemetry.callback_span_metadata() - def callback_meta(state, callback, args, context) do + defp callback_meta(state, callback, args, context) do %{ callback: callback, callback_args: args, From 9894437d2ad23acc3d4dc2b1ef289419346a15c3 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 6 Feb 2025 11:45:36 +0100 Subject: [PATCH 44/46] Update lib/membrane/telemetry.ex MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com> --- lib/membrane/telemetry.ex | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index d8f76011e..077a88a1e 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -10,8 +10,8 @@ defmodule Membrane.Telemetry do ## Instrumentation The following telemetric events are published by Membrane's Core components: - * `[:membrane, :element | :bin | :pipeline, handler, :start | :stop | :exception]` - - where handler is any possible handle_* function defined for a component. + * `[:membrane, :element | :bin | :pipeline, callback, :start | :stop | :exception]` - + where `callback` is any possible handle_* function defined for a component. * `:start` - when the components begins callback's execution * `:stop` - when the components finishes callback's execution * `:exception` - when the component crashes during callback's execution From 94ba04a1f2aabb106f71802fb01d0ca336cfbd35 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 6 Feb 2025 11:55:48 +0100 Subject: [PATCH 45/46] Documentation changes --- lib/membrane/telemetry.ex | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 077a88a1e..216f2f2d1 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -10,8 +10,8 @@ defmodule Membrane.Telemetry do ## Instrumentation The following telemetric events are published by Membrane's Core components: - * `[:membrane, :element | :bin | :pipeline, callback, :start | :stop | :exception]` - - where `callback` is any possible handle_* function defined for a component. + * `[:membrane, :element | :bin | :pipeline, handler, :start | :stop | :exception]` - + where handler is any possible handle_* function defined for a component. * `:start` - when the components begins callback's execution * `:stop` - when the components finishes callback's execution * `:exception` - when the component crashes during callback's execution @@ -39,6 +39,8 @@ defmodule Membrane.Telemetry do ] ``` + Datapoint metrics are to be deprecated in the future (2.0) in favor of spans. They are still available for now. + Available datapoints are: * `:link` - reports the number of links created in the pipeline * `:buffer` - number of buffers being sent from a particular element From dc707acb6ac280235d55ec904b17789ddc00f4f3 Mon Sep 17 00:00:00 2001 From: Krzysztof Wende Date: Thu, 6 Feb 2025 11:57:50 +0100 Subject: [PATCH 46/46] faulty merge --- lib/membrane/telemetry.ex | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/membrane/telemetry.ex b/lib/membrane/telemetry.ex index 216f2f2d1..e7d72eaf2 100644 --- a/lib/membrane/telemetry.ex +++ b/lib/membrane/telemetry.ex @@ -10,8 +10,8 @@ defmodule Membrane.Telemetry do ## Instrumentation The following telemetric events are published by Membrane's Core components: - * `[:membrane, :element | :bin | :pipeline, handler, :start | :stop | :exception]` - - where handler is any possible handle_* function defined for a component. + * `[:membrane, :element | :bin | :pipeline, callback, :start | :stop | :exception]` - + where callback is any possible handle_* function defined for a component. * `:start` - when the components begins callback's execution * `:stop` - when the components finishes callback's execution * `:exception` - when the component crashes during callback's execution