From 77db483a2742f619e56b402c4810d185c9f6c0aa Mon Sep 17 00:00:00 2001 From: Graham McIntire Date: Tue, 31 Mar 2026 16:18:10 -0500 Subject: [PATCH] Add timing instrumentation to PropagationGridWorker Logs duration for each phase: HRRR fetch, profile storage, score computation, and upsert, plus total elapsed time. --- .../workers/propagation_grid_worker.ex | 25 +++++++++++++++---- 1 file changed, 20 insertions(+), 5 deletions(-) diff --git a/lib/microwaveprop/workers/propagation_grid_worker.ex b/lib/microwaveprop/workers/propagation_grid_worker.ex index 963c9942..42d47408 100644 --- a/lib/microwaveprop/workers/propagation_grid_worker.ex +++ b/lib/microwaveprop/workers/propagation_grid_worker.ex @@ -21,6 +21,8 @@ defmodule Microwaveprop.Workers.PropagationGridWorker do @impl Oban.Worker def perform(%Oban.Job{}) do + t_start = System.monotonic_time(:millisecond) + # HRRR takes ~45min to publish after the hour. Use 2 hours ago to ensure availability. two_hours_ago = DateTime.add(DateTime.utc_now(), -2, :hour) valid_time = two_hours_ago |> HrrrClient.nearest_hrrr_hour() |> DateTime.truncate(:second) @@ -30,15 +32,14 @@ defmodule Microwaveprop.Workers.PropagationGridWorker do Enum.each(@pause_queues, &Oban.pause_queue(queue: &1)) result = - with {:ok, grid_data} <- HrrrClient.fetch_grid(points, valid_time) do - # Store HRRR profiles in the database for future reference - store_hrrr_profiles(grid_data, valid_time) + with {:ok, grid_data} <- timed("fetch_hrrr", fn -> HrrrClient.fetch_grid(points, valid_time) end) do + timed("store_profiles", fn -> store_hrrr_profiles(grid_data, valid_time) end) - scores = compute_scores(grid_data, valid_time) + scores = timed("compute_scores", fn -> compute_scores(grid_data, valid_time) end) Logger.info("PropagationGrid: computed #{length(scores)} scores, upserting") - case Propagation.upsert_scores(scores) do + case timed("upsert_scores", fn -> Propagation.upsert_scores(scores) end) do {:ok, count} -> Logger.info("PropagationGrid: upserted #{count} scores for #{valid_time}") Phoenix.PubSub.broadcast(Microwaveprop.PubSub, "propagation:updated", {:propagation_updated, valid_time}) @@ -55,9 +56,23 @@ defmodule Microwaveprop.Workers.PropagationGridWorker do Weather.prune_old_grid_profiles() + total_ms = System.monotonic_time(:millisecond) - t_start + Logger.info("PropagationGrid: total time #{format_duration(total_ms)}") + result end + defp timed(label, fun) do + t0 = System.monotonic_time(:millisecond) + result = fun.() + elapsed = System.monotonic_time(:millisecond) - t0 + Logger.info("PropagationGrid: #{label} took #{format_duration(elapsed)}") + result + end + + defp format_duration(ms) when ms < 1000, do: "#{ms}ms" + defp format_duration(ms), do: "#{Float.round(ms / 1000, 1)}s" + defp store_hrrr_profiles(grid_data, valid_time) do stored = Enum.flat_map(grid_data, fn {{lat, lon}, profile} ->