Skip to content

Commit 5c01a38

Browse files
GuzekAlanhhubert6
andauthored
Enhancement: Improve tracing performance (#989) (#990)
* Use :erlang.trace instead of :dbg.tracer * Change :procs flag applying * Update comments * Refactor and add tests * CR suggestions Co-authored-by: Hubert Kasprzycki <67634024+hhubert6@users.noreply.github.com>
1 parent 3e0a54f commit 5c01a38

10 files changed

Lines changed: 233 additions & 74 deletions

File tree

Lines changed: 127 additions & 25 deletions
Original file line numberDiff line numberDiff line change
@@ -1,13 +1,17 @@
11
defmodule LiveDebugger.API.System.Dbg do
22
@moduledoc """
3-
API for interacting with the Erlang's `:dbg` tracing functionalities.
3+
API for interacting with Erlang's tracing functionalities.
4+
5+
The implementation uses `:erlang.trace/3` and `:erlang.trace_pattern/3` BIFs
6+
directly (instead of going through `:dbg`) to reduce per-message overhead in
7+
the tracer.
48
59
## Usage
610
1. If you want to trace callbacks you need to start tracer using `tracer/1` function.
711
Do not start it multiple times, as it will return an error if the tracer is already running.
812
2. Then using `process/1` you can enable tracing for all processes in the system.
913
3. To add a trace pattern for a specific function or module, use `trace_pattern/2`.
10-
If you want to trace more information you can pass `match_spec` created with `flags_to_match_spec/1` function.
14+
If you want to trace more information you can pass `match_spec` created with `flag_to_match_spec/1` function.
1115
"""
1216

1317
@tracing_flags [:return_trace, :exception_trace]
@@ -24,35 +28,42 @@ defmodule LiveDebugger.API.System.Dbg do
2428
@callback stop() :: :ok
2529

2630
@doc """
27-
Starts tracer process and returns its PID.
28-
When tracer is already started, it returns error.
29-
It uses `:dbg.tracer/2` under the hood.
31+
Starts a tracer process and returns its PID.
32+
When a tracer is already started, returns an error.
33+
34+
The tracer is a plain Erlang process that loops on `receive` and calls
35+
the supplied handler for every trace message produced by the BEAM tracing
36+
BIFs. This mirrors what `:dbg.tracer(:process, handler)` did, but without
37+
the `:dbg` server in the middle.
3038
"""
3139
@spec tracer(handler_spec()) :: {:ok, pid()} | {:error, term()}
3240
def tracer(handler_spec), do: impl().tracer(handler_spec)
3341

3442
@doc """
35-
Enables tracing for all processes in the system.
43+
Enables tracing for all processes in the system using `:erlang.trace/3`.
3644
37-
For list of supported flags, see `:dbg.p/2`.
45+
Accepts the same short flag mnemonics as `:dbg.p/2` (e.g. `:c`, `:s`, `:p`)
46+
for compatibility with the existing call sites; they are translated into
47+
the BIF's full flag names internally. Long names (e.g. `:call`, `:timestamp`,
48+
`:procs`) pass through unchanged.
3849
"""
3950
@spec process(flags :: list()) :: {:ok, term()} | {:error, term()}
4051
def process(flags) when is_list(flags) do
4152
impl().process(flags)
4253
end
4354

4455
@doc """
45-
Enables tracing for a specific process.
56+
Enables tracing for a specific process using `:erlang.trace/3`.
4657
"""
4758
@spec process(pid(), flags :: list()) :: {:ok, term()} | {:error, term()}
4859
def process(pid, flags) when is_list(flags) and is_pid(pid) do
4960
impl().process(pid, flags)
5061
end
5162

5263
@doc """
53-
This is a wrapper for `:dbg.tp/2`.
5464
Adds a trace pattern for the specified module or MFA (Module, Function, Arity).
55-
You can create proper `match_spec` by using `flags_to_match_spec/1` function.
65+
This is a wrapper for `:erlang.trace_pattern/3` with `:global` scope.
66+
You can create proper `match_spec` by using `flag_to_match_spec/1` function.
5667
"""
5768
@spec trace_pattern(module() | mfa(), match_spec :: term()) ::
5869
{:ok, term()} | {:error, term()}
@@ -62,24 +73,23 @@ defmodule LiveDebugger.API.System.Dbg do
6273

6374
@doc """
6475
Removes a trace pattern for the specified module or MFA (Module, Function, Arity).
65-
This is a wrapper for `:dbg.ctp/1`.
76+
This is a wrapper for `:erlang.trace_pattern/3` with `false` match spec.
6677
"""
6778
@spec clear_trace_pattern(module() | mfa()) :: {:ok, term()} | {:error, term()}
6879
def clear_trace_pattern(module_or_mfa) do
6980
impl().clear_trace_pattern(module_or_mfa)
7081
end
7182

7283
@doc """
73-
Stops dbg process.
74-
This is a wrapper for `:dbg.stop/0`
84+
Stops the tracer process and clears all active trace flags and patterns.
7585
"""
7686
@spec stop() :: :ok
7787
def stop() do
7888
impl().stop()
7989
end
8090

8191
@doc """
82-
Converts flag to `match_spec` format used by `tp/2` function.
92+
Converts flag to `match_spec` format used by `trace_pattern/2`.
8393
Available flags are: #{Enum.map_join(@tracing_flags, ", ", &"`:#{&1}`")}
8494
"""
8595
@spec flag_to_match_spec(flag :: atom()) :: term()
@@ -99,34 +109,126 @@ defmodule LiveDebugger.API.System.Dbg do
99109
@moduledoc false
100110
@behaviour LiveDebugger.API.System.Dbg
101111

112+
# Registered name of the tracer process. The `process/1,2` calls look it
113+
# up here because `:erlang.trace/3` requires the tracer pid to be passed
114+
# alongside the trace flags.
115+
@tracer_name :live_debugger_tracer
116+
117+
# Translation table for the short flag mnemonics historically accepted by
118+
# `:dbg.p/2`. Long names pass through unchanged via the default branch in
119+
# `translate_flag/1`.
120+
@flag_translation %{
121+
s: :send,
122+
r: :receive,
123+
m: :messages,
124+
c: :call,
125+
p: :procs,
126+
sos: :set_on_spawn,
127+
sol: :set_on_link,
128+
sofs: :set_on_first_spawn,
129+
sofl: :set_on_first_link
130+
}
131+
102132
@impl true
103-
def tracer(handler) do
104-
:dbg.tracer(:process, handler)
133+
def tracer({handler_fun, initial_data})
134+
when is_function(handler_fun, 2) do
135+
pid = spawn(fn -> loop(handler_fun, initial_data) end)
136+
137+
try do
138+
Process.register(pid, @tracer_name)
139+
{:ok, pid}
140+
rescue
141+
ArgumentError ->
142+
Process.exit(pid, :kill)
143+
{:error, :already_started}
144+
end
105145
end
106146

107147
@impl true
108-
def process(flags) do
109-
:dbg.p(:all, flags)
110-
end
148+
def process(flags), do: do_process(:all, flags)
111149

112150
@impl true
113-
def process(pid, flags) do
114-
:dbg.p(pid, flags)
115-
end
151+
def process(pid, flags), do: do_process(pid, flags)
116152

117153
@impl true
118154
def trace_pattern(pattern, match_spec) do
119-
:dbg.tp(pattern, match_spec)
155+
result = :erlang.trace_pattern(normalize_pattern(pattern), match_spec, [])
156+
{:ok, result}
157+
catch
158+
kind, reason -> {:error, {kind, reason}}
120159
end
121160

122161
@impl true
123162
def clear_trace_pattern(pattern) do
124-
:dbg.ctp(pattern)
163+
result = :erlang.trace_pattern(normalize_pattern(pattern), false, [])
164+
{:ok, result}
165+
catch
166+
kind, reason -> {:error, {kind, reason}}
125167
end
126168

127169
@impl true
128170
def stop() do
129-
:dbg.stop()
171+
safe(fn -> :erlang.trace(:all, false, [:all]) end)
172+
safe(fn -> :erlang.trace_pattern({:_, :_, :_}, false, []) end)
173+
174+
case Process.whereis(@tracer_name) do
175+
nil ->
176+
:ok
177+
178+
pid ->
179+
ref = Process.monitor(pid)
180+
send(pid, :stop)
181+
182+
receive do
183+
{:DOWN, ^ref, _, _, _} -> :ok
184+
after
185+
1_000 ->
186+
Process.exit(pid, :kill)
187+
:ok
188+
end
189+
end
190+
end
191+
192+
# Tracer process loop. Receives raw trace tuples from the BEAM and
193+
# dispatches them to the user-provided handler, threading state through
194+
# each call. A `:stop` message terminates the loop with reason `:done`.
195+
defp loop(handler_fun, data) do
196+
receive do
197+
:stop ->
198+
exit(:done)
199+
200+
msg ->
201+
new_data = handler_fun.(msg, data)
202+
loop(handler_fun, new_data)
203+
end
204+
end
205+
206+
defp do_process(target, flags) do
207+
case Process.whereis(@tracer_name) do
208+
nil ->
209+
{:error, :tracer_not_started}
210+
211+
tracer ->
212+
result =
213+
:erlang.trace(target, true, [{:tracer, tracer} | translate_flags(flags)])
214+
215+
{:ok, result}
216+
end
217+
catch
218+
kind, reason -> {:error, {kind, reason}}
219+
end
220+
221+
defp normalize_pattern({_mod, _fun, _arity} = mfa), do: mfa
222+
defp normalize_pattern(module) when is_atom(module), do: {module, :_, :_}
223+
224+
defp translate_flags(flags), do: Enum.map(flags, &translate_flag/1)
225+
defp translate_flag(flag), do: Map.get(@flag_translation, flag, flag)
226+
227+
defp safe(fun) do
228+
fun.()
229+
:ok
230+
catch
231+
_, _ -> :ok
130232
end
131233
end
132234
end
Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
## CallbackTracer
22

3-
This service is responsible for setting up `:dbg.tracer`, monitoring and managing it, parsing raw traces and finally sending them to the bus.
3+
This service is responsible for setting up the tracer process, monitoring and managing it, parsing raw traces and finally sending them to the bus.
44

55
### Overview
66

7-
The CallbackTracer initializes `:dbg.tracer` to collect callback-related data. It continuously monitors the tracer for errors and exceptions. Trace data sent from the tracer is received by a GenServer within the service, which then analyzes and persists this data before broadcasting it to the event bus. The service also adapts tracer configurations in response to system changes like module recompilations to maintain accurate and relevant data collection.
7+
The CallbackTracer starts a dedicated tracer process (via `:erlang.trace/3` / `:erlang.trace_pattern/3`) to collect callback-related data. It continuously monitors the tracer for errors and exceptions. Trace data sent from the tracer is received by a GenServer within the service, which then analyzes and persists this data before broadcasting it to the event bus. The service also adapts tracer configurations in response to system changes like module recompilations to maintain accurate and relevant data collection.

lib/live_debugger/services/callback_tracer/actions/tracing.ex

Lines changed: 24 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -24,35 +24,32 @@ defmodule LiveDebugger.Services.CallbackTracer.Actions.Tracing do
2424
def setup_tracing_with_monitoring!(state) do
2525
last_id = TraceQueries.get_last_trace_id()
2626

27-
if Map.get(state, :dbg_pid) do
28-
Dbg.stop()
29-
end
30-
31-
case Dbg.tracer({&Tracer.handle_trace/2, {:init, last_id - 1}}) do
32-
{:ok, pid} ->
33-
Process.monitor(pid)
27+
Dbg.stop()
3428

35-
Dbg.process([:c, :timestamp, :procs])
29+
with {:ok, pid} <- Dbg.tracer({&Tracer.handle_trace/2, {:init, last_id - 1}}),
30+
{:ok, _} <- Dbg.process([:c, :timestamp]) do
31+
Process.monitor(pid)
3632

37-
# Fetch all live modules once with paths for both operations
38-
live_modules_with_paths = CallbackQueries.all_live_modules_with_paths()
33+
# Fetch all live modules once with paths for both operations
34+
live_modules_with_paths = CallbackQueries.all_live_modules_with_paths()
3935

40-
# Extract just the module names for callback queries
41-
module_names = Enum.map(live_modules_with_paths, fn {module, _path} -> module end)
36+
# Extract just the module names for callback queries
37+
module_names = Enum.map(live_modules_with_paths, fn {module, _path} -> module end)
4238

43-
# Apply trace patterns using the fetched modules
44-
apply_trace_patterns(module_names)
39+
# Apply trace patterns using the fetched modules
40+
apply_trace_patterns(module_names)
4541

46-
# Monitor recompilation using the paths
47-
start_file_monitoring(live_modules_with_paths)
42+
# Monitor recompilation using the paths
43+
start_file_monitoring(live_modules_with_paths)
4844

49-
# Broadcast information
50-
Bus.broadcast_event!(%DbgStarted{})
51-
52-
%{state | dbg_pid: pid}
45+
# Broadcast information
46+
Bus.broadcast_event!(%DbgStarted{})
5347

48+
%{state | dbg_pid: pid}
49+
else
5450
{:error, error} ->
55-
raise "Couldn't start tracer: #{inspect(error)}"
51+
Logger.error("Couldn't start tracer: #{inspect(error)}")
52+
state
5653
end
5754
end
5855

@@ -71,9 +68,13 @@ defmodule LiveDebugger.Services.CallbackTracer.Actions.Tracing do
7168

7269
@spec start_outgoing_messages_tracing(pid()) :: :ok
7370
def start_outgoing_messages_tracing(pid) do
74-
Dbg.process(pid, [:s])
71+
case Dbg.process(pid, [:s, :procs]) do
72+
{:ok, _} ->
73+
:ok
7574

76-
:ok
75+
{:error, error} ->
76+
Logger.error("Couldn't enable send tracing for #{inspect(pid)}: #{inspect(error)}")
77+
end
7778
end
7879

7980
defp refresh_tracing_for_module(module) do

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,7 @@ defmodule LiveDebugger.Services.CallbackTracer.GenServers.TraceHandler do
4646
end
4747

4848
@doc """
49-
Handles trace from `:dbg.tracer` process.
49+
Handles trace from the tracer process started via `LiveDebugger.API.System.Dbg`.
5050
"""
5151
@spec handle_trace(trace :: term(), n :: integer()) :: :ok
5252
def handle_trace(trace, n) do
@@ -146,7 +146,7 @@ defmodule LiveDebugger.Services.CallbackTracer.GenServers.TraceHandler do
146146
#########################################################
147147
# Handling diffs tracing
148148
#
149-
# Use :dbg.p(channel_pid, [:s]) to activate
149+
# Activated via `Dbg.process(channel_pid, [:s])` from `TracingActions`.
150150
#########################################################
151151

152152
def handle_cast({:new_trace, {_, pid, :send, {:socket_push, :text, iodata}, _, ts}, n}, state) do

lib/live_debugger/services/callback_tracer/gen_servers/tracing_manager.ex

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -81,8 +81,7 @@ defmodule LiveDebugger.Services.CallbackTracer.GenServers.TracingManager do
8181
end
8282

8383
# Handling tracer process stop or crash.
84-
# All exit messages are trapped and sent with `:done` reason.
85-
def handle_info({:DOWN, _, _, pid, :done}, %{dbg_pid: pid} = state) do
84+
def handle_info({:DOWN, _, _, pid, _reason}, %{dbg_pid: pid} = state) do
8685
Bus.broadcast_event!(%DbgKilled{})
8786

8887
{:noreply, %{state | dbg_pid: nil}}

lib/live_debugger/services/callback_tracer/process/tracer.ex

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
defmodule LiveDebugger.Services.CallbackTracer.Process.Tracer do
22
@moduledoc """
3-
This module defines a function that is used in the `:dbg.tracer` process.
3+
This module defines a function that is used as the handler in the tracer process
4+
started by `LiveDebugger.API.System.Dbg.tracer/1`.
45
"""
56

67
alias LiveDebugger.Services.CallbackTracer.GenServers.TraceHandler
@@ -10,7 +11,8 @@ defmodule LiveDebugger.Services.CallbackTracer.Process.Tracer do
1011

1112
@spec handle_trace(trace :: term(), state :: integer() | {:init, integer()}) :: integer()
1213
def handle_trace(trace, {:init, n}) do
13-
# Maximum heap size is set inside `:dbg.tracer` process to prevent it from consuming too much memory.
14+
# Set on first invocation so the limit applies to the tracer process itself
15+
# (which is the one receiving every BEAM trace message).
1416
Memory.set_max_heap_size(@max_heap_size)
1517

1618
do_handle_trace(trace, n)

lib/live_debugger/structs/trace.ex

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@ defmodule LiveDebugger.Structs.Trace do
66
- DiffTrace - represents a diff trace (HTML diff generated by LiveView/LiveComponent sent to the client).
77
88
Each trace has:
9-
- id - unique id of the trace which is generated by :dbg tracer.
9+
- id - unique id of the trace, generated by the tracer process.
1010
- pid - pid of the LiveView that generated the trace.
1111
- timestamp - timestamp of the trace.
1212
"""

0 commit comments

Comments
 (0)