feat(metrics): report scheduler utilization in runtime metrics

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

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
 

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

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

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

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