From f131b7cd92067abb6048483c2fe13a8211f9c570 Mon Sep 17 00:00:00 2001 From: Anthony Shull Date: Wed, 8 May 2024 10:23:00 -0500 Subject: [PATCH] phoenix telemetry --- lib/dotcom/application.ex | 1 + lib/dotcom_web/stats.ex | 62 ++++++++++++++++++++++++++++++++++++- lib/dotcom_web/telemetry.ex | 18 ++++++++--- lib/telemetry/helper.ex | 57 ++++++++++++++++++++++++++++++++++ mix.exs | 2 +- mix.lock | 2 +- 6 files changed, 134 insertions(+), 8 deletions(-) create mode 100644 lib/telemetry/helper.ex diff --git a/lib/dotcom/application.ex b/lib/dotcom/application.ex index acf6245551..622fb7b33e 100644 --- a/lib/dotcom/application.ex +++ b/lib/dotcom/application.ex @@ -27,6 +27,7 @@ defmodule Dotcom.Application do children = [ {Application.get_env(:dotcom, :cache, Dotcom.Cache.Multilevel), []}, + {Dotcom.Telemetry, []}, {DotcomWeb.Telemetry, []}, {Req.Telemetry, []} ] ++ diff --git a/lib/dotcom_web/stats.ex b/lib/dotcom_web/stats.ex index 0c939df218..caf30da98c 100644 --- a/lib/dotcom_web/stats.ex +++ b/lib/dotcom_web/stats.ex @@ -6,9 +6,69 @@ defmodule DotcomWeb.Stats do use Agent @doc """ - Starts the Agent and attaches to `[:phoenix, ...]` telemetry events. + Starts the Agent and attaches to `[:phoenix, :router_dispatch, :stop]` telemetry events. """ def start_link(initial_value \\ %{}) do + :telemetry.attach( + "phoenix-router_dispatch-stop", + [:phoenix, :router_dispatch, :stop], + &__MODULE__.handle_event/4, + nil + ) + Agent.start_link(fn -> initial_value end, name: __MODULE__) end + + @doc """ + Handles telemetry events and aggregates them by path and status. + """ + def handle_event(_name, measurement, metadata, _config) do + method = metadata.conn.method + path = metadata.route + status = metadata.conn.status + duration = measurement[:duration] + + Agent.update(__MODULE__, fn state -> + if Kernel.get_in(state, [method, path, status]) do + Kernel.update_in(state, [method, path, status], &(&1 ++ [duration])) + else + Kernel.put_in(state, [Access.key(method, %{}), Access.key(path, %{}), status], [duration]) + end + end) + end + + @doc """ + Dispatches the aggregated stats to the `[:phoenix, :router_dispatch, :stop]` telemetry event. + + Resets the Agent state after dispatching the stats. + """ + def dispatch_stats() do + Enum.each(Agent.get(__MODULE__, & &1), &dispatch_method/1) + + Agent.update(__MODULE__, fn _ -> %{} end) + end + + defp dispatch_method({method, stats}) do + Enum.each(stats, fn {path, statuses} -> + Enum.each(statuses, fn {status, durations} -> + dispatch_stat(method, path, status, durations) + end) + end) + end + + defp dispatch_stat(method, path, status, durations) do + count = Enum.count(durations) + + avg = + durations + |> Enum.sum() + |> Kernel.div(count) + |> System.convert_time_unit(:native, :millisecond) + + :telemetry.execute([:dotcom_web, :request], %{count: count, avg: avg}, %{ + method: method, + path: path, + status: status + }) + end end diff --git a/lib/dotcom_web/telemetry.ex b/lib/dotcom_web/telemetry.ex index 8874a3e0fa..f5c0874b11 100644 --- a/lib/dotcom_web/telemetry.ex +++ b/lib/dotcom_web/telemetry.ex @@ -11,7 +11,6 @@ defmodule DotcomWeb.Telemetry do Supervisor.start_link(__MODULE__, arg, name: __MODULE__) end - @impl true def init(_arg) do telemetry_metrics_splunk_config = Application.get_env(:dotcom, :telemetry_metrics_splunk) @@ -24,17 +23,26 @@ defmodule DotcomWeb.Telemetry do url: telemetry_metrics_splunk_config[:url] ] }, + { + :telemetry_poller, + measurements: measurements(), period: :timer.seconds(60), init_delay: :timer.seconds(5) + }, {DotcomWeb.Stats, %{}} ] Supervisor.init(children, strategy: :one_for_one) end - def measurements do - [] + defp measurements do + [ + {DotcomWeb.Stats, :dispatch_stats, []} + ] end - def metrics do - [] + defp metrics do + [ + Metrics.last_value("dotcom_web.request.count"), + Metrics.last_value("dotcom_web.request.avg") + ] end end diff --git a/lib/telemetry/helper.ex b/lib/telemetry/helper.ex new file mode 100644 index 0000000000..f0d4b1d503 --- /dev/null +++ b/lib/telemetry/helper.ex @@ -0,0 +1,57 @@ +defmodule Telemetry.Helper do + @moduledoc """ + Helper functions for seeing all telemetry events. + + Only for use in development. + """ + + require Logger + + @doc """ + Attach to all telemetry events and log them. + + You can pass in a filter so that you only see telemetry events for a specific module. + E.g., if you want to see all telemetry events for Phoenix you can pass in `[:phoenix]`. + For more specific events you can pass in more specific names like `[:phoenix, :router_dispatch]` or `[:phoenix, :router_dispatch, :stop]`. + """ + def attach(filter \\ nil) do + # Start the tracer + :dbg.start() + + # Create tracer process with a function that pattern matches out the three arguments the telemetry calls are made with. + :dbg.tracer( + :process, + { + fn + {_, _, _, {_mod, :execute, [name, measurement, metadata]}}, _state -> + handler(name, metadata, measurement, filter) + end, + nil + } + ) + + # Trace all processes + :dbg.p(:all, :c) + + # Trace calls to the functions used to emit telemetry events + :dbg.tp(:telemetry, :execute, 3, []) + end + + def stop do + :dbg.stop() + end + + defp handler(name, metadata, measure, filter) do + unless filtered?(name, filter) do + IO.inspect(%{name: name, metadata: metadata, measure: measure}) + end + end + + defp filtered?(name, filter) when is_atom(name), do: name == filter + + defp filtered?(_, nil), do: false + + defp filtered?(name, filter) do + not Enum.all?(filter, fn entry -> Enum.member?(name, entry) end) + end +end diff --git a/mix.exs b/mix.exs index b34f3cafa2..9c61eb9164 100644 --- a/mix.exs +++ b/mix.exs @@ -143,7 +143,7 @@ defmodule DotCom.Mixfile do {:sweet_xml, "0.7.4", only: [:prod, :dev]}, {:telemetry, "1.2.1", override: true}, {:telemetry_metrics, "1.0.0", override: true}, - {:telemetry_metrics_splunk, "0.0.1-alpha"}, + {:telemetry_metrics_splunk, "0.0.2-alpha"}, {:telemetry_poller, "1.1.0"}, {:telemetry_test, "0.1.2", only: [:test]}, # latest version is 3.7.11; cannot upgrade because tests fail diff --git a/mix.lock b/mix.lock index 3399ee393d..3ed4b17cb9 100644 --- a/mix.lock +++ b/mix.lock @@ -100,7 +100,7 @@ "sweet_xml": {:hex, :sweet_xml, "0.7.4", "a8b7e1ce7ecd775c7e8a65d501bc2cd933bff3a9c41ab763f5105688ef485d08", [:mix], [], "hexpm", "e7c4b0bdbf460c928234951def54fe87edf1a170f6896675443279e2dbeba167"}, "telemetry": {:hex, :telemetry, "1.2.1", "68fdfe8d8f05a8428483a97d7aab2f268aaff24b49e0f599faa091f1d4e7f61c", [:rebar3], [], "hexpm", "dad9ce9d8effc621708f99eac538ef1cbe05d6a874dd741de2e689c47feafed5"}, "telemetry_metrics": {:hex, :telemetry_metrics, "1.0.0", "29f5f84991ca98b8eb02fc208b2e6de7c95f8bb2294ef244a176675adc7775df", [:mix], [{:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "f23713b3847286a534e005126d4c959ebcca68ae9582118ce436b521d1d47d5d"}, - "telemetry_metrics_splunk": {:hex, :telemetry_metrics_splunk, "0.0.1-alpha", "2104f9d79d5a278edde4976ce0905f09abfade81a5b4e96972a9d35618a89ea8", [:mix], [{:jason, "1.4.1", [hex: :jason, repo: "hexpm", optional: false]}, {:recase, "0.7.0", [hex: :recase, repo: "hexpm", optional: false]}, {:telemetry, "1.2.1", [hex: :telemetry, repo: "hexpm", optional: false]}, {:telemetry_metrics, "1.0.0", [hex: :telemetry_metrics, repo: "hexpm", optional: false]}], "hexpm", "2f40676055ee8a44f6a2515be9ee171016a9635de66ddb3f4c86cf4b23169306"}, + "telemetry_metrics_splunk": {:hex, :telemetry_metrics_splunk, "0.0.2-alpha", "f0a25d582b4315b5461840a55c77f2b0ad625c8afceaec56ce0b198f6c87f741", [:mix], [{:jason, "1.4.1", [hex: :jason, repo: "hexpm", optional: false]}, {:recase, "0.7.0", [hex: :recase, repo: "hexpm", optional: false]}, {:telemetry, "1.2.1", [hex: :telemetry, repo: "hexpm", optional: false]}, {:telemetry_metrics, "1.0.0", [hex: :telemetry_metrics, repo: "hexpm", optional: false]}], "hexpm", "c6ea80ee987a19df3c5d3bb87a5b94c3acf4a8d4df778e0f3ede2987426eba8f"}, "telemetry_metrics_statsd": {:hex, :telemetry_metrics_statsd, "0.7.0", "92732fae63db31ef2508df6faee7d81401883e33f2976715a82f296a33a45cee", [:mix], [{:nimble_options, "~> 0.4 or ~> 1.0", [hex: :nimble_options, repo: "hexpm", optional: false]}, {:telemetry, "~> 0.4 or ~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}, {:telemetry_metrics, "~> 0.6", [hex: :telemetry_metrics, repo: "hexpm", optional: false]}], "hexpm", "797e34a856376dfd4e96347da0f747fcff4e0cadf6e6f0f989598f563cad05ff"}, "telemetry_poller": {:hex, :telemetry_poller, "1.1.0", "58fa7c216257291caaf8d05678c8d01bd45f4bdbc1286838a28c4bb62ef32999", [:rebar3], [{:telemetry, "~> 1.0", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "9eb9d9cbfd81cbd7cdd24682f8711b6e2b691289a0de6826e58452f28c103c8f"}, "telemetry_test": {:hex, :telemetry_test, "0.1.2", "122d927567c563cf57773105fa8104ae4299718ec2cbdddcf6776562c7488072", [:mix], [{:telemetry, "~> 1.2", [hex: :telemetry, repo: "hexpm", optional: false]}], "hexpm", "7bd41a49ecfd33ecd82d2c7edae19a5736f0d2150206d0ee290dcf3885d0e14d"},