diff --git a/lib/sentry/application.ex b/lib/sentry/application.ex index 3a8e6116..827c2d63 100644 --- a/lib/sentry/application.ex +++ b/lib/sentry/application.ex @@ -45,6 +45,8 @@ defmodule Sentry.Application do [] end + maybe_runtime_metrics_poller = maybe_runtime_metrics_poller() + maybe_span_storage = if Config.tracing?() do [Sentry.OpenTelemetry.SpanStorage] @@ -77,6 +79,7 @@ defmodule Sentry.Application do maybe_client_report_sender() ++ maybe_http_client_spec ++ maybe_span_storage ++ + maybe_runtime_metrics_poller ++ telemetry_processor ++ maybe_rate_limiter() ++ [Sentry.Transport.SenderPool] @@ -108,6 +111,25 @@ defmodule Sentry.Application do end end + defp maybe_runtime_metrics_poller do + cond do + not Config.metrics()[:runtime][:enabled] -> + [] + + Code.ensure_loaded?(:telemetry_poller) -> + [Sentry.Metrics.Runtime] + + true -> + LoggerUtils.warning( + "[Sentry] runtime metrics are enabled but the :telemetry_poller application is " <> + "not available, so elixir.runtime.scheduler.utilization will not be reported. " <> + ~s[Add {:telemetry_poller, "~> 1.0"} to your dependencies.] + ) + + [] + end + end + defp maybe_detach_runtime_metrics do if Config.metrics()[:runtime][:enabled] do Sentry.Metrics.Runtime.detach() diff --git a/lib/sentry/metrics.ex b/lib/sentry/metrics.ex index d1b804c8..24f84814 100644 --- a/lib/sentry/metrics.ex +++ b/lib/sentry/metrics.ex @@ -45,6 +45,11 @@ defmodule Sentry.Metrics do a `count`, the hard VM `limit`, and the `utilization` ratio between them. The `limit` and `utilization` gauges need telemetry_poller 1.3.0 or later, which is when it started measuring the limits; on older versions only `count` is reported. + * `elixir.runtime.scheduler.utilization` — the busy fraction of scheduler time, as a + ratio between `0.0` and `1.0`. Unlike the others this is a delta between two + samples, so the first collection only takes a baseline and the first value arrives + one collection later. The SDK polls for it itself, at the period configured for + `telemetry_poller`. ### Collection Frequency diff --git a/lib/sentry/metrics/runtime.ex b/lib/sentry/metrics/runtime.ex index 582a5515..a7faac6c 100644 --- a/lib/sentry/metrics/runtime.ex +++ b/lib/sentry/metrics/runtime.ex @@ -3,14 +3,18 @@ defmodule Sentry.Metrics.Runtime do alias Sentry.Metrics + @compile {:no_warn_undefined, [:telemetry_poller]} + @handler_id "sentry-runtime-metrics" @origin "auto.elixir.runtime_metrics" @memory_event [:vm, :memory] @run_queue_event [:vm, :total_run_queue_lengths] @system_counts_event [:vm, :system_counts] + @scheduler_event [:sentry, :vm, :scheduler] + @scheduler_sample_key {__MODULE__, :scheduler_sample} - @events [@memory_event, @run_queue_event, @system_counts_event] + @events [@memory_event, @run_queue_event, @system_counts_event, @scheduler_event] @run_queue_keys [:total, :cpu, :io] @@ -68,6 +72,69 @@ defmodule Sentry.Metrics.Runtime do end) end + def handle_event(@scheduler_event, %{utilization: utilization}, _metadata, config) do + gauge(config, "elixir.runtime.scheduler.utilization", utilization, "ratio") + end + + @spec child_spec(keyword()) :: Supervisor.child_spec() + def child_spec(_opts) do + :telemetry_poller.child_spec( + [name: __MODULE__, measurements: [{__MODULE__, :dispatch_scheduler_utilization, []}]] ++ + configured_poller_period() + ) + end + + @doc false + @spec dispatch_scheduler_utilization() :: :ok + def dispatch_scheduler_utilization do + case Process.get(@scheduler_sample_key) do + nil -> + _ = :erlang.system_flag(:scheduler_wall_time, true) + Process.put(@scheduler_sample_key, scheduler_sample()) + + previous -> + current = scheduler_sample() + Process.put(@scheduler_sample_key, current) + dispatch_utilization(previous, current) + end + + :ok + end + + defp configured_poller_period do + case Application.get_env(:telemetry_poller, :default, []) do + opts when is_list(opts) -> Keyword.take(opts, [:period]) + _ -> [] + end + end + + defp dispatch_utilization(_previous, []), do: :ok + + defp dispatch_utilization(previous, current) do + {active, total} = + previous + |> Enum.zip(current) + |> Enum.reduce({0, 0}, fn {{_, active0, total0}, {_, active1, total1}}, {active, total} -> + {active + (active1 - active0), total + (total1 - total0)} + end) + + :telemetry.execute(@scheduler_event, %{utilization: ratio(active, total)}, %{}) + end + + defp scheduler_sample do + case :erlang.statistics(:scheduler_wall_time) do + :undefined -> + [] + + sample -> + normal_schedulers = :erlang.system_info(:schedulers) + + sample + |> Enum.filter(fn {id, _active, _total} -> id <= normal_schedulers end) + |> Enum.sort() + end + end + defp report_count(_config, _name, nil, _limit), do: :ok defp report_count(config, name, count, limit) do diff --git a/test/sentry/application_test.exs b/test/sentry/application_test.exs index edfce6c0..03c2927e 100644 --- a/test/sentry/application_test.exs +++ b/test/sentry/application_test.exs @@ -374,6 +374,18 @@ defmodule Sentry.ApplicationTest do assert runtime_metrics_attached?() end + test "the scheduler poller is not started by default" do + restart_sentry_with([]) + + refute Process.whereis(Sentry.Metrics.Runtime) + end + + test "the scheduler poller is started when runtime metrics are enabled" do + restart_sentry_with(metrics: [runtime: [enabled: true]]) + + assert is_pid(Process.whereis(Sentry.Metrics.Runtime)) + end + test "the handler is detached when the application stops" do restart_sentry_with(metrics: [runtime: [enabled: true]]) assert runtime_metrics_attached?() diff --git a/test/sentry/metrics/runtime_test.exs b/test/sentry/metrics/runtime_test.exs index 03e0d57d..fa7f9a00 100644 --- a/test/sentry/metrics/runtime_test.exs +++ b/test/sentry/metrics/runtime_test.exs @@ -85,6 +85,69 @@ defmodule Sentry.Metrics.RuntimeTest do end end + describe "scheduler utilization" do + test "is not reported by the memory event" do + metrics = emit_memory() + + refute "elixir.runtime.scheduler.utilization" in Enum.map(metrics, & &1.name) + end + + test "reports nothing on the first measurement, which only takes a baseline" do + attach() + + assert :ok = Runtime.dispatch_scheduler_utilization() + flush_telemetry_processor() + + assert SentryTest.pop_sentry_metrics() == [] + end + + test "reports the busy fraction of scheduler time once a baseline exists" do + attach() + + assert :ok = Runtime.dispatch_scheduler_utilization() + assert :ok = Runtime.dispatch_scheduler_utilization() + + metric = assert_sentry_metric(:gauge, name: "elixir.runtime.scheduler.utilization") + + assert metric.unit == "ratio" + assert metric.value >= 0.0 and metric.value <= 1.0 + end + end + + describe "the scheduler poller" do + test "follows the period configured for telemetry_poller" do + put_telemetry_poller_default(period: 30_000) + + assert %{start: {:telemetry_poller, :start_link, [opts]}} = Runtime.child_spec([]) + assert opts[:period] == 30_000 + end + + test "leaves the period to telemetry_poller when none is configured" do + put_telemetry_poller_default([]) + + assert %{start: {:telemetry_poller, :start_link, [opts]}} = Runtime.child_spec([]) + refute Keyword.has_key?(opts, :period) + end + + test "leaves the period to telemetry_poller when the default poller is disabled" do + put_telemetry_poller_default(false) + + assert %{start: {:telemetry_poller, :start_link, [opts]}} = Runtime.child_spec([]) + refute Keyword.has_key?(opts, :period) + end + + test "reports utilization when driven by a real poller" do + attach() + poller = start_supervised!(Runtime.child_spec([])) + :ok = SentryTest.allow_sentry_reports(self(), poller) + + collect_once(poller) + collect_once(poller) + + assert_sentry_metric(:gauge, name: "elixir.runtime.scheduler.utilization") + end + end + describe "metric attributes" do test "tags every metric with the runtime metrics origin" do for metric <- emit_memory() do @@ -118,6 +181,7 @@ defmodule Sentry.Metrics.RuntimeTest do describe "wiring against a real telemetry_poller" do test "maps the builtin measurements onto Sentry gauges" do attach() + poller = start_idle_poller([:memory, :total_run_queue_lengths, :system_counts]) :ok = SentryTest.allow_sentry_reports(self(), poller) @@ -167,6 +231,12 @@ defmodule Sentry.Metrics.RuntimeTest do :ok end + defp put_telemetry_poller_default(value) do + original = Application.get_env(:telemetry_poller, :default) + Application.put_env(:telemetry_poller, :default, value) + on_exit(fn -> Application.put_env(:telemetry_poller, :default, original) end) + end + defp find_metric!(metrics, name) do Enum.find(metrics, &(&1.name == name)) || flunk("no #{name} in #{inspect(Enum.map(metrics, & &1.name))}") diff --git a/test_integrations/phoenix_app/test/phoenix_app/runtime_metrics_test.exs b/test_integrations/phoenix_app/test/phoenix_app/runtime_metrics_test.exs index 41f03e02..a71eca8c 100644 --- a/test_integrations/phoenix_app/test/phoenix_app/runtime_metrics_test.exs +++ b/test_integrations/phoenix_app/test/phoenix_app/runtime_metrics_test.exs @@ -3,6 +3,7 @@ defmodule Sentry.Integrations.Phoenix.RuntimeMetricsTest do import Sentry.TestHelpers + alias Sentry.Metrics.Runtime alias Sentry.Test, as: SentryTest @memory_keys [ @@ -118,6 +119,32 @@ defmodule Sentry.Integrations.Phoenix.RuntimeMetricsTest do end end + describe "scheduler utilization from the SDK poller" do + setup do + SentryTest.setup_sentry() + :ok + end + + test "reports utilization once the poller has a baseline" do + %{start: {:telemetry_poller, :start_link, [opts]}} = Runtime.child_spec([]) + + poller = start_vm_poller(opts[:measurements]) + :ok = SentryTest.allow_sentry_reports(self(), poller) + + collect_once(poller) + collect_once(poller) + Sentry.TelemetryProcessor.flush() + + metric = + SentryTest.pop_sentry_metrics() + |> find_metric!("elixir.runtime.scheduler.utilization") + + assert metric.unit == "ratio" + assert metric.value >= 0.0 + assert metric.value <= 1.0 + end + end + describe "the application wiring" do test "attaches the runtime metrics handler at boot" do handler_ids = [:vm, :memory] |> :telemetry.list_handlers() |> Enum.map(& &1.id) @@ -128,6 +155,10 @@ defmodule Sentry.Integrations.Phoenix.RuntimeMetricsTest do test "runs the default telemetry_poller the SDK relies on for its events" do assert is_pid(Process.whereis(:telemetry_poller_default)) end + + test "starts the SDK scheduler poller at boot" do + assert is_pid(Process.whereis(Sentry.Metrics.Runtime)) + end end defp collect_runtime_metrics(measurements) do