Telemetry (#905) #918

wende · 2024-12-06T11:19:43Z

Relates to #905

test/membrane/telemetry_test.exs

lib/membrane/core/callback_handler.ex

lib/membrane/core/bin.ex

FelonEkonom · 2024-12-30T12:44:57Z

I took a brief look at your changes and I commented things that caught my attention

wende · 2025-01-10T13:12:54Z

@FelonEkonom, could you provide an example of how the .config.exs file should look for the end user? This would help me a lot with separation of concerns.

config :membrane_core, :telemetry_flags,
    handlers: [
      element: [
        :init,
        :setup,
        :terminate_request,
        :playing,
        :parent_notification
      ],
      bin: :all,
      pipeline: :all
    ],
    metrics: :all

Is this example requiring excessive detail from the end user? Or would you consider it an adequate level of granularity?

FelonEkonom · 2025-01-10T15:01:40Z

@wende the example you proposed demands enough details from the user and in general it looks OK 👍

I would replace :playing, :demand and rest with full names of callbacks, I mean :handle_playing, :handle_demand, handle_buffer, handle_parent_notification etc. In the first case using :playing makes it not clear for me if the span will cover only the time when handle_playing is executed or if it will cover the whole time when the component is in playing playback. In the second case it could be not clear for me if we track the callback or e.g. demand action.

FelonEkonom · 2025-01-10T15:06:41Z

It could look like

config :membrane_core, :telemetry_flags,
    tracked_callbacks: [
      element: [
        :handle_init,
        :handle_playing,
        :handle_demand
      ],
      bin: :all,
      pipeline: :all
    ],
    metrics: :all

or simply

config :membrane_core, :telemetry_flags,
    tracked_callbacks: :all,
    metrics: :all

@varsill @mat-hek @Noarkhh WDYT guys?

lib/membrane/core/telemetry.ex

wende · 2025-01-16T10:35:22Z

lib/membrane/core/telemetry.ex

+  def report_metric(metric_name, measurement, metadata \\ %{}) do
+    if metric_measured?(metric_name) do
+      :telemetry.execute([:membrane, :metric, metric_name], %{value: measurement}, metadata)
    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
+      measurement


This one is currently unused. There used to be some metrics measured by legacy code of this purpose, but since it wasn't tested anywhere I treated it as dead code and removed it
A list of metrics that you want to measure would be appreciated.

I reimplemented metrics for: [link, buffer, bitrate, queue, stream_format, ~~event, store~~]

lib/membrane/telemetry.ex

wende · 2025-01-16T10:57:01Z

This is an MVP version of this PR. I'm going to need a list of desirable metrics to be measured, as well as some guidance on how to document Membrane.Telemetry and Membrane.Core.Telemetry in relation to each other

FelonEkonom

I haven't finished my review, but I am publishing some of the comments that I've made.

Further review soon 🔜

lib/membrane/core/telemetry.ex

lib/membrane/telemetry.ex

test/membrane/telemetry_test.exs

lib/membrane/core/telemetry.ex

FelonEkonom

It would be nice to have a piece of documentation that describes

how to enable metrics in config
what events are emitted and when
what is passed as events metadata
but you can wait with it until the code and API are more or less stable within this PR

Another thing is, please take a look at the CI: test_performance job doesn't work at all for now, but test and lint should pass

FelonEkonom · 2025-01-21T14:42:21Z

lib/membrane/core/callback_handler.ex

+        Telemetry.report_span(
+          state.__struct__,
+          callback,
+          fn ->
+            apply(module, callback, args)
+            |> Telemetry.state_result(internal_state, state)
+          end
+        )


IMO the structure of the code here and in related functions (Telemetry.report_span/3, Telemetry.state_result/3) is overcomplicated and it is hard to understand, which function or lambda does and returns what. I recommend to avoid any type of circular dependencies like the one we have here between Telemetry module and CallbackHandler.

What about creating a macro that would be used like

callback_result = Telemetry.with_callback_execution_span callback, internal_state, state, do apply(module, callback, args) end

Or eventually a function in Telemetry module that will take all data necessary to 1. execute a callback and 2. pass proper metadata to :telemetry event?

If you will have any question regarding writing such a macro - let me know

The purpose of Telemetry.state_result was exactly that to avoid circular dependency. I did incorrectly use it after all though.
Take a look at the most recent version. I don't believe there is a way to avoid circ dependency with a macro. Using this state_result/2 workaround while not ideal achieves better decoupling.

Not to mention there is little to no benefit of using a macro here, I don't think it's warranted but i'm open to discussion

The circular dependency could by avoided by writing function looking more or less like that

Telemetry.apply_within_span( fn () -> apply(module, callback, args) end, callback, args, internal_state, state )

and in Telemetry module:

def apply_within_span(lambda, callback, callback_args, internal_state, state) do report_span( state.__struct__, callback, fn -> apply(lambda) |> state_result(internal_state, state) end ) end

This same could be done with macro that could be used like in the example from my previous comment

defmacro with_callback_execution_span(callback, internal_state, state, do_block) do quote do if unquote(callback) |> tracked?(unquote(state).__struct__) do unquote(__MODULE__).apply_within_span( fn -> unquote(do_block) end, unquote(callback), unquote(args), unquote(internal_state), unquote(state) ) else unquote(do_block) end end end

The advantage of macro is that the code will look similar to e.g. OpenTelemetry.Tracer.with_span "id", do .... end and the usage of macro will be easier and more intuitive to read for somebody else

def apply_within_span(lambda, callback, callback_args, internal_state, state) do report_span( state.__struct__, callback, fn -> apply(lambda) |> state_result(internal_state, state) end ) end

This solution has the problem that internal state passed this way would be an old internal state, instead of the new one

You can get the new one from the value returned from apply(lambda)

For me it is overcomplicated and I still think that it is possible to write functions in Membrane.Core.Telemetry in a way that they will be much more intuitive to read. We can do pair-coding session to do so

You can get the new one from the value returned from apply(lambda)

But then we get a circular dependency of CallbackHandler using Telemetry and Telemetry module being specifically coded for CallbackHandler response of {actions, state}

test/membrane/telemetry_test.exs

lib/membrane/telemetry.ex

test/membrane/telemetry_test.exs

test/test_helper.exs

lib/membrane/telemetry.ex

varsill · 2025-01-22T11:17:33Z

@wende @FelonEkonom performance tests should be fixed, you just need to merge changes from current master branch for them to run properly

wende · 2025-01-24T11:31:29Z

It would be nice to have a piece of documentation that describes

how to enable metrics in config
what events are emitted and when
what is passed as events metadata
but you can wait with it until the code and API are more or less stable within this PR

It's all there in lib/membrane/telemetry.ex, but still requires some work. I don't want to document it mid-development especially when measured metrics are still unspecified

If we had some :telemetry metrics, that were emitted, I wouldn't remove them because of the backwards compatibility, but IMO the main goal is to have new, well designed and documented metrics that will allow us to plug something more or less like this

I am planning to restore these in accordance with new changes. Please keep in mind though that these were calls at the very heart of the core functionality while being 100% uncovered by tests. I want to make sure these are properly TDDed before they are reintroduced

lib/membrane/core/element.ex

test/membrane/telemetry_test.exs

lib/membrane/core/telemetry.ex

… terminate (#905)

using :telemetry.span

FelonEkonom · 2025-01-31T13:59:37Z

lib/membrane/core/telemetry.ex

+    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


How can the first clause return quote, while the second clause doesn't?

FelonEkonom · 2025-01-31T14:20:57Z

lib/membrane/core/callback_handler.ex

+        Telemetry.report_span(
+          state.__struct__,
+          callback,
+          fn ->
+            apply(module, callback, args)
+            |> Telemetry.state_result(internal_state, state)
+          end
+        )


For me it is overcomplicated and I still think that it is possible to write functions in Membrane.Core.Telemetry in a way that they will be much more intuitive to read. We can do pair-coding session to do so

FelonEkonom · 2025-01-31T14:23:24Z

test/membrane/telemetry_test.exs

+                         %{component_path: [_, ^element_type]}}},
+                       1000
+
+        assert results.monotonic_time < 0


