Task: Implement filtering by execution time (#379)

* Filter loading existing traces

* Apply execution time filter

* Filter new traces

* Update CallbackTracingServer tests

* Update TraceService tests

* Fix empty inputs

* Add e2e tests

Author: hhubert6

lib/live_debugger/services/trace_service.ex

@@ -97,13 +97,14 @@ defmodule LiveDebugger.Services.TraceService do
   defp existing_traces_start(table_id, opts) do
     limit = Keyword.get(opts, :limit, @default_limit)
     functions = Keyword.get(opts, :functions, [])
+    execution_times = Keyword.get(opts, :execution_times, [])
     node_id = Keyword.get(opts, :node_id)
 
     if limit < 1 do
       raise ArgumentError, "limit must be >= 1"
     end
 
-    match_spec = match_spec(node_id, functions)
+    match_spec = match_spec(node_id, functions, execution_times)
 
     table_id
     |> ets_table!()
@@ -118,36 +119,65 @@ defmodule LiveDebugger.Services.TraceService do
     :ets.select(cont)
   end
 
-  defp match_spec(node_id, functions) when is_pid(node_id) do
+  defp match_spec(node_id, functions, execution_times) when is_pid(node_id) do
     [
       {{:_, %{function: :"$1", execution_time: :"$2", pid: node_id, cid: nil}},
-       to_spec(functions), [:"$_"]}
+       to_spec(functions, execution_times), [:"$_"]}
     ]
   end
 
-  defp match_spec(%CID{} = node_id, functions) do
-    [{{:_, %{function: :"$1", execution_time: :"$2", cid: node_id}}, to_spec(functions), [:"$_"]}]
+  defp match_spec(%CID{} = node_id, functions, execution_times) do
+    [
+      {{:_, %{function: :"$1", execution_time: :"$2", cid: node_id}},
+       to_spec(functions, execution_times), [:"$_"]}
+    ]
+  end
+
+  defp match_spec(nil, functions, execution_times) do
+    [
+      {{:_, %{function: :"$1", execution_time: :"$2"}}, to_spec(functions, execution_times),
+       [:"$_"]}
+    ]
+  end
+
+  def to_spec([], []), do: [{:"/=", :"$2", nil}]
+
+  def to_spec(functions, []) do
+    [{:andalso, List.first(functions_to_spec(functions)), {:"/=", :"$2", nil}}]
   end
 
-  defp match_spec(nil, functions) do
-    [{{:_, %{function: :"$1", execution_time: :"$2"}}, to_spec(functions), [:"$_"]}]
+  def to_spec([], execution_times) do
+    [{:andalso, List.first(execution_times_to_spec(execution_times)), {:"/=", :"$2", nil}}]
   end
 
-  def to_spec([]), do: [{:"/=", :"$2", nil}]
+  def to_spec(functions, execution_times) do
+    [
+      {:andalso,
+       {:andalso, List.first(functions_to_spec(functions)),
+        List.first(execution_times_to_spec(execution_times))}, {:"/=", :"$2", nil}}
+    ]
+  end
 
-  def to_spec([single]), do: [{:andalso, {:"=:=", :"$1", single}, {:"/=", :"$2", nil}}]
+  def functions_to_spec([single]), do: [{:"=:=", :"$1", single}]
 
-  def to_spec([first, second | rest]) do
-    initial_orelse = {:orelse, List.first(to_spec([first])), List.first(to_spec([second]))}
+  def functions_to_spec([first, second | rest]) do
+    initial_orelse =
+      {:orelse, List.first(functions_to_spec([first])), List.first(functions_to_spec([second]))}
 
     result =
       Enum.reduce(rest, initial_orelse, fn x, acc ->
-        {:orelse, acc, List.first(to_spec([x]))}
+        {:orelse, acc, List.first(functions_to_spec([x]))}
       end)
 
     [{:andalso, result, {:"/=", :"$2", nil}}]
   end
 
