Refactor: Create TraceHandler GenServer

lib/live_debugger.ex

@@ -27,6 +27,7 @@ defmodule LiveDebugger do
 
     if Application.get_env(@app_name, :refactor, false) do
       LiveDebuggerRefactor.API.SettingsStorage.init()
+      LiveDebuggerRefactor.API.TracesStorage.init()
 
       get_refactor_children()
     else

lib/live_debugger_refactor/api/system/process.ex

@@ -1,6 +1,11 @@
 defmodule LiveDebuggerRefactor.API.System.Process do
   @moduledoc """
   This module provides wrappers for system functions that queries processes in the current application.
+
+  It is discouraged to use it
+  It will be entirely moved to `LiveDebuggerRefactor.API.LiveViewDebug` in the future.
+
+  https://github.com/software-mansion/live-debugger/issues/577
   """
   @callback initial_call(pid :: pid()) :: {:ok, mfa()} | {:error, term()}
   @callback state(pid :: pid()) :: {:ok, term()} | {:error, term()}

lib/live_debugger_refactor/api/traces_storage.ex

@@ -4,7 +4,7 @@ defmodule LiveDebuggerRefactor.API.TracesStorage do
   It uses Erlang's ETS (Erlang Term Storage).
   """
 
-  alias LiveDebugger.Structs.Trace
+  alias LiveDebuggerRefactor.Structs.Trace
   alias LiveDebuggerRefactor.CommonTypes
 
   @typedoc """
@@ -456,6 +456,10 @@ defmodule LiveDebuggerRefactor.API.TracesStorage do
         [] ->
           ref = :ets.new(@traces_table_name, [:ordered_set, :public])
           :ets.insert(@processes_table_name, {pid, ref})
+
+          # This cannot be given away to LiveDebugger.Supervisor - it's temporary solution
+          # It will be given away to GarbageCollector
+          :ets.give_away(ref, Process.whereis(LiveDebugger.Supervisor), nil)
           ref
 
         [{^pid, ref}] ->

lib/live_debugger_refactor/services/callback_tracer/actions/trace.ex

@@ -0,0 +1,132 @@
+defmodule LiveDebuggerRefactor.Services.CallbackTracer.Actions.Trace do
+  @moduledoc """
+  This module provides actions for traces.
+  """
+
+  alias LiveDebuggerRefactor.Structs.Trace
+  alias LiveDebuggerRefactor.API.TracesStorage
+  alias LiveDebuggerRefactor.API.LiveViewDebug
+
+  alias LiveDebuggerRefactor.Bus
+  alias LiveDebuggerRefactor.Services.CallbackTracer.Events.TraceCalled
+  alias LiveDebuggerRefactor.Services.CallbackTracer.Events.TraceReturned
+  alias LiveDebuggerRefactor.Services.CallbackTracer.Events.TraceErrored
+
+  @spec create_trace(
+          n :: non_neg_integer(),
+          module :: module(),
+          fun :: atom(),
+          args :: list(),
+          pid :: pid(),
+          timestamp :: :erlang.timestamp()
+        ) :: {:ok, Trace.t()} | {:error, term()}
+  def create_trace(n, module, fun, args, pid, timestamp) do
+    trace = Trace.new(n, module, fun, args, pid, timestamp)
+
+    case trace.transport_pid do
+      nil ->
+        {:error, "Transport PID is nil"}
+
+      _ ->
+        {:ok, trace}
+    end
+  end
+
+  @spec create_delete_component_trace(
+          n :: non_neg_integer(),
+          args :: list(),
+          pid :: pid(),
+          cid :: String.t(),
+          timestamp :: :erlang.timestamp()
+        ) :: {:ok, Trace.t()} | {:error, term()}
+  def create_delete_component_trace(n, args, pid, cid, timestamp) do
+    pid
+    |> LiveViewDebug.socket()
+    |> case do
+      {:ok, %{id: socket_id, transport_pid: t_pid}} when is_pid(t_pid) ->
+        trace =
+          Trace.new(
+            n,
+            Phoenix.LiveView.Diff,
+            :delete_component,
+            args,
+            pid,
+            timestamp,
+            socket_id: socket_id,
+            transport_pid: t_pid,
+            cid: %Phoenix.LiveComponent.CID{cid: cid}
+          )
+
+        {:ok, trace}
+
+      _ ->
+        {:error, "Could not get socket"}
+    end
+  end
+
+  @spec update_trace(Trace.t(), map()) :: {:ok, Trace.t()}
+  def update_trace(%Trace{} = trace, params) do
+    {:ok, Map.merge(trace, params)}
+  end
+
+  @spec persist_trace(Trace.t()) :: {:ok, reference()} | {:error, term()}
+  def persist_trace(%Trace{pid: pid} = trace) do
+    with ref when is_reference(ref) <- TracesStorage.get_table(pid),
+         true <- TracesStorage.insert!(ref, trace) do
+      {:ok, ref}
+    else
+      _ ->
+        {:error, "Could not persist trace"}
+    end
+  end
+
+  @spec persist_trace(Trace.t(), reference()) :: {:ok, reference()}
+  def persist_trace(%Trace{} = trace, ref) do
+    TracesStorage.insert!(ref, trace)
+
+    {:ok, ref}
+  end
+
+  @spec publish_trace(Trace.t(), reference() | nil) :: :ok | {:error, term()}
+  def publish_trace(%Trace{pid: pid} = trace, ref \\ nil) do
+    trace
+    |> get_event(ref)
+    |> Bus.broadcast_trace!(pid)
+  rescue
+    err ->
+      {:error, err}
+  end
+
+  defp get_event(%Trace{type: :call} = trace, ref) do
+    %TraceCalled{
+      trace_id: trace.id,
+      ets_ref: ref,
+      module: trace.module,
+      function: trace.function,
+      pid: trace.pid,
+      cid: trace.cid
+    }
+  end
+
+  defp get_event(%Trace{type: :return_from} = trace, ref) do
+    %TraceReturned{
+      trace_id: trace.id,
+      ets_ref: ref,
+      module: trace.module,
+      function: trace.function,
+      pid: trace.pid,
+      cid: trace.cid
+    }
+  end
+
+  defp get_event(%Trace{type: :exception_from} = trace, ref) do
+    %TraceErrored{
+      trace_id: trace.id,
+      ets_ref: ref,
+      module: trace.module,
+      function: trace.function,
+      pid: trace.pid,
+      cid: trace.cid
+    }
+  end
+end

