Task: implement displaying event handling time (#277)

* Get execution time using dbg trace return_from

* Implement callback execution time measuring

* Display callback execution time

* Add spinner

* Add parsing elapsed time

* Change execution time visualization

* Add timer

* Small tweaks

* Remove console.log

* Rename hook

* Change timer stopping

* Refactor

* Add tooltips

* Refactor

* Fix infinite loading spinner

* Show only finished callbacks on refresh

* Fix trace callback return after tracing stopped

* Save timestamp to trace from tracer handler

* Update TraceService test

* fix

* Update tests

* Add e2e test cases

Author: hhubert6

assets/css/themes/dark.css

@@ -61,5 +61,8 @@
     --error-border: var(--gray-700);
     --error-icon: var(--swm-pink-80);
     --error-text: var(--swm-pink-80);
+
+    /* Warning */
+    --warning-text: var(--swm-yellow-40);
   }
 }

assets/css/themes/light.css

@@ -61,5 +61,8 @@
     --error-border: var(--red-100);
     --error-icon: var(--red-500);
     --error-text: var(--red-800);
+
+    /* Warning */
+    --warning-text: #9a7e00;
   }
 }

assets/js/hooks.js

@@ -8,6 +8,7 @@ import Tooltip from './hooks/tooltip';
 import Highlight from './hooks/highlight';
 import LiveDropdown from './hooks/live_dropdown';
 import AutoClearFlash from './hooks/auto_clear_flash';
+import TraceExecutionTime from './hooks/trace_execution_time';
 
 import topbar from '../vendor/topbar';
 
@@ -28,6 +29,7 @@ function createHooks() {
     Highlight,
     LiveDropdown,
     AutoClearFlash,
+    TraceExecutionTime,
   };
 }
 

assets/js/hooks/trace_execution_time.js

@@ -0,0 +1,25 @@
+const TraceExecutionTime = {
+  mounted() {
+    let start = Date.now();
+    let current = start;
+    let handled = false;
+
+    this.intervalId = setInterval(() => {
+      current = Date.now() - start;
+      this.el.textContent = current + ' ms';
+    }, 16);
+
+    this.handleEvent('stop-timer', () => {
+      if (!handled) {
+        clearInterval(this.intervalId);
+        this.el.closest('details').open = false;
+        handled = true;
+      }
+    });
+  },
+  destroyed() {
+    clearInterval(this.intervalId);
+  },
+};
+
+export default TraceExecutionTime;

assets/tailwind.config.js