Why do you check, if monotonic_time is smaller than zero? Shouldn't it be a positive number?

On systems I checked at the monotonic time was always negative. But I did some research and it appears it can be positive on some systems. I'll change it to just be different than 0 to make sure it doesn't fail randomly for some

FelonEkonom · 2025-01-31T14:31:30Z

lib/membrane/telemetry.ex

+    * `[: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


It is still undone

FelonEkonom · 2025-01-31T14:39:54Z

lib/membrane/telemetry.ex

+  @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()
+        }
+


This is for legacy events, right?

FelonEkonom · 2025-01-31T14:41:52Z

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))


Shouldn't it be in legacy telemetry?

FelonEkonom · 2025-01-31T14:47:21Z

lib/membrane/core/telemetry.ex

+  @type telemetry_callback_metadata() :: %{
+          args: list(any()),
+          module: module(),
+          internal_state_before: any(),
+          internal_state_after: any(),
+          component_context: Membrane.Telemetry.component_context()


please add module, component_path and setup_incomplete? (the last one is the value stored in state) to Membrane.Element/Bin/Pipeline.CallbackContext.t() and to values returned from functions defined in Membrane.Core.Element/Bin/Pipeline.CallbackContext

Since module will be inside callback_context, there will be no need to have it explicitly in telemetry_callback_metadata

FelonEkonom · 2025-01-31T14:47:39Z

lib/membrane/telemetry.ex

+  @type component_context ::
+          Element.CallbackContext.t() | Bin.CallbackContext.t() | Pipeline.CallbackContext.t()


Rename it to callback_context

FelonEkonom · 2025-01-31T14:50:04Z

lib/membrane/telemetry.ex

-  * `: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'
  * `: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


Add a mention, that events will be removed in v2.0

FelonEkonom · 2025-01-31T14:52:37Z

lib/membrane/telemetry.ex

+  @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()
+        }


Do you have any idea what prefix could be added to names of these two types, to avoid confusion if it has anything to do with newly added callback events?

FelonEkonom

@wende are you planning on making any major changes to the documentation?

FelonEkonom · 2025-02-04T11:06:38Z

lib/membrane/core/callback_handler.ex

+      %{
+        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
+      }


Let's move creating this map into Telemetry.span_component_callback/4

FelonEkonom · 2025-02-04T11:10:23Z

lib/membrane/telemetry.ex

+  @type callback_span_metadata :: %{
+          callback: atom(),
+          callback_args: [any()],
+          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()
+          internal_state_after: Element.state() | Bin.state() | Pipeline.state() | nil


Let's rename fields internal_state_before and internal_state_after to state_before_callback and state_after_callback.

The name internal_state occurs only inside membrane_core private modules and nowhere beyond them. In every other place it is called just state

FelonEkonom · 2025-02-04T11:11:20Z

config/config.exs

  # config to test legacy version of telemetry
  # config :membrane_core, :telemetry_flags, [


I would remove the legacy config

FelonEkonom · 2025-02-04T11:13:40Z

lib/membrane/core/telemetry.ex

+          atom(),
+          Telemetry.callback_span_metadata()
+        ) :: CallbackHandler.callback_return() | no_return()
+  def span_component_callback(f, component_module, callback, meta) do


Suggested change

def span_component_callback(f, component_module, callback, meta) do

def apply_callback_within_span(callback_lambda, component_module, callback, meta) do

IMO name of this function is little weird

It uses span as a verb, but I'll find a better name for it

What do you think of "track_callback_handler" it has less ambiguous verb, it still specifies it's for a callback and also adds handler to be more descriptive and consistent with "callback_tracked?/1" function name

lib/membrane/telemetry.ex

Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com>

wende · 2025-02-04T15:06:46Z

@wende are you planning on making any major changes to the documentation?

Not unless they're needed. I want to have this merged as soon as possible and the documentation can always be improved upon without breaking changes

mat-hek · 2025-02-05T10:15:15Z

config/config.exs

+      bin: :all,
+      pipeline: :all
+    ],
+    datapoints: :all


IIRC, this enables the old, deprecated metrics. Why do we add a new config key for a deprecated feature?

It's not for deprecated metrics. It's for those that were renewed. So:
link, buffer, queue_len, stream_format, event, store and take (no bitrate, demand, init or terminate)

And it's only for those to be tested

FelonEkonom · 2025-02-05T15:51:22Z

lib/membrane/core/callback_handler.ex

      end
+      |> report_telemetry(callback, args, state, context)


The API of Telemetry module should allow on sth like

Suggested change

|> report_telemetry(callback, args, state, context)

|> Telemetry.track_callback_handler(callback, args, context, state)

and the creation of event metadata should be fully hidden inside Telemetry module

FelonEkonom · 2025-02-05T15:52:52Z

lib/membrane/core/callback_handler.ex

+  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


This shouldn't be necessary, take a look at the comment to the code above

Suggested change

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

FelonEkonom

Fix these two things and it should be fine

FelonEkonom · 2025-02-06T10:15:06Z

lib/membrane/telemetry.ex

-  * `: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'
  * `: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


Add a mention, that events will be removed in v2.0

Undone

lib/membrane/telemetry.ex

Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com>

wende requested a review from FelonEkonom December 6, 2024 11:20

wende force-pushed the 905-telemetry branch from f30db73 to 13f2d49 Compare December 11, 2024 16:33

FelonEkonom reviewed Dec 30, 2024

View reviewed changes

wende commented Jan 16, 2025

View reviewed changes

lib/membrane/core/telemetry.ex Outdated Show resolved Hide resolved

wende commented Jan 16, 2025

View reviewed changes

lib/membrane/core/telemetry.ex Outdated Show resolved Hide resolved

wende commented Jan 16, 2025

View reviewed changes

lib/membrane/telemetry.ex Show resolved Hide resolved

wende requested a review from FelonEkonom January 16, 2025 11:03

FelonEkonom marked this pull request as ready for review January 17, 2025 14:55

FelonEkonom requested a review from mat-hek as a code owner January 17, 2025 14:55

FelonEkonom requested changes Jan 17, 2025

View reviewed changes

wende requested a review from FelonEkonom January 20, 2025 12:10

FelonEkonom reviewed Jan 21, 2025

View reviewed changes

wende commented Jan 24, 2025

View reviewed changes

lib/membrane/core/element.ex Show resolved Hide resolved

wende commented Jan 24, 2025

View reviewed changes

test/membrane/telemetry_test.exs Outdated Show resolved Hide resolved

wende commented Jan 24, 2025

View reviewed changes

test/membrane/telemetry_test.exs Outdated Show resolved Hide resolved

wende commented Jan 24, 2025

View reviewed changes

lib/membrane/core/telemetry.ex Outdated Show resolved Hide resolved

wende requested a review from FelonEkonom January 24, 2025 14:23

wende added 5 commits January 27, 2025 10:42

Telemetry refresh and element/pipeline telemetry testing for init and…

4fcfcb2

… terminate (#905)

Tests async false. Telemetry captured other tests' processes

328d30a

Unnecessary code trim

e599fcb

Telemetry spans for init and setup

e60b127

using :telemetry.span

Telemetry for spans, metrics and events for elements and pipelines

42f099e

Context instead of state

d7f083a

FelonEkonom reviewed Jan 31, 2025

View reviewed changes

FelonEkonom requested changes Jan 31, 2025

View reviewed changes

wende added 5 commits February 3, 2025 15:41

Simpler(?) telemetry private API

66cdefd

Documentation of metadata passed to and from telemetry modules

24f6cb6

Satisfy FilterAggregator.Context

7041bf9

Documentation of metadata passed to and from telemetry modules

72ca1be

Event -> Datapoint

fe86693

wende requested a review from FelonEkonom February 3, 2025 16:07

FelonEkonom requested changes Feb 4, 2025

View reviewed changes

Update lib/membrane/telemetry.ex

17dfe27

Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com>

wende added 3 commits February 4, 2025 16:27

Comments addressed

cf8efa1

Track callback handler name

fe9d0eb

Config cleanup

70cc188

wende requested a review from FelonEkonom February 4, 2025 16:19

mat-hek reviewed Feb 5, 2025

View reviewed changes

Faulty f+r

e846d7a

wende requested a review from mat-hek February 5, 2025 14:20

mat-hek approved these changes Feb 5, 2025

View reviewed changes

FelonEkonom requested changes Feb 5, 2025

View reviewed changes

Better public API

9583a5d

wende requested a review from FelonEkonom February 6, 2025 09:43

FelonEkonom approved these changes Feb 6, 2025

View reviewed changes

wende and others added 3 commits February 6, 2025 11:45

Update lib/membrane/telemetry.ex

9894437

Co-authored-by: Feliks Pobiedziński <38541925+FelonEkonom@users.noreply.github.com>

Documentation changes

94ba04a

faulty merge

dc707ac

wende merged commit 7089f8a into master Feb 6, 2025
7 checks passed

wende deleted the 905-telemetry branch February 6, 2025 13:27

		@type component_context ::
		Element.CallbackContext.t() \| Bin.CallbackContext.t() \| Pipeline.CallbackContext.t()

		# config to test legacy version of telemetry
		# config :membrane_core, :telemetry_flags, [

	def span_component_callback(f, component_module, callback, meta) do
	def apply_callback_within_span(callback_lambda, component_module, callback, meta) do

	\|> report_telemetry(callback, args, state, context)
	\|> Telemetry.track_callback_handler(callback, args, context, state)

Telemetry (#905) #918

Telemetry (#905) #918

Conversation

wende commented Dec 6, 2024 • edited by FelonEkonom Loading

FelonEkonom commented Dec 30, 2024

wende commented Jan 10, 2025

FelonEkonom commented Jan 10, 2025

FelonEkonom commented Jan 10, 2025 • edited Loading

Choose a reason for hiding this comment

wende Jan 24, 2025 • edited Loading

Choose a reason for hiding this comment

wende commented Jan 16, 2025

FelonEkonom left a comment

Choose a reason for hiding this comment

FelonEkonom left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wende Jan 24, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wende Jan 30, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

varsill commented Jan 22, 2025

wende commented Jan 24, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FelonEkonom left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wende commented Feb 4, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FelonEkonom Feb 5, 2025 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

FelonEkonom left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

wende commented Dec 6, 2024 •

edited by FelonEkonom

Loading

FelonEkonom commented Jan 10, 2025 •

edited

Loading

wende Jan 24, 2025 •

edited

Loading

wende Jan 24, 2025 •

edited

Loading

wende Jan 30, 2025 •

edited

Loading

wende commented Jan 24, 2025 •

edited

Loading

wende commented Feb 4, 2025 •

edited

Loading

FelonEkonom Feb 5, 2025 •

edited

Loading