lib/live_debugger_refactor/services/callback_tracer/events.ex

@@ -10,6 +10,7 @@ defmodule LiveDebuggerRefactor.Services.CallbackTracer.Events do
 
   defevent(TraceCalled,
     trace_id: Trace.id(),
+    ets_ref: reference() | nil,
     module: module(),
     function: atom(),
     pid: pid(),
@@ -18,6 +19,16 @@ defmodule LiveDebuggerRefactor.Services.CallbackTracer.Events do
 
   defevent(TraceReturned,
     trace_id: Trace.id(),
+    ets_ref: reference() | nil,
+    module: module(),
+    function: atom(),
+    pid: pid(),
+    cid: CommonTypes.cid() | nil
+  )
+
+  defevent(TraceErrored,
+    trace_id: Trace.id(),
+    ets_ref: reference() | nil,
     module: module(),
     function: atom(),
     pid: pid(),

lib/live_debugger_refactor/services/callback_tracer/gen_servers/trace_handler.ex

@@ -0,0 +1,190 @@
+defmodule LiveDebuggerRefactor.Services.CallbackTracer.GenServers.TraceHandler do
+  @moduledoc """
+  GenServer for handling trace data.
+  """
+
+  use GenServer
+
+  require Logger
+
+  alias LiveDebuggerRefactor.Utils.Callbacks, as: CallbackUtils
+  alias LiveDebuggerRefactor.Services.CallbackTracer.Actions.Trace, as: TraceActions
+  alias LiveDebuggerRefactor.Services.CallbackTracer.Actions.Tracing, as: TracingActions
+  alias LiveDebuggerRefactor.Structs.Trace
+
+  @allowed_callbacks Enum.map(CallbackUtils.all_callbacks(), &elem(&1, 0))
+
+  @typedoc """
+  Trace record is a tuple of:
+  - reference to ETS table
+  - trace struct
+  - timestamp of the trace
+
+  We are storing this tuple in the state of this GenServer to calculate execution time of callbacks.
+  """
+  @type trace_record :: {reference(), Trace.t(), non_neg_integer()}
+
+  @typedoc """
+  Trace key is a tuple of:
+  - pid of the process that called the callback
+  - module of the callback
+  - function of the callback
+  """
+  @type trace_key :: {pid(), module(), atom()}
+  @type state :: %{trace_key => trace_record}
+
+  @spec start_link(opts :: list()) :: GenServer.on_start()
+  def start_link(opts \\ []) do
+    GenServer.start_link(__MODULE__, opts, name: __MODULE__)
+  end
+
+  @doc """
+  Handles trace from `:dbg.tracer` process.
+  """
+  @spec handle_trace(trace :: term(), n :: integer()) :: :ok
+  def handle_trace(trace, n) do
+    GenServer.cast(__MODULE__, {:new_trace, trace, n})
+  end
+
+  @impl true
+  def init(_opts) do
+    {:ok, %{}}
+  end
+
+  #########################################################
+  # Handling recompile events
+  #
+  # We catch this trace to know when modules were recompiled.
+  # We do not display this trace to user, so we do not have to care about order
+  # We need to catch that case because tracer disconnects from modules that were recompiled
+  # and we need to reapply tracing patterns to them.
+  # This will be replaced in the future with a more efficient way to handle this.
+  # https://github.com/software-mansion/live-debugger/issues/592
+  #
+  #########################################################
+
+  @impl true
+  def handle_cast(
+        {:new_trace, {_, _, :return_from, {Mix.Tasks.Compile.Elixir, _, _}, {:ok, _}, _}, _n},
+        state
+      ) do
+    Task.start(fn ->
+      Process.sleep(100)
+      TracingActions.refresh_tracing()
+    end)
+
+    {:noreply, state}
+  end
+
+  @impl true
+  def handle_cast({:new_trace, {_, _, _, {Mix.Tasks.Compile.Elixir, _, _}, _}, _}, state) do
+    {:noreply, state}
+  end
+
+  @impl true
+  def handle_cast({:new_trace, {_, _, _, {Mix.Tasks.Compile.Elixir, _, _}, _, _}, _}, state) do
+    {:noreply, state}
+  end
+
+  #########################################################
+  # Handling component deletion traces
+  #
+  # We catch this trace to know when components are deleted.
+  # We do not display this trace to user, so we do not have to care about order
+  # This will be replaced in the future with telemetry event added in LiveView 1.1.0
+  # https://hexdocs.pm/phoenix_live_view/1.1.0-rc.3/telemetry.html
+  #
+  #########################################################
+
+  @impl true
+  def handle_cast(
+        {:new_trace,
+         {_, pid, _, {Phoenix.LiveView.Diff, :delete_component, [cid | _] = args}, ts}, n},
+        state
+      ) do
+    Task.start(fn ->
+      with {:ok, trace} <- TraceActions.create_delete_component_trace(n, args, pid, cid, ts),
+           :ok <- TraceActions.publish_trace(trace) do
+        :ok
+      else
+        {:error, err} ->
+          raise "Error while handling trace: #{inspect(err)}"
+      end
+    end)
+
+    {:noreply, state}
+  end
+
+  #########################################################
+  # Handling standard callback traces
+  #
+  # To measure execution time of callbacks we save in GenServer timestamp when callback is called.
+  # Since LiveView is a single process all callbacks are called in order.
+  # This means that we can measure execution time of callbacks by subtracting timestamp when
+  # callback is called from timestamp when callback returns.
+  #
+  #########################################################
+
+  @impl true
+  def handle_cast({:new_trace, {_, pid, :call, {module, fun, args}, ts}, n}, state)
+      when fun in @allowed_callbacks do
+    with {:ok, trace} <- TraceActions.create_trace(n, module, fun, args, pid, ts),
+         {:ok, ref} <- TraceActions.persist_trace(trace),
+         :ok <- TraceActions.publish_trace(trace, ref) do
+      {:noreply, put_trace_record(state, trace, ref, ts)}
+    else
+      {:error, "Transport PID is nil"} ->
+        {:noreply, state}
+
+      {:error, err} ->
+        raise "Error while handling trace: #{inspect(err)}"
+    end
+  end
+
+  @impl true
+  def handle_cast({:new_trace, {_, pid, type, {module, fun, _}, _, return_ts}, _n}, state)
+      when fun in @allowed_callbacks and type in [:return_from, :exception_from] do
+    with trace_key <- {pid, module, fun},
+         {ref, trace, ts} <- get_trace_record(state, trace_key),
+         execution_time <- calculate_execution_time(return_ts, ts),
+         params <- %{execution_time: execution_time, type: type},
+         {:ok, updated_trace} <- TraceActions.update_trace(trace, params),
+         {:ok, ref} <- TraceActions.persist_trace(updated_trace, ref),
+         :ok <- TraceActions.publish_trace(updated_trace, ref) do
+      {:noreply, delete_trace_record(state, trace_key)}
+    else
+      :trace_record_not_found ->
+        {:noreply, state}
+
+      {:error, err} ->
+        raise "Error while handling trace: #{inspect(err)}"
+    end
+  end
+
+  #########################################################
+  # Handling unknown traces
+  #########################################################
+
+  @impl true
+  def handle_cast({:new_trace, trace, _n}, state) do
+    Logger.info("Ignoring unexpected trace: #{inspect(trace)}")
+
+    {:noreply, state}
+  end
+
+  defp put_trace_record(state, trace, ref, timestamp) do
+    Map.put(state, {trace.pid, trace.module, trace.function}, {ref, trace, timestamp})
+  end
+
+  defp get_trace_record(state, trace_key) do
+    Map.get(state, trace_key, :trace_record_not_found)
+  end
+
+  defp delete_trace_record(state, trace_key) do
+    Map.delete(state, trace_key)
+  end
+
+  defp calculate_execution_time(return_ts, call_ts) do
+    :timer.now_diff(return_ts, call_ts)
+  end
+end