perf(telemetry): cut hot-path overhead on scores_at cache hits

Three small wins from a telemetry audit:

1. Propagation.scores_at/3 wrapped every call in Instrument.span, firing
   two handler dispatches that dominated the ~10µs ETS lookup on cache
   hits. The map's LiveView fires this on every pan + point-click, so
   hot-path latency was mostly telemetry. Span now wraps only the miss
   branch (where disk IO makes the duration signal meaningful); hit path
   still emits the cheap hit/miss counter the cache-ratio panel reads.

2. Oban queue-depth poller: 10s → 30s. Every replica independently
   GROUP-BYs oban_jobs, so each extra replica paid ~3 redundant queries
   per minute for a gauge that moves on the hour-scale anyway.

3. Dropped summary(phoenix.endpoint.start.system_time): summarizing a
   wall-clock timestamp produces no useful aggregate — stop.duration
   below it is the meaningful signal.
This commit is contained in:
Graham McIntire 2026-04-20 16:12:00 -05:00
parent 6463b7261f
commit 9bf96349ad
No known key found for this signature in database
GPG key ID: F4ABF488E6029E59
4 changed files with 87 additions and 15 deletions

View file

@ -332,7 +332,7 @@ defmodule Microwaveprop.PromEx.InstrumentPlugin do
event_name: [:microwaveprop, :oban, :queue, :depth],
measurement: :count,
tags: [:queue, :state],
description: "Oban job count per (queue, state) sampled every 10s"
description: "Oban job count per (queue, state) sampled every 30s"
)
]
)

View file

@ -271,16 +271,20 @@ defmodule Microwaveprop.Propagation do
@spec scores_at(non_neg_integer(), DateTime.t() | nil, map() | nil) ::
[%{lat: float(), lon: float(), score: non_neg_integer(), valid_time: DateTime.t()}]
def scores_at(band_mhz, valid_time, bounds \\ nil) do
Microwaveprop.Instrument.span([:propagation, :scores_at], %{band_mhz: band_mhz}, fn ->
time = valid_time || earliest_valid_time(band_mhz)
time = valid_time || earliest_valid_time(band_mhz)
case time do
nil -> []
_ -> scores_at_fetch(band_mhz, time, bounds)
end
end)
case time do
nil -> []
_ -> scores_at_fetch(band_mhz, time, bounds)
end
end
# Cache-hit path is the map's most frequent LiveView call (~every
# pan + click). A wrapping Instrument.span fires 2 telemetry handler
# dispatches that dominate the ~10µs ETS lookup — skip the span on
# hits and rely on the cheap hit/miss counter for the cache-ratio
# panel. The miss path still wraps the disk read where duration is
# the meaningful signal.
defp scores_at_fetch(band_mhz, time, bounds) do
case ScoreCache.fetch_bounds(band_mhz, time, bounds) do
{:ok, scores} ->
@ -289,7 +293,10 @@ defmodule Microwaveprop.Propagation do
:miss ->
:telemetry.execute([:microwaveprop, :propagation, :scores_at, :cache], %{}, %{hit: false})
read_from_disk_and_cache(band_mhz, time, bounds)
Microwaveprop.Instrument.span([:propagation, :scores_at], %{band_mhz: band_mhz}, fn ->
read_from_disk_and_cache(band_mhz, time, bounds)
end)
end
end

View file

@ -11,9 +11,11 @@ defmodule MicrowavepropWeb.Telemetry do
@impl true
def init(_arg) do
children = [
# Telemetry poller will execute the given period measurements
# every 10_000ms. Learn more here: https://hexdocs.pm/telemetry_metrics
{:telemetry_poller, measurements: periodic_measurements(), period: 10_000}
# Oban queue-depth is the only poller measurement and each replica
# issues the same GROUP-BY over oban_jobs. 30s gives enough fidelity
# for dashboard trends without burning ~3/min of identical queries
# per extra replica.
{:telemetry_poller, measurements: periodic_measurements(), period: 30_000}
# Add reporters as children of your supervision tree.
# {Telemetry.Metrics.ConsoleReporter, metrics: metrics()}
]
@ -33,7 +35,6 @@ defmodule MicrowavepropWeb.Telemetry do
defp phoenix_metrics do
[
summary("phoenix.endpoint.start.system_time", unit: {:native, :millisecond}),
summary("phoenix.endpoint.stop.duration", unit: {:native, :millisecond}),
summary("phoenix.router_dispatch.start.system_time",
tags: [:route],
@ -125,7 +126,7 @@ defmodule MicrowavepropWeb.Telemetry do
event_name: [:microwaveprop, :oban, :queue, :depth],
measurement: :count,
tags: [:queue, :state],
description: "Oban job count per (queue, state) sampled every 10s"
description: "Oban job count per (queue, state) sampled every 30s"
)
]
end
@ -256,7 +257,7 @@ defmodule MicrowavepropWeb.Telemetry do
@doc false
# Periodic poller: emit `microwaveprop.oban.queue.depth` gauges per
# (queue, state) tuple so LiveDashboard / Prometheus can chart queue
# saturation over time. Cheap aggregation query, runs every 10s.
# saturation over time. Cheap aggregation query, runs every 30s.
def dispatch_oban_queue_depth do
import Ecto.Query

View file

@ -338,6 +338,70 @@ defmodule Microwaveprop.PropagationTest do
test "returns empty list when no data anywhere" do
assert Propagation.scores_at(10_000, ~U[2026-07-15 13:00:00Z]) == []
end
# Cache-hit is the map's most frequent LiveView call. The span
# wrapping the disk-read path costs ~2 telemetry handler dispatches
# per call, dominating the actual ~10µs ETS work; skip the span on
# hits and rely on the cache hit/miss counter instead.
test "cache-hit path does not emit the scores_at.stop span" do
valid_time = ~U[2026-07-15 13:00:00Z]
ScoreCache.put(10_000, valid_time, [%{lat: 32.0, lon: -97.0, score: 75}])
test_pid = self()
handler_id = {__MODULE__, :cache_hit_no_span}
:telemetry.attach_many(
handler_id,
[
[:microwaveprop, :propagation, :scores_at, :stop],
[:microwaveprop, :propagation, :scores_at, :cache]
],
fn event, _measurements, metadata, _config ->
send(test_pid, {:telemetry, event, metadata})
end,
nil
)
try do
_ = Propagation.scores_at(10_000, valid_time)
assert_receive {:telemetry, [:microwaveprop, :propagation, :scores_at, :cache], %{hit: true}}
refute_receive {:telemetry, [:microwaveprop, :propagation, :scores_at, :stop], _}, 50
after
:telemetry.detach(handler_id)
end
end
test "cache-miss path still emits the scores_at.stop span" do
valid_time = ~U[2026-07-15 13:00:00Z]
Propagation.replace_scores(
[%{lat: 25.0, lon: -125.0, valid_time: valid_time, band_mhz: 10_000, score: 75, factors: nil}],
valid_time
)
assert ScoreCache.fetch(10_000, valid_time) == :miss
test_pid = self()
handler_id = {__MODULE__, :cache_miss_span}
:telemetry.attach(
handler_id,
[:microwaveprop, :propagation, :scores_at, :stop],
fn event, measurements, metadata, _config ->
send(test_pid, {:telemetry, event, measurements, metadata})
end,
nil
)
try do
_ = Propagation.scores_at(10_000, valid_time)
assert_receive {:telemetry, [:microwaveprop, :propagation, :scores_at, :stop], _, _}
after
:telemetry.detach(handler_id)
end
end
end
describe "point_forecast/3 with cache" do