From 3864edc5d14f794d812b1140e7dad35ce3657f2f Mon Sep 17 00:00:00 2001 From: Vince Foley Date: Tue, 11 Feb 2025 21:31:55 -0800 Subject: [PATCH 1/2] Phoenix LiveView instrumentation --- README.md | 1 + config/config.exs | 8 +- .../test/absinthe_example_test.exs | 2 +- .../lib/phx_example_web/bandit_endpoint.ex | 5 +- .../lib/phx_example_web/endpoint.ex | 5 +- .../lib/phx_example_web/live/home_live.ex | 28 ++- examples/apps/phx_example/mix.exs | 1 + .../phx_example/test/phx_example_test.exs | 58 ++++-- examples/config/config.exs | 5 +- examples/mix.lock | 1 + lib/new_relic/aggregate/aggregate.ex | 2 +- lib/new_relic/config.ex | 5 + lib/new_relic/init.ex | 5 + lib/new_relic/metric/metric_data.ex | 10 + lib/new_relic/telemetry/absinthe.ex | 10 +- lib/new_relic/telemetry/phoenix_live_view.ex | 172 ++++++++++++++++++ lib/new_relic/telemetry/plug.ex | 4 +- lib/new_relic/telemetry/supervisor.ex | 1 + lib/new_relic/tracer/direct.ex | 17 +- lib/new_relic/transaction/reporter.ex | 22 ++- 20 files changed, 312 insertions(+), 50 deletions(-) create mode 100644 lib/new_relic/telemetry/phoenix_live_view.ex diff --git a/README.md b/README.md index 9fbd64e2..7868e0e2 100644 --- a/README.md +++ b/README.md @@ -84,6 +84,7 @@ Some common Elixir packages are auto-instrumented via [`telemetry`](https://gith * [`Plug`](https://github.com/elixir-plug/plug): See [NewRelic.Telemetry.Plug](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Plug.html) for details. * [`Phoenix`](https://github.com/phoenixframework/phoenix): See [NewRelic.Telemetry.Phoenix](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Phoenix.html) for details. +* [`Phoenix LiveView`](https://github.com/phoenixframework/phoenix_live_view): See [NewRelic.Telemetry.PhoenixLiveView](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.PhoenixLiveView.html) for details. * [`Ecto`](https://github.com/elixir-ecto/ecto): See [NewRelic.Telemetry.Ecto](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Ecto.html) for details. * [`Redix`](https://github.com/whatyouhide/redix): See [NewRelic.Telemetry.Redix](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Redix.html) for details. * [`Finch`](https://github.com/sneako/finch): See [NewRelic.Telemetry.Finch](https://hexdocs.pm/new_relic_agent/NewRelic.Telemetry.Finch.html) for details. diff --git a/config/config.exs b/config/config.exs index 62b5d27c..e2e5359c 100644 --- a/config/config.exs +++ b/config/config.exs @@ -1,4 +1,8 @@ import Config -if Mix.env() == :test, do: import_config("test.exs") -if File.exists?("config/secret.exs"), do: import_config("secret.exs") +if Mix.env() == :test do + import_config("test.exs") +else + if File.exists?("config/secret.exs"), + do: import_config("secret.exs") +end diff --git a/examples/apps/absinthe_example/test/absinthe_example_test.exs b/examples/apps/absinthe_example/test/absinthe_example_test.exs index e4c4919f..5f3e84d1 100644 --- a/examples/apps/absinthe_example/test/absinthe_example_test.exs +++ b/examples/apps/absinthe_example/test/absinthe_example_test.exs @@ -43,7 +43,7 @@ defmodule AbsintheExampleTest do operation = Enum.find(spans, fn %{attributes: attr} -> - attr[:name] == "query:TestQuery" + attr[:name] == "Absinthe/Operation/query:TestQuery" end) one_resolver = diff --git a/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex b/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex index 0ee600f9..e0ab8b88 100644 --- a/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex +++ b/examples/apps/phx_example/lib/phx_example_web/bandit_endpoint.ex @@ -8,7 +8,10 @@ defmodule PhxExampleWeb.BanditEndpoint do same_site: "Lax" ] - socket "/live", Phoenix.LiveView.Socket, websocket: [connect_info: [session: @session_options]] + socket "/live", + Phoenix.LiveView.Socket, + websocket: [connect_info: [session: @session_options]], + longpoll: [connect_info: [session: @session_options]] plug Plug.Static, at: "/", diff --git a/examples/apps/phx_example/lib/phx_example_web/endpoint.ex b/examples/apps/phx_example/lib/phx_example_web/endpoint.ex index 00dc956b..ce7c2052 100644 --- a/examples/apps/phx_example/lib/phx_example_web/endpoint.ex +++ b/examples/apps/phx_example/lib/phx_example_web/endpoint.ex @@ -8,7 +8,10 @@ defmodule PhxExampleWeb.Endpoint do same_site: "Lax" ] - socket "/live", Phoenix.LiveView.Socket, websocket: [connect_info: [session: @session_options]] + socket "/live", + Phoenix.LiveView.Socket, + websocket: [connect_info: [session: @session_options]], + longpoll: [connect_info: [session: @session_options]] plug Plug.Static, at: "/", diff --git a/examples/apps/phx_example/lib/phx_example_web/live/home_live.ex b/examples/apps/phx_example/lib/phx_example_web/live/home_live.ex index ef05d880..9e734379 100644 --- a/examples/apps/phx_example/lib/phx_example_web/live/home_live.ex +++ b/examples/apps/phx_example/lib/phx_example_web/live/home_live.ex @@ -1,12 +1,38 @@ defmodule PhxExampleWeb.HomeLive do use PhxExampleWeb, :live_view - @impl true + def mount(_params, _session, socket) do + socket = + socket + |> assign(:content, "stuff") + + {:ok, socket} + end + + def handle_event("click", _params, socket) do + socket = + socket + |> assign(:content, "clicked") + + Process.send_after(self(), :after, 1_000) + {:noreply, socket} + end + + def handle_info(:after, socket) do + socket = + socket + |> assign(:content, "after") + + {:noreply, socket} + end + def render(assigns) do ~H"""

Home

Some content

+

<%= @content %>

+
Click me
""" end diff --git a/examples/apps/phx_example/mix.exs b/examples/apps/phx_example/mix.exs index 657de158..2ae8805b 100644 --- a/examples/apps/phx_example/mix.exs +++ b/examples/apps/phx_example/mix.exs @@ -30,6 +30,7 @@ defmodule PhxExample.MixProject do {:phoenix_html, "~> 3.3"}, {:phoenix_view, "~> 2.0"}, {:phoenix_live_view, "~> 0.20"}, + {:floki, ">= 0.30.0", only: :test}, {:jason, "~> 1.0"}, {:plug_cowboy, "~> 2.0"}, {:bandit, "~> 1.0"} diff --git a/examples/apps/phx_example/test/phx_example_test.exs b/examples/apps/phx_example/test/phx_example_test.exs index a9381c97..ad830351 100644 --- a/examples/apps/phx_example/test/phx_example_test.exs +++ b/examples/apps/phx_example/test/phx_example_test.exs @@ -7,12 +7,18 @@ defmodule PhxExampleTest do TestHelper.simulate_agent_enabled() end + setup do + TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) + TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) + TestHelper.restart_harvest_cycle(Collector.SpanEvent.HarvestCycle) + TestHelper.restart_harvest_cycle(Collector.ErrorTrace.HarvestCycle) + NewRelic.DistributedTrace.BackoffSampler.reset() + :ok + end + for server <- [:cowboy, :bandit] do describe "Testing #{server}:" do test "Phoenix metrics generated" do - TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body}} = request("/phx/bar", unquote(server)) assert body =~ "Welcome to Phoenix" @@ -48,9 +54,6 @@ defmodule PhxExampleTest do end test "Phoenix metrics generated for LiveView" do - TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body}} = request("/phx/home", unquote(server)) assert body =~ "Some content" @@ -71,7 +74,6 @@ defmodule PhxExampleTest do end test "Phoenix spans generated" do - TestHelper.restart_harvest_cycle(Collector.SpanEvent.HarvestCycle) {:ok, %{body: body}} = request("/phx/home", unquote(server)) assert body =~ "Some content" @@ -79,15 +81,44 @@ defmodule PhxExampleTest do tx_span = TestHelper.find_span(span_events, "/Phoenix/PhxExampleWeb.HomeLive/index") process_span = TestHelper.find_span(span_events, "Transaction Root Process") + mount_span = TestHelper.find_span(span_events, "PhxExampleWeb.HomeLive:index.mount") + + assert process_span[:parentId] == tx_span[:guid] + assert mount_span[:"live_view.params"] + end + + @endpoint PhxExampleWeb.Endpoint + test "Live View transaction and spans generated" do + import Phoenix.ConnTest + import Phoenix.LiveViewTest + + conn = + Phoenix.ConnTest.build_conn() + |> Plug.Test.init_test_session([]) + + conn = get(conn, "/phx/home") + assert html_response(conn, 200) =~ "

Some content

" + + {:ok, _view, _html} = live(conn) + + span_events = TestHelper.gather_harvest(Collector.SpanEvent.Harvester) + + tx_span = + TestHelper.find_span(span_events, "/Phoenix.LiveView/Live/PhxExampleWeb.HomeLive/index") + + process_span = TestHelper.find_span(span_events, "Transaction Root Process") + mount_span = TestHelper.find_span(span_events, "PhxExampleWeb.HomeLive:index.mount") + render_span = TestHelper.find_span(span_events, "PhxExampleWeb.HomeLive:index.render") + + assert tx_span[:"live_view.endpoint"] == "PhxExampleWeb.Endpoint" assert process_span[:parentId] == tx_span[:guid] + assert mount_span[:parentId] == process_span[:guid] + assert render_span[:parentId] == process_span[:guid] end @tag :capture_log test "Phoenix error" do - TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body, status_code: 500}} = request("/phx/error", unquote(server)) assert body =~ "Oops, Internal Server Error" @@ -111,9 +142,6 @@ defmodule PhxExampleTest do @tag :capture_log test "Phoenix LiveView error" do - TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - {:ok, %{body: body, status_code: 500}} = request("/phx/live_error", unquote(server)) assert body =~ "Oops, Internal Server Error" @@ -136,10 +164,6 @@ defmodule PhxExampleTest do end test "Phoenix route not found" do - TestHelper.restart_harvest_cycle(Collector.Metric.HarvestCycle) - TestHelper.restart_harvest_cycle(Collector.TransactionEvent.HarvestCycle) - TestHelper.restart_harvest_cycle(Collector.ErrorTrace.HarvestCycle) - {:ok, %{body: body, status_code: 404}} = request("/not_found", unquote(server)) assert body =~ "Not Found" diff --git a/examples/config/config.exs b/examples/config/config.exs index 161e298e..47af5473 100644 --- a/examples/config/config.exs +++ b/examples/config/config.exs @@ -12,4 +12,7 @@ for config <- "../apps/*/config/config.exs" |> Path.expand(__DIR__) |> Path.wild import_config config end -if File.exists?("config/secret.exs"), do: import_config("secret.exs") +if Mix.env() != :test do + if File.exists?(Path.expand("./secret.exs", __DIR__)), + do: import_config("secret.exs") +end diff --git a/examples/mix.lock b/examples/mix.lock index ff7b96e2..f9a47ce9 100644 --- a/examples/mix.lock +++ b/examples/mix.lock @@ -15,6 +15,7 @@ "ecto_sqlite3": {:hex, :ecto_sqlite3, "0.14.0", "8710aa6de137a9c428fc86306b574777e9d545534b0259030a325948d43fc740", [:mix], [{:decimal, "~> 1.6 or ~> 2.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:ecto, "~> 3.11", [hex: :ecto, repo: "hexpm", optional: false]}, {:ecto_sql, "~> 3.11", [hex: :ecto_sql, repo: "hexpm", optional: false]}, {:exqlite, "~> 0.9", [hex: :exqlite, repo: "hexpm", optional: false]}], "hexpm", "4f69e5df5bdf8b98d80797b1a88b1d24b13ad9f187a553241c2aa6cb7447a672"}, "elixir_make": {:hex, :elixir_make, "0.7.7", "7128c60c2476019ed978210c245badf08b03dbec4f24d05790ef791da11aa17c", [:mix], [{:castore, "~> 0.1 or ~> 1.0", [hex: :castore, repo: "hexpm", optional: true]}], "hexpm", "5bc19fff950fad52bbe5f211b12db9ec82c6b34a9647da0c2224b8b8464c7e6c"}, "exqlite": {:hex, :exqlite, "0.17.0", "865ab503debde7913ffa02b58838ab92885165978f4c88d8169ee8688c655d1e", [:make, :mix], [{:cc_precompiler, "~> 0.1", [hex: :cc_precompiler, repo: "hexpm", optional: false]}, {:db_connection, "~> 2.1", [hex: :db_connection, repo: "hexpm", optional: false]}, {:elixir_make, "~> 0.7", [hex: :elixir_make, repo: "hexpm", optional: false]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "719fa7986fed242839629a907d60f774000c1d2dc03ba6ba05fcd30579f2ab45"}, + "floki": {:hex, :floki, "0.37.0", "b83e0280bbc6372f2a403b2848013650b16640cd2470aea6701f0632223d719e", [:mix], [], "hexpm", "516a0c15a69f78c47dc8e0b9b3724b29608aa6619379f91b1ffa47109b5d0dd3"}, "hackney": {:hex, :hackney, "1.17.0", "717ea195fd2f898d9fe9f1ce0afcc2621a41ecfe137fae57e7fe6e9484b9aa99", [:rebar3], [{:certifi, "~>2.5", [hex: :certifi, repo: "hexpm", optional: false]}, {:idna, "~>6.1.0", [hex: :idna, repo: "hexpm", optional: false]}, {:metrics, "~>1.0.0", [hex: :metrics, repo: "hexpm", optional: false]}, {:mimerl, "~>1.1", [hex: :mimerl, repo: "hexpm", optional: false]}, {:parse_trans, "~>3.3", [hex: :parse_trans, repo: "hexpm", optional: false]}, {:ssl_verify_fun, "~>1.1.0", [hex: :ssl_verify_fun, repo: "hexpm", optional: false]}, {:unicode_util_compat, "~>0.7.0", [hex: :unicode_util_compat, repo: "hexpm", optional: false]}], "hexpm", "64c22225f1ea8855f584720c0e5b3cd14095703af1c9fbc845ba042811dc671c"}, "hpax": {:hex, :hpax, "1.0.0", "28dcf54509fe2152a3d040e4e3df5b265dcb6cb532029ecbacf4ce52caea3fd2", [:mix], [], "hexpm", "7f1314731d711e2ca5fdc7fd361296593fc2542570b3105595bb0bc6d0fad601"}, "httpoison": {:hex, :httpoison, "1.8.0", "6b85dea15820b7804ef607ff78406ab449dd78bed923a49c7160e1886e987a3d", [:mix], [{:hackney, "~> 1.17", [hex: :hackney, repo: "hexpm", optional: false]}], "hexpm", "28089eaa98cf90c66265b6b5ad87c59a3729bea2e74e9d08f9b51eb9729b3c3a"}, diff --git a/lib/new_relic/aggregate/aggregate.ex b/lib/new_relic/aggregate/aggregate.ex index ac2e4e0e..059fdfbe 100644 --- a/lib/new_relic/aggregate/aggregate.ex +++ b/lib/new_relic/aggregate/aggregate.ex @@ -19,7 +19,7 @@ defmodule NewRelic.Aggregate do defp averages(%{call_count: call_count} = values) do values - |> Stream.reject(fn {key, _value} -> key == :call_count end) + |> Enum.reject(fn {key, _value} -> key == :call_count end) |> Map.new(fn {key, value} -> {:"avg_#{key}", value / call_count} end) end diff --git a/lib/new_relic/config.ex b/lib/new_relic/config.ex index 27cd4881..7e21c269 100644 --- a/lib/new_relic/config.ex +++ b/lib/new_relic/config.ex @@ -156,6 +156,7 @@ defmodule NewRelic.Config do * `:plug_instrumentation_enabled` * `:phoenix_instrumentation_enabled` + * `:phoenix_live_view_instrumentation_enabled` * `:ecto_instrumentation_enabled` * `:redix_instrumentation_enabled` * `:oban_instrumentation_enabled` @@ -184,6 +185,10 @@ defmodule NewRelic.Config do get(:features, :phoenix_instrumentation) end + def feature?(:phoenix_live_view_instrumentation) do + get(:features, :phoenix_live_view_instrumentation) + end + def feature?(:ecto_instrumentation) do get(:features, :ecto_instrumentation) end diff --git a/lib/new_relic/init.ex b/lib/new_relic/init.ex index d01c43b3..2b2acc52 100644 --- a/lib/new_relic/init.ex +++ b/lib/new_relic/init.ex @@ -108,6 +108,11 @@ defmodule NewRelic.Init do "NEW_RELIC_PHOENIX_INSTRUMENTATION_ENABLED", :phoenix_instrumentation_enabled ), + phoenix_live_view_instrumentation: + determine_feature( + "NEW_RELIC_PHOENIX_LIVE_VIEW_INSTRUMENTATION_ENABLED", + :phoenix_live_view_instrumentation_enabled + ), oban_instrumentation: determine_feature( "NEW_RELIC_OBAN_INSTRUMENTATION_ENABLED", diff --git a/lib/new_relic/metric/metric_data.ex b/lib/new_relic/metric/metric_data.ex index fd64736f..818603ba 100644 --- a/lib/new_relic/metric/metric_data.ex +++ b/lib/new_relic/metric/metric_data.ex @@ -358,6 +358,16 @@ defmodule NewRelic.Metric.MetricData do max_call_time: duration_s } + def transform({:function, function_name}, duration_s: duration_s), + do: %Metric{ + name: join(["Function", function_name]), + call_count: 1, + total_call_time: duration_s, + total_exclusive_time: duration_s, + min_call_time: duration_s, + max_call_time: duration_s + } + def transform({:function, function_name}, duration_s: duration_s, exclusive_time_s: exclusive_time_s diff --git a/lib/new_relic/telemetry/absinthe.ex b/lib/new_relic/telemetry/absinthe.ex index 6c1f9f97..0ca35823 100644 --- a/lib/new_relic/telemetry/absinthe.ex +++ b/lib/new_relic/telemetry/absinthe.ex @@ -64,8 +64,8 @@ defmodule NewRelic.Telemetry.Absinthe do NewRelic.Tracer.Direct.start_span( meta.id, - "Operation", - start_time: meas.system_time, + "Absinthe/Operation", + system_time: meas.system_time, attributes: [ "absinthe.schema": inspect(meta.options[:schema]), "absinthe.query": query @@ -116,7 +116,7 @@ defmodule NewRelic.Telemetry.Absinthe do NewRelic.Tracer.Direct.start_span( meta.id, {resolver_name, "#{inspect(resolution.schema)}.#{path}"}, - start_time: meas.system_time, + system_time: meas.system_time, attributes: [ "absinthe.field.path": path, "absinthe.field.type": type, @@ -160,11 +160,11 @@ defmodule NewRelic.Telemetry.Absinthe do end defp operation_span_name(%{type: type, name: name}) when is_binary(name) do - "#{to_string(type)}:#{name}" + "Absinthe/Operation/#{to_string(type)}:#{name}" end defp operation_span_name(%{type: type}) do - "#{to_string(type)}" + "Absinthe/Operation/#{to_string(type)}" end defp transaction_name(schema, operation) do diff --git a/lib/new_relic/telemetry/phoenix_live_view.ex b/lib/new_relic/telemetry/phoenix_live_view.ex new file mode 100644 index 00000000..686c7ee0 --- /dev/null +++ b/lib/new_relic/telemetry/phoenix_live_view.ex @@ -0,0 +1,172 @@ +defmodule NewRelic.Telemetry.PhoenixLiveView do + use GenServer + + alias NewRelic.Transaction + alias NewRelic.Tracer + + @moduledoc """ + Provides Phoenix `LiveView` instrumentation via `telemetry`. + + This instrumentation collects Transactions for the initial LiveView lifecycle events + that occur inside the WebSocket process, as well as metrics for subsequent instances + of lifecycle events. + + You can opt-out of this instrumentation as a whole with `:phoenix_live_view_instrumentation_enabled`, + and specifically out of params collection with `:function_argument_collection_enabled` via configuration. + + See `NewRelic.Config` for details. + """ + def start_link(_) do + config = %{ + handler_id: {:new_relic, :phoenix_live_view}, + enabled?: NewRelic.Config.feature?(:phoenix_live_view_instrumentation), + collect_args?: NewRelic.Config.feature?(:function_argument_collection) + } + + GenServer.start_link(__MODULE__, config, name: __MODULE__) + end + + @live_view_mount_start [:phoenix, :live_view, :mount, :start] + @live_view_mount_stop [:phoenix, :live_view, :mount, :stop] + @live_view_mount_exception [:phoenix, :live_view, :mount, :exception] + + @live_view_handle_params_start [:phoenix, :live_view, :handle_params, :start] + @live_view_handle_params_stop [:phoenix, :live_view, :handle_params, :stop] + @live_view_handle_params_exception [:phoenix, :live_view, :handle_params, :exception] + + @live_view_handle_event_start [:phoenix, :live_view, :handle_event, :start] + @live_view_handle_event_stop [:phoenix, :live_view, :handle_event, :stop] + @live_view_handle_event_exception [:phoenix, :live_view, :handle_event, :exception] + + @live_view_render_start [:phoenix, :live_view, :render, :start] + @live_view_render_stop [:phoenix, :live_view, :render, :stop] + @live_view_render_exception [:phoenix, :live_view, :render, :exception] + + @live_view_events [ + @live_view_mount_start, + @live_view_mount_stop, + @live_view_mount_exception, + @live_view_handle_params_start, + @live_view_handle_params_stop, + @live_view_handle_params_exception, + @live_view_handle_event_start, + @live_view_handle_event_stop, + @live_view_handle_event_exception, + @live_view_render_start, + @live_view_render_stop, + @live_view_render_exception + ] + + @doc false + def init(%{enabled?: false}), do: :ignore + + def init(%{enabled?: true} = config) do + :telemetry.attach_many( + config.handler_id, + @live_view_events, + &__MODULE__.handle_event/4, + config + ) + + {:ok, config} + end + + @doc false + def terminate(_reason, %{handler_id: handler_id}) do + :telemetry.detach(handler_id) + end + + def handle_event(@live_view_mount_start, meas, meta, config) do + if meta.socket.transport_pid do + uri = URI.parse(meta.uri) + + # We're in the LiveView WebSocket process, collect a Transaction + with :collect <- Transaction.Reporter.start_transaction(:web, uri.path) do + NewRelic.DistributedTrace.start(:other) + framework_name = "/Phoenix.LiveView/Live/#{inspect(meta.socket.view)}/#{meta.socket.assigns.live_action}" + + NewRelic.add_attributes( + pid: inspect(self()), + start_time: meas.system_time, + framework_name: framework_name, + host: uri.host, + path: uri.path, + "live_view.router": inspect(meta.socket.router), + "live_view.endpoint": inspect(meta.socket.endpoint), + "live_view.action": meta.socket.assigns[:live_action], + "live_view.socket_id": meta.socket.id + ) + end + end + + Tracer.Direct.start_span( + meta.telemetry_span_context, + "#{inspect(meta.socket.view)}:#{meta.socket.assigns.live_action}.mount", + system_time: meas.system_time, + attributes: [ + "live_view.params": config.collect_args? && meta[:params] && inspect(meta[:params]) + ] + ) + end + + def handle_event([_, _, type, _] = event, meas, meta, config) + when event in [ + @live_view_handle_params_start, + @live_view_handle_event_start, + @live_view_render_start + ] do + Tracer.Direct.start_span( + meta.telemetry_span_context, + "#{inspect(meta.socket.view)}:#{meta.socket.assigns.live_action}.#{type}", + system_time: meas.system_time, + attributes: [ + event: meta[:event], + params: config.collect_args? && meta[:params] && inspect(meta[:params]), + "live_view.render.changed?": meta[:changed?], + "live_view.render.force?": meta[:force?] + ] + ) + end + + def handle_event(event, meas, meta, _config) + when event in [ + @live_view_mount_stop, + @live_view_handle_params_stop, + @live_view_handle_event_stop + ] do + Tracer.Direct.stop_span(meta.telemetry_span_context, duration: meas.duration) + end + + def handle_event(event, meas, meta, _config) + when event in [ + @live_view_mount_exception, + @live_view_handle_params_exception, + @live_view_handle_event_exception + ] do + Tracer.Direct.stop_span( + meta.telemetry_span_context, + duration: meas.duration, + attributes: [error: true, "error.kind": meta.kind, "error.reason": inspect(meta.reason)] + ) + end + + def handle_event(@live_view_render_stop, meas, meta, _config) do + Tracer.Direct.stop_span(meta.telemetry_span_context, duration: meas.duration) + + Transaction.Reporter.stop_transaction(:web) + end + + def handle_event(@live_view_render_exception, meas, meta, _config) do + Tracer.Direct.stop_span( + meta.telemetry_span_context, + duration: meas.duration, + attributes: [error: true, "error.kind": meta.kind, "error.reason": inspect(meta.reason)] + ) + + Transaction.Reporter.stop_transaction(:web) + end + + def handle_event(_event, _meas, _meta, _config) do + :ignore + end +end diff --git a/lib/new_relic/telemetry/plug.ex b/lib/new_relic/telemetry/plug.ex index d4a82f93..351339d0 100644 --- a/lib/new_relic/telemetry/plug.ex +++ b/lib/new_relic/telemetry/plug.ex @@ -79,9 +79,7 @@ defmodule NewRelic.Telemetry.Plug do with :collect <- Transaction.Reporter.start_transaction(:web, path(meta, server)) do headers = get_headers(meta, server) - if NewRelic.Config.enabled?(), - do: DistributedTrace.start(:http, headers) - + DistributedTrace.start(:http, headers) add_start_attrs(meta, measurements, headers, server) maybe_report_queueing(headers) end diff --git a/lib/new_relic/telemetry/supervisor.ex b/lib/new_relic/telemetry/supervisor.ex index ddb6e969..cc644d26 100644 --- a/lib/new_relic/telemetry/supervisor.ex +++ b/lib/new_relic/telemetry/supervisor.ex @@ -20,6 +20,7 @@ defmodule NewRelic.Telemetry.Supervisor do NewRelic.Telemetry.Redix, NewRelic.Telemetry.Plug, NewRelic.Telemetry.Phoenix, + NewRelic.Telemetry.PhoenixLiveView, NewRelic.Telemetry.Oban, NewRelic.Telemetry.Finch, NewRelic.Telemetry.Absinthe diff --git a/lib/new_relic/tracer/direct.ex b/lib/new_relic/tracer/direct.ex index 02e1ee97..75f52baa 100644 --- a/lib/new_relic/tracer/direct.ex +++ b/lib/new_relic/tracer/direct.ex @@ -12,7 +12,8 @@ defmodule NewRelic.Tracer.Direct do under -> Process.put(:nr_open_span_count, under + 1) - start_time = Keyword.get(options, :start_time, System.system_time()) + system_time = Keyword.get(options, :system_time, System.system_time()) + monotonic_time = Keyword.get(options, :monotonic_time, System.monotonic_time()) attributes = Keyword.get(options, :attributes, []) |> Map.new() {span, previous_span, previous_span_attrs} = @@ -23,7 +24,7 @@ defmodule NewRelic.Tracer.Direct do Process.put( {:nr_span, id}, - {name, start_time, attributes, {span, previous_span, previous_span_attrs}} + {name, system_time, monotonic_time, attributes, {span, previous_span, previous_span_attrs}} ) end @@ -31,17 +32,17 @@ defmodule NewRelic.Tracer.Direct do end def stop_span(id, options \\ []) do - case Process.get({:nr_span, id}) do + case Process.delete({:nr_span, id}) do nil -> :no_such_span - {name, start_time, start_attributes, {span, previous_span, previous_span_attrs}} -> + {name, system_time, monotonic_start_time, start_attributes, {span, previous_span, previous_span_attrs}} -> Process.put(:nr_open_span_count, Process.get(:nr_open_span_count) - 1) {duration, duration_s} = case Keyword.get(options, :duration) do nil -> - duration = System.system_time() - start_time + duration = System.monotonic_time() - monotonic_start_time {duration, System.convert_time_unit(duration, :native, :millisecond) / 1_000} duration -> @@ -51,7 +52,7 @@ defmodule NewRelic.Tracer.Direct do name = Keyword.get(options, :name, name) stop_attributes = Keyword.get(options, :attributes, []) |> Map.new() attributes = Map.merge(start_attributes, stop_attributes) - timestamp_ms = System.convert_time_unit(start_time, :native, :millisecond) + timestamp_ms = System.convert_time_unit(system_time, :native, :millisecond) {primary_name, secondary_name} = case name do @@ -66,7 +67,7 @@ defmodule NewRelic.Tracer.Direct do pid: self(), id: span, parent_id: previous_span || :root, - start_time: start_time, + start_time: system_time, duration: duration }) @@ -79,6 +80,8 @@ defmodule NewRelic.Tracer.Direct do attributes: attributes ) + NewRelic.report_metric({:function, primary_name}, duration_s: duration_s) + NewRelic.DistributedTrace.reset_span( previous_span: previous_span, previous_span_attrs: previous_span_attrs diff --git a/lib/new_relic/transaction/reporter.ex b/lib/new_relic/transaction/reporter.ex index 264f1c10..be024d43 100644 --- a/lib/new_relic/transaction/reporter.ex +++ b/lib/new_relic/transaction/reporter.ex @@ -27,16 +27,18 @@ defmodule NewRelic.Transaction.Reporter do end def start_transaction(:web, path) do - {system_time, start_time_mono} = {System.system_time(), System.monotonic_time()} - - if NewRelic.Util.path_match?(path, NewRelic.Config.ignore_paths()) do - ignore_transaction() - :ignore - else - Transaction.ErlangTrace.trace() - Transaction.Sidecar.track(:web) - Transaction.Sidecar.add(system_time: system_time, start_time_mono: start_time_mono) - :collect + unless Transaction.Sidecar.tracking?() do + {system_time, start_time_mono} = {System.system_time(), System.monotonic_time()} + + if NewRelic.Util.path_match?(path, NewRelic.Config.ignore_paths()) do + ignore_transaction() + :ignore + else + Transaction.ErlangTrace.trace() + Transaction.Sidecar.track(:web) + Transaction.Sidecar.add(system_time: system_time, start_time_mono: start_time_mono) + :collect + end end end From c5d00a30ba97df3349d9d300b49041490d96c643 Mon Sep 17 00:00:00 2001 From: Vince Foley Date: Thu, 13 Feb 2025 20:57:07 -0800 Subject: [PATCH 2/2] Only stop websocket transaction when render completes --- lib/new_relic/telemetry/phoenix_live_view.ex | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/new_relic/telemetry/phoenix_live_view.ex b/lib/new_relic/telemetry/phoenix_live_view.ex index 686c7ee0..e9053800 100644 --- a/lib/new_relic/telemetry/phoenix_live_view.ex +++ b/lib/new_relic/telemetry/phoenix_live_view.ex @@ -153,7 +153,9 @@ defmodule NewRelic.Telemetry.PhoenixLiveView do def handle_event(@live_view_render_stop, meas, meta, _config) do Tracer.Direct.stop_span(meta.telemetry_span_context, duration: meas.duration) - Transaction.Reporter.stop_transaction(:web) + if meta.socket.transport_pid do + Transaction.Reporter.stop_transaction(:web) + end end def handle_event(@live_view_render_exception, meas, meta, _config) do @@ -163,7 +165,9 @@ defmodule NewRelic.Telemetry.PhoenixLiveView do attributes: [error: true, "error.kind": meta.kind, "error.reason": inspect(meta.reason)] ) - Transaction.Reporter.stop_transaction(:web) + if meta.socket.transport_pid do + Transaction.Reporter.stop_transaction(:web) + end end def handle_event(_event, _meas, _meta, _config) do