@@ -62,6 +62,7 @@ module.exports = {
         'error-border': 'var(--error-border)',
         'error-icon': 'var(--error-icon)',
         'error-text': 'var(--error-text)',
+        'warning-text': 'var(--warning-text)',
       },
       screens: { xs: '380px' },
       fontFamily: {

dev/live_views/main.ex

@@ -7,6 +7,8 @@ defmodule LiveDebuggerDev.LiveViews.Main do
     socket =
       socket
       |> assign(counter: 0)
+      |> assign(counter_slow: 0)
+      |> assign(counter_very_slow: 0)
       |> assign(datetime: nil)
       |> assign(name: random_name())
       |> assign(single_element_list: [%Phoenix.LiveComponent.CID{cid: 1}])
@@ -29,6 +31,18 @@ defmodule LiveDebuggerDev.LiveViews.Main do
           </.button>
           <span class="text-xl"><%= @counter %></span>
         </div>
+        <div class="flex items-center gap-2">
+          <.button id="slow-increment-button" phx-click="slow-increment" color="blue">
+            Slow Increment
+          </.button>
+          <span class="text-xl"><%= @counter_slow %></span>
+        </div>
+        <div class="flex items-center gap-2">
+          <.button id="very-slow-increment-button" phx-click="very-slow-increment" color="blue">
+            Very Slow Increment
+          </.button>
+          <span class="text-xl"><%= @counter_very_slow %></span>
+        </div>
         <div class="flex items-center gap-1">
           <.button id="update-button" phx-click="change_name" color="red">
             Update
@@ -72,7 +86,17 @@ defmodule LiveDebuggerDev.LiveViews.Main do
   end
 
   def handle_event("increment", _, socket) do
-    {:noreply, assign(socket, :counter, socket.assigns.counter + 1)}
+    {:noreply, update(socket, :counter, &(&1 + 1))}
+  end
+
+  def handle_event("slow-increment", _, socket) do
+    Process.sleep(400)
+    {:noreply, update(socket, :counter_slow, &(&1 + 1))}
+  end
+
+  def handle_event("very-slow-increment", _, socket) do
+    Process.sleep(2500)
+    {:noreply, update(socket, :counter_very_slow, &(&1 + 1))}
   end
 
   def handle_event("change_name", _, socket) do

lib/live_debugger/gen_servers/callback_tracing_server.ex

@@ -45,7 +45,7 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
   @impl true
   def handle_info(:setup_tracing, state) do
     Dbg.tracer(:process, {&handle_trace/2, 0})
-    Dbg.p(:all, :c)
+    Dbg.p(:all, [:c, :timestamp])
 
     all_modules = ModuleDiscoveryService.all_modules()
 
@@ -58,7 +58,10 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
     |> ModuleDiscoveryService.live_component_modules()
     |> CallbackUtils.live_component_callbacks()
     |> Enum.concat(callbacks)
-    |> Enum.each(fn mfa -> Dbg.tp(mfa, []) end)
+    |> Enum.each(fn mfa ->
+      Dbg.tp(mfa, [{:_, [], [{:return_trace}]}])
+      Dbg.tp(mfa, [{:_, [], [{:exception_trace}]}])
+    end)
 
     # This is not a callback created by user
     # We trace it to refresh the components tree
@@ -76,7 +79,10 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
   # Because of that we do it asynchronously to speed up tracer a bit
   # We do not persist this trace because it is not displayed to user
   @spec handle_trace(term(), n :: integer()) :: integer()
-  defp handle_trace({_, pid, _, {Phoenix.LiveView.Diff, :delete_component, [cid | _] = args}}, n) do
+  defp handle_trace(
+         {_, pid, _, {Phoenix.LiveView.Diff, :delete_component, [cid | _] = args}, timestamp},
+         n
+       ) do
     Task.start(fn ->
       with cid <- %Phoenix.LiveComponent.CID{cid: cid},
            {:ok, %{socket: socket}} <- ChannelService.state(pid),
@@ -89,6 +95,7 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
                :delete_component,
                args,
                pid,
+               timestamp,
                socket_id: socket_id,
                transport_pid: transport_pid,
                cid: cid
@@ -102,16 +109,36 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
 
   # This handles callbacks created by user that will be displayed to user
   # It cannot be async because we care about order
-  defp handle_trace({_, pid, _, {module, fun, args}}, n) when fun in @callback_functions do
-    with trace <- Trace.new(n, module, fun, args, pid),
+  defp handle_trace({_, pid, :call, {module, fun, args}, timestamp}, n)
+       when fun in @callback_functions do
+    with trace <- Trace.new(n, module, fun, args, pid, timestamp),
          true <- is_pid(trace.transport_pid),
          :ok <- persist_trace(trace) do
+      :erlang.put({pid, module, fun}, {timestamp, trace})
       publish_trace(trace)
     end
 
     n - 1
   end
 
+  defp handle_trace({_, pid, :return_from, {module, fun, _arity}, _, return_ts}, n)
+       when fun in @callback_functions do
+    with {call_ts, trace} <- :erlang.get({pid, module, fun}),
+         execution_time <- :timer.now_diff(return_ts, call_ts),
+         trace <- %{trace | execution_time: execution_time},
+         :ok <- persist_trace(trace) do
+      :erlang.erase({pid, module, fun})
+      publish_update_trace(trace)
+    end
+
+    n
+  end
+
+  defp handle_trace({_, _pid, :exception_from, {_module, fun, _}, _, _timestamp}, n)
+       when fun in @callback_functions do
+    n
+  end
+
   defp handle_trace(trace, n) do
     Logger.info("Ignoring unexpected trace: #{inspect(trace)}")
     n
@@ -138,6 +165,16 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
       {:error, err}
   end
 
+  @spec publish_update_trace(Trace.t()) :: :ok | {:error, term()}
+  defp publish_update_trace(%Trace{} = trace) do
+    do_publish_update(trace)
+    :ok
+  rescue
+    err ->
+      Logger.error("Error while publishing trace: #{inspect(err)}")
+      {:error, err}
+  end
+
   @spec do_publish(Trace.t()) :: :ok
   defp do_publish(%{module: Phoenix.LiveView.Diff} = trace) do
     trace
@@ -152,11 +189,23 @@ defmodule LiveDebugger.GenServers.CallbackTracingServer do
     fun = trace.function
 
     socket_id
-    |> PubSubUtils.tsnf_topic(transport_pid, node_id, fun)
+    |> PubSubUtils.tsnf_topic(transport_pid, node_id, fun, :call)
     |> PubSubUtils.broadcast({:new_trace, trace})
 
     socket_id
     |> PubSubUtils.ts_f_topic(transport_pid, fun)
     |> PubSubUtils.broadcast({:new_trace, trace})
   end
+
+  @spec do_publish_update(Trace.t()) :: :ok
+  defp do_publish_update(trace) do
+    socket_id = trace.socket_id
+    node_id = Trace.node_id(trace)
+    transport_pid = trace.transport_pid
+    fun = trace.function
+
+    socket_id
+    |> PubSubUtils.tsnf_topic(transport_pid, node_id, fun, :return)
+    |> PubSubUtils.broadcast({:updated_trace, trace})
+  end
 end

lib/live_debugger/services/trace_service.ex

@@ -120,21 +120,22 @@ defmodule LiveDebugger.Services.TraceService do
 
   defp match_spec(node_id, functions) when is_pid(node_id) do
     [
-      {{:_, %{function: :"$1", pid: node_id, cid: nil}}, to_spec(functions), [:"$_"]}
+      {{:_, %{function: :"$1", execution_time: :"$2", pid: node_id, cid: nil}},
+       to_spec(functions), [:"$_"]}
     ]
   end
 
   defp match_spec(%CID{} = node_id, functions) do
-    [{{:_, %{function: :"$1", cid: node_id}}, to_spec(functions), [:"$_"]}]
+    [{{:_, %{function: :"$1", execution_time: :"$2", cid: node_id}}, to_spec(functions), [:"$_"]}]
   end
 
   defp match_spec(nil, functions) do
-    [{{:_, %{function: :"$1"}}, to_spec(functions), [:"$_"]}]
+    [{{:_, %{function: :"$1", execution_time: :"$2"}}, to_spec(functions), [:"$_"]}]
   end
 
-  def to_spec([]), do: []
+  def to_spec([]), do: [{:"/=", :"$2", nil}]
 
-  def to_spec([single]), do: [{:"=:=", :"$1", single}]
+  def to_spec([single]), do: [{:andalso, {:"=:=", :"$1", single}, {:"/=", :"$2", nil}}]
 
   def to_spec([first, second | rest]) do
     initial_orelse = {:orelse, List.first(to_spec([first])), List.first(to_spec([second]))}
@@ -144,7 +145,7 @@ defmodule LiveDebugger.Services.TraceService do
         {:orelse, acc, List.first(to_spec([x]))}
       end)
 
-    [result]
+    [{:andalso, result, {:"/=", :"$2", nil}}]
   end
 
   @spec ets_table!(pid :: ets_table_id()) :: :ets.table()

lib/live_debugger/structs/trace.ex

@@ -23,9 +23,12 @@ defmodule LiveDebugger.Structs.Trace do
     :transport_pid,
     :pid,
     :cid,
-    :timestamp
+    :timestamp,
+    :execution_time
   ]
 