+  def execution_times_to_spec(execution_times) do
+    min_time = Keyword.get(execution_times, :exec_time_min, 0)
+    max_time = Keyword.get(execution_times, :exec_time_max, :infinity)
+    [{:andalso, {:>=, :"$2", min_time}, {:"=<", :"$2", max_time}}]
+  end
+
   @spec ets_table!(pid :: ets_table_id()) :: :ets.table()
   defp ets_table!(pid) when is_pid(pid) do
     EtsTableServer.table!(pid)

lib/live_debugger_web/live/traces_live.ex

@@ -244,11 +244,20 @@ defmodule LiveDebuggerWeb.TracesLive do
   def handle_info({:updated_trace, trace}, socket) when socket.assigns.trace_callback_running? do
     trace_display = TraceDisplay.from_trace(trace, true)
 
-    socket
+    execution_time = get_execution_times(socket)
+    min_time = Keyword.get(execution_time, :exec_time_min, 0)
+    max_time = Keyword.get(execution_time, :exec_time_max, :infinity)
+
+    if trace.execution_time >= min_time and trace.execution_time <= max_time do
+      socket
+      |> stream_insert(:existing_traces, trace_display, at: 0, limit: @live_stream_limit)
+    else
+      socket
+      |> stream_delete(:existing_traces, trace_display)
+    end
     |> assign(trace_callback_running?: false)
     |> TracingHelper.maybe_disable_tracing_after_update()
     |> push_event("stop-timer", %{})
-    |> stream_insert(:existing_traces, trace_display, at: 0, limit: @live_stream_limit)
     |> noreply()
   end
 
@@ -366,6 +375,7 @@ defmodule LiveDebuggerWeb.TracesLive do
     pid = socket.assigns.lv_process.pid
     node_id = socket.assigns.node_id
     active_functions = get_active_functions(socket)
+    execution_times = get_execution_times(socket)
 
     socket
     |> assign(:existing_traces_status, :loading)
@@ -374,7 +384,8 @@ defmodule LiveDebuggerWeb.TracesLive do
       TraceService.existing_traces(pid,
         node_id: node_id,
         limit: @page_size,
-        functions: active_functions
+        functions: active_functions,
+        execution_times: execution_times
       )
     end)
   end
@@ -384,6 +395,7 @@ defmodule LiveDebuggerWeb.TracesLive do
     node_id = socket.assigns.node_id
     cont = socket.assigns.traces_continuation
     active_functions = get_active_functions(socket)
+    execution_times = get_execution_times(socket)
 
     socket
     |> assign(:traces_continuation, :loading)
@@ -392,7 +404,8 @@ defmodule LiveDebuggerWeb.TracesLive do
         node_id: node_id,
         limit: @page_size,
         cont: cont,
-        functions: active_functions
+        functions: active_functions,
+        execution_times: execution_times
       )
     end)
   end
@@ -411,7 +424,7 @@ defmodule LiveDebuggerWeb.TracesLive do
       functions: functions,
       execution_time: [
         {:exec_time_max, ""},
-        {:exec_time_min, "0"}
+        {:exec_time_min, ""}
       ]
     }
   end
@@ -422,6 +435,12 @@ defmodule LiveDebuggerWeb.TracesLive do
     |> Enum.map(fn {function, _} -> function end)
   end
 
+  defp get_execution_times(socket) do
+    socket.assigns.current_filters.execution_time
+    |> Enum.filter(fn {_, value} -> value != "" end)
+    |> Enum.map(fn {filter, value} -> {filter, String.to_integer(value)} end)
+  end
+
   defp log_async_error(operation, reason) do
     Logger.error(
       "LiveDebugger encountered unexpected error while #{operation}: #{inspect(reason)}"

lib/live_debugger_web/live_components/filters_form.ex

@@ -144,13 +144,21 @@ defmodule LiveDebuggerWeb.LiveComponents.FiltersForm do
         {filter, Map.get(params, Atom.to_string(filter), value)}
       end)
 