+  @type timestamp() :: {non_neg_integer(), non_neg_integer(), non_neg_integer()}
+
   @type t() :: %__MODULE__{
           id: integer(),
           module: atom(),
@@ -36,14 +39,15 @@ defmodule LiveDebugger.Structs.Trace do
           transport_pid: pid() | nil,
           pid: pid(),
           cid: struct() | nil,
-          timestamp: non_neg_integer()
+          timestamp: timestamp(),
+          execution_time: non_neg_integer() | nil
         }
 
   @doc """
   Creates a new trace struct.
   """
-  @spec new(integer(), atom(), atom(), list(), pid(), Keyword.t()) :: t()
-  def new(id, module, function, args, pid, opts \\ []) do
+  @spec new(integer(), atom(), atom(), list(), pid(), timestamp(), Keyword.t()) :: t()
+  def new(id, module, function, args, pid, timestamp, opts \\ []) do
     socket_id = Keyword.get(opts, :socket_id, get_socket_id_from_args(args))
     transport_pid = Keyword.get(opts, :transport_pid, get_transport_pid_from_args(args))
     cid = Keyword.get(opts, :cid, get_cid_from_args(args))
@@ -58,7 +62,8 @@ defmodule LiveDebugger.Structs.Trace do
       transport_pid: transport_pid,
       pid: pid,
       cid: cid,
-      timestamp: :os.system_time(:microsecond)
+      timestamp: :timer.now_diff(timestamp, {0, 0, 0}),
+      execution_time: nil
     }
   end
 

lib/live_debugger/structs/trace_display.ex

@@ -6,16 +6,17 @@ defmodule LiveDebugger.Structs.TraceDisplay do
 
   alias LiveDebugger.Structs.Trace
 
-  defstruct [:id, :trace, :render_body?, :counter]
+  defstruct [:id, :trace, :render_body?, :from_tracing?, :counter]
 
   @type t() :: %__MODULE__{
           id: integer(),
           trace: Trace.t(),
-          render_body?: boolean()
+          render_body?: boolean(),
+          from_tracing?: boolean()
         }
 
-  def from_trace(%Trace{} = trace) do
-    %__MODULE__{id: trace.id, trace: trace, render_body?: false}
+  def from_trace(%Trace{} = trace, from_tracing? \\ false) do
+    %__MODULE__{id: trace.id, trace: trace, render_body?: false, from_tracing?: from_tracing?}
   end
 
   def render_body(%__MODULE__{} = trace) do