+    case validate_execution_time(execution_time) do
+      :ok -> {:ok, %{functions: functions, execution_time: execution_time}}
+      {:error, errors} -> {:error, errors}
+    end
+  end
+
+  defp validate_execution_time(execution_time) do
     min_time = Keyword.get(execution_time, :exec_time_min, 0)
     max_time = Keyword.get(execution_time, :exec_time_max, :infinity)
 
-    if String.to_integer(min_time) > String.to_integer(max_time) do
+    if min_time != "" and max_time != "" and
+         String.to_integer(min_time) > String.to_integer(max_time) do
       {:error, [exec_time_min: "min must be less than max", exec_time_max: ""]}
     else
-      {:ok, %{functions: functions, execution_time: execution_time}}
+      :ok
     end
   end
 

test/gen_servers/callback_tracing_server_test.exs

@@ -85,6 +85,20 @@ defmodule LiveDebugger.GenServers.CallbackTracingServerTest do
       module = Phoenix.LiveView.Diff
       fun = :delete_component
       args = [cid, %{}]
+      timestamp = :erlang.timestamp()
+
+      expected_trace = %Trace{
+        id: 0,
+        module: module,
+        function: fun,
+        arity: 2,
+        args: args,
+        socket_id: socket_id,
+        transport_pid: transport_pid,
+        pid: pid,
+        cid: %Phoenix.LiveComponent.CID{cid: cid},
+        timestamp: :timer.now_diff(timestamp, {0, 0, 0})
+      }
 
       component_deleted_topic =
         PubSubUtils.component_deleted_topic()
@@ -95,26 +109,14 @@ defmodule LiveDebugger.GenServers.CallbackTracingServerTest do
       end)
 
       MockPubSubUtils
-      |> expect(:broadcast, fn ^component_deleted_topic, {:component_deleted, trace} ->
-        send(parent, {:trace, trace})
+      |> expect(:broadcast, fn ^component_deleted_topic, {:component_deleted, ^expected_trace} ->
+        send(parent, :broadcasted)
       end)
 
       assert {:noreply, %{}} = CallbackTracingServer.handle_info(:setup_tracing, %{})
       assert_receive handle_trace
-      assert 0 = handle_trace.({:trace, pid, :call, {module, fun, args}, :erlang.timestamp()}, 0)
-      assert_receive {:trace, trace}
-
-      assert %Trace{
-               id: 0,
-               module: ^module,
-               function: ^fun,
-               arity: 2,
-               args: ^args,
-               socket_id: ^socket_id,
-               transport_pid: ^transport_pid,
-               pid: ^pid,
-               cid: %Phoenix.LiveComponent.CID{cid: ^cid}
-             } = trace
+      assert 0 = handle_trace.({:trace, pid, :call, {module, fun, args}, timestamp}, 0)
+      assert_receive :broadcasted
     end
 
     test "handle standard live view trace" do
@@ -131,19 +133,28 @@ defmodule LiveDebugger.GenServers.CallbackTracingServerTest do
 
       table = :ets.new(:test_table, [:ordered_set, :public])
 
-      expected_trace_topic = PubSubUtils.trace_topic(socket_id, transport_pid, pid, fun)
+      expected_trace_call_topic =
+        PubSubUtils.trace_topic(socket_id, transport_pid, pid, fun, :call)
+
+      expected_trace_return_topic =
+        PubSubUtils.trace_topic(socket_id, transport_pid, pid, fun, :return)
 
       MockEtsTableServer
-      |> expect(:table!, fn ^pid -> table end)
+      |> expect(:table!, 2, fn ^pid -> table end)
 
       MockPubSubUtils
-      |> expect(:broadcast, fn ^expected_trace_topic, {:new_trace, _trace} -> :ok end)
+      |> expect(:broadcast, fn ^expected_trace_call_topic, {:new_trace, _trace} -> :ok end)
+      |> expect(:broadcast, fn ^expected_trace_return_topic, {:updated_trace, _trace} -> :ok end)
 
       assert {:noreply, %{}} = CallbackTracingServer.handle_info(:setup_tracing, %{})
       assert_receive handle_trace
-      assert -1 = handle_trace.({:trace, pid, :call, {module, fun, args}, :erlang.timestamp()}, 0)
+
+      call_timestamp = :erlang.timestamp()
+      assert -1 = handle_trace.({:trace, pid, :call, {module, fun, args}, call_timestamp}, 0)
       assert [{0, trace}] = :ets.tab2list(table)
 
+      expected_timestamp = :timer.now_diff(call_timestamp, {0, 0, 0})
+
       assert %Trace{
                id: 0,
                module: ^module,
@@ -153,8 +164,25 @@ defmodule LiveDebugger.GenServers.CallbackTracingServerTest do
                socket_id: ^socket_id,
                transport_pid: ^transport_pid,
                pid: ^pid,
-               cid: nil
+               cid: nil,
+               timestamp: ^expected_timestamp,
+               execution_time: nil
              } = trace
+
+      return_timestamp = :erlang.timestamp()
+
+      assert -1 =
+               handle_trace.(
+                 {:trace, pid, :return_from, {module, fun, length(args)}, {:noreply, %{}},
+                  return_timestamp},
+                 -1
+               )
+
+      assert [{0, updated_trace}] = :ets.tab2list(table)
+
+      expected_execution_time = :timer.now_diff(return_timestamp, call_timestamp)
+
+      assert %{trace | execution_time: expected_execution_time} == updated_trace
     end
 
     test "handle unexpected trace" do

test/live_debugger/channel_dashboard_test.exs

@@ -16,6 +16,7 @@ defmodule LiveDebugger.ChannelDashboardTest do
     |> assert_has(counter_in_assigns(text: "0"))
     |> assert_has(traces(count: 2))
 
+    # Callback traces appear in debugger
     dev_app
     |> click(button("increment-button"))
     |> click(button("increment-button"))
@@ -46,6 +47,7 @@ defmodule LiveDebugger.ChannelDashboardTest do
     |> assert_has(traces(count: 4))
     |> click(clear_traces_button())
 
+    # Callback traces have proper execution times displayed
     dev_app
     |> click(button("slow-increment-button"))
 
@@ -58,7 +60,6 @@ defmodule LiveDebugger.ChannelDashboardTest do
     execution_time =
       debugger
       |> click(refresh_button())
-      |> take_screenshot()
       |> find(traces(count: 2))
       |> List.last()
       |> find(css("span.text-warning-text"))
@@ -78,6 +79,35 @@ defmodule LiveDebugger.ChannelDashboardTest do
     |> find(traces(count: 4))
     |> Enum.at(1)
     |> assert_has(css("span.text-error-text", text: "2.50 s"))
+
+    # Filtering callback traces by execution time works
+    debugger
+    |> click(toggle_tracing_button())
+    |> click(filters_button())
+    |> fill_in(text_field("exec_time_min"), with: 100)
+    |> fill_in(text_field("exec_time_max"), with: 2_000_000)
+    |> send_keys([:enter])
+    |> find(traces(count: 1))
+    |> find(css("span.text-warning-text"))
+    |> Element.text()
+    |> String.match?(~r"^40\d ms$")
+
+    debugger
+    |> click(toggle_tracing_button())
+
+    dev_app
+    |> click(button("increment-button"))
+    |> click(button("slow-increment-button"))
+
+    Process.sleep(405)
+
+    debugger
+    |> find(traces(count: 2))
+    |> Enum.each(fn trace ->
+      find(trace, css("span.text-warning-text"))
+      |> Element.text()
+      |> String.match?(~r"^40\d ms$")
+    end)
   end
 
   defp first_link(), do: css("#live-sessions a", count: 1)
@@ -95,4 +125,6 @@ defmodule LiveDebugger.ChannelDashboardTest do
   defp toggle_tracing_button(), do: css("button[phx-click=\"switch-tracing\"]")
 
   defp clear_traces_button(), do: css("button[phx-click=\"clear-traces\"]")
+
+  defp filters_button(), do: css("button[phx-click=\"open\"]")
 end