Skip to content

Commit 7017d16

Browse files
christhekeelechristhekeele
committed
WIP tracing
1 parent 97458dc commit 7017d16

File tree

6 files changed

+210
-79
lines changed

6 files changed

+210
-79
lines changed

‎lib/matcha/application.ex‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,8 @@ defmodule Matcha.Application do
77
def start(_type, _args) do
88
[
99
{Matcha.Trace.Supervisor, name: Matcha.Trace.Tracer.Supervisor},
10-
{Matcha.Trace.Supervisor, name: Matcha.Trace.Handler.Supervisor}
10+
{Matcha.Trace.Supervisor, name: Matcha.Trace.Handler.Supervisor},
11+
{Matcha.Trace.Supervisor, name: Matcha.Trace.Worker.Supervisor}
1112
]
1213
|> Supervisor.start_link(strategy: :one_for_one, name: Matcha.Supervisor)
1314
end

‎lib/matcha/trace.ex‎

Lines changed: 14 additions & 62 deletions
Original file line numberDiff line numberDiff line change
@@ -37,13 +37,6 @@ defmodule Matcha.Trace do
3737
handler: @default_handler
3838
]
3939

40-
@type t :: %__MODULE__{
41-
topic: Trace.Calls.t(),
42-
limit: limit(),
43-
pids: pid_spec(),
44-
handler: (tuple() -> term())
45-
}
46-
4740
@type limit :: limit_calls() | limit_rate()
4841
@type limit_calls :: non_neg_integer()
4942
@type limit_rate :: {limit_calls(), milliseconds :: non_neg_integer()}
@@ -65,6 +58,14 @@ defmodule Matcha.Trace do
6558
| {:trace, pid(), :call,
6659
{module :: atom, function :: atom(), arguments :: integer() | term(), binary()}}
6760

61+
62+
@type t :: %__MODULE__{
63+
topic: Trace.Calls.t(),
64+
limit: limit(),
65+
pids: pid_spec(),
66+
handler: (Matcha.Trace.Handler.t(), message() -> term())
67+
}
68+
6869
@spec start(Trace.t(), keyword()) :: Trace.Supervisor.on_start_child()
6970
@doc """
7071
Starts the provided `trace`.
@@ -87,6 +88,7 @@ defmodule Matcha.Trace do
8788

8889
@spec options(keyword()) ::
8990
{[{:handler, any()} | {:limit, any()} | {:pids, any()}, ...], keyword()}
91+
@doc false
9092
def options(options) do
9193
{pids, options} = Keyword.pop(options, :pids, @default_trace_pids)
9294
{limit, options} = Keyword.pop(options, :limit, @default_trace_limit)
@@ -97,7 +99,7 @@ defmodule Matcha.Trace do
9799

98100
@spec new(Trace.Topic.t(), keyword()) :: t()
99101
@doc """
100-
Builds a new trace.
102+
Builds a new trace from a given `topic`.
101103
"""
102104
def new(topic, options \\ []) do
103105
{options, extra_options} = options(options)
@@ -200,8 +202,11 @@ defmodule Matcha.Trace do
200202
This function is best used when shutting down processes (or the current node),
201203
to give them a chance to finish any tracing they are handling.
202204
205+
Works by wrapping `:erlang.trace_delivered/1` in a `receive` block
206+
that blocks the current process with the provided `timeout`.
207+
203208
"""
204-
def awaiting_messages?(pid \\ :all, timeout \\ 5000) do
209+
def awaiting_messages?(pid \\ :all, timeout \\ 5_000) do
205210
ref = request_confirmation_all_messages_delivered(pid)
206211

207212
receive do
@@ -278,59 +283,6 @@ defmodule Matcha.Trace do
278283
:erlang.trace_info(pid_port_func_event, item)
279284
end
280285

281-
@doc """
282-
Formats a trace message.
283-
"""
284-
def format_message(message)
285-
286-
def format_message({:trace, pid, :call, {module, function, arguments}}) do
287-
call = format_call(module, function, arguments, pid)
288-
289-
"Matcha.Trace: #{call}\n"
290-
end
291-
292-
def format_message({:trace, pid, :call, {module, function, arguments}, message}) do
293-
call = format_call(module, function, arguments, pid, message)
294-
295-
"Matcha.Trace:#{call}\n"
296-
end
297-
298-
def format_message(term) do
299-
"Matcha.Trace: unrecognized trace message\n```\n#{inspect(term)}\n```\n"
300-
end
301-
302-
defp format_call(module, function, arguments, pid, message \\ nil)
303-
304-
defp format_call(module, function, arguments, pid, message) when is_list(arguments) do
305-
arity = length(arguments)
306-
call = call_to_string(module, function, arity)
307-
308-
" traced call `#{call}`" <>
309-
"\n on pid: #{inspect(pid)}" <>
310-
if message do
311-
"\n with message: #{message}"
312-
else
313-
""
314-
end <>
315-
"\n with arguments:\n```\n#{inspect(arguments)}\n```"
316-
end
317-
318-
defp format_call(module, function, arity, pid, message) when is_integer(arity) do
319-
call = call_to_string(module, function, arity)
320-
321-
"\n traced call `#{call}`" <>
322-
"\n on pid: #{inspect(pid)}" <>
323-
if message do
324-
"\n with message: #{message}"
325-
else
326-
""
327-
end
328-
end
329-
330-
defp call_to_string(module, function, arity) when is_integer(arity) do
331-
Macro.to_string(quote(do: &(unquote(module).unquote(function) / unquote(arity))))
332-
end
333-
334286
@doc """
335287
Stops all tracing at once, system-wide.
336288
"""

‎lib/matcha/trace/handler.ex‎

Lines changed: 92 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -3,25 +3,33 @@ defmodule Matcha.Trace.Handler do
33
About trace handlers.
44
"""
55

6+
@default_width 120
7+
68
alias Matcha.Trace
79

10+
import Inspect.Algebra
11+
812
use GenServer
913

10-
defstruct [:trace, :caller, :io_device]
14+
defstruct [:trace, :caller, :io_device, :width, :worker_supervisor]
1115

1216
@type t :: %__MODULE__{
1317
trace: Trace.t(),
1418
caller: pid() | nil,
15-
io_device: IO.device()
19+
io_device: IO.device(),
20+
width: non_neg_integer() | :infinity,
21+
worker_supervisor: pid()
1622
}
1723

1824
def options(options \\ []) do
1925
{caller, options} = Keyword.pop(options, :caller, self())
2026
{io_device, options} = Keyword.pop(options, :io_device, Process.group_leader())
27+
{width, options} = Keyword.pop(options, :width, @default_width)
2128

2229
{[
2330
caller: caller,
24-
io_device: io_device
31+
io_device: io_device,
32+
width: width
2533
], options}
2634
end
2735

@@ -86,6 +94,9 @@ defmodule Matcha.Trace.Handler do
8694
Process.link(handler.caller)
8795
end
8896

97+
{:ok, worker_supervisor} = Trace.Supervisor.start_worker_supervisor(handler, [])
98+
handler = %__MODULE__{handler | worker_supervisor: worker_supervisor}
99+
89100
{:ok, handler}
90101
end
91102

@@ -102,20 +113,87 @@ defmodule Matcha.Trace.Handler do
102113
@impl true
103114
def handle_cast(message, handler)
104115

105-
# Invoke user-defined handler function when available
106-
def handle_cast(
107-
{:__matcha_trace__, message},
108-
handler = %__MODULE__{trace: %Trace{handler: fun}}
109-
)
110-
when not is_nil(fun) do
111-
fun.(handler, message)
116+
def handle_cast({:__matcha_trace__, message}, handler = %__MODULE__{trace: %Trace{handler: custom_handler}}) do
117+
worker = if custom_handler do
118+
fn ->
119+
custom_handler.(handler, message)
120+
end
121+
else
122+
fn ->
123+
IO.puts(handler.io_device, format_message(handler, message))
124+
end
125+
end
126+
127+
Task.Supervisor.start_child(handler.worker_supervisor, worker)
128+
112129
{:noreply, handler}
113130
end
114131

115-
# Otherwise, by default write back to IO device
116-
def handle_cast({:__matcha_trace__, message}, handler = %__MODULE__{}) do
117-
IO.puts(handler.io_device, Trace.format_message(message))
132+
@spec format_message(%__MODULE__{}, Trace.message()) :: iodata()
133+
@doc """
134+
Formats a trace message.
135+
"""
136+
def format_message(handler, message)
118137

119-
{:noreply, handler}
138+
def format_message(handler, {:trace, pid, :call, {module, function, arguments}}) do
139+
call = format_call(module, function, arguments, pid)
140+
141+
"Matcha.Trace:"
142+
|> Inspect.Algebra.glue(call)
143+
|> Inspect.Algebra.nest(2)
144+
|> Inspect.Algebra.format(handler.width)
145+
end
146+
147+
def format_message(handler, {:trace, pid, :call, {module, function, arguments}, message}) do
148+
call = format_call(module, function, arguments, pid, message)
149+
150+
"Matcha.Trace:"
151+
|> Inspect.Algebra.glue(call)
152+
|> Inspect.Algebra.nest(2)
153+
|> Inspect.Algebra.format(handler.width)
154+
end
155+
156+
def format_message(handler, term) do
157+
# "Matcha.Trace:"
158+
# |> Inspect.Algebra.glue("unrecognized trace message:")
159+
# # |> Inspect.Algebra.
160+
# |> Inspect.Algebra.nest(2)
161+
"Matcha.Trace: unrecognized trace message\n```\n#{inspect(term)}\n```\n"
162+
end
163+
164+
defp format_call(module, function, arguments, pid, message \\ nil)
165+
166+
defp format_call(module, function, arguments, pid, message) when is_list(arguments) do
167+
arity = length(arguments)
168+
call = call_to_string(module, function, arity)
169+
170+
" traced call `#{call}`" <>
171+
"\n on pid: #{inspect(pid)}" <>
172+
if message do
173+
"\n with message: #{message}"
174+
else
175+
""
176+
end <>
177+
"\n with arguments:\n```\n#{inspect(arguments)}\n```"
178+
end
179+
180+
defp format_call(module, function, arity, pid, message) when is_integer(arity) do
181+
call = call_to_string(module, function, arity)
182+
183+
"\n traced call `#{call}`" <>
184+
"\n on pid: #{inspect(pid)}" <>
185+
if message do
186+
"\n with message: #{message}"
187+
else
188+
""
189+
end
190+
end
191+
192+
defp format_arguments(arguments) do
193+
194+
end
195+
196+
defp call_to_string(module, function, arity) when is_integer(arity) do
197+
Macro.to_string(quote(do: &(unquote(module).unquote(function) / unquote(arity))))
120198
end
121199
end

‎lib/matcha/trace/supervisor.ex‎

Lines changed: 21 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -70,4 +70,25 @@ defmodule Matcha.Trace.Supervisor do
7070
)
7171
end
7272
end
73+
74+
@spec start_worker_supervisor(Trace.Handler.t(), keyword()) :: on_start_child()
75+
def start_worker_supervisor(handler = %Trace.Handler{}, options \\ []) do
76+
if options != [] do
77+
problems =
78+
for option <- options do
79+
{:error,
80+
"unexpected option `#{inspect(option)}` provided to `#{inspect(__MODULE__)}.start_worker_supervisor/2`"}
81+
end
82+
83+
raise Trace.Error,
84+
source: handler.trace,
85+
details: "when starting worker supervisor",
86+
problems: problems
87+
else
88+
DynamicSupervisor.start_child(
89+
{:via, PartitionSupervisor, {Matcha.Trace.Worker.Supervisor, handler.caller || self()}},
90+
Task.Supervisor
91+
)
92+
end
93+
end
7394
end

‎lib/matcha/trace/tracer.ex‎

Lines changed: 51 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,56 @@
11
defmodule Matcha.Trace.Tracer do
22
@moduledoc """
33
About trace tracers.
4+
5+
```mermaid
6+
sequenceDiagram
7+
8+
participant erlang as Erlang Trace Engine
9+
participant Process
10+
participant Trace as Matcha.Trace
11+
12+
Note over Process: Matcha.Trace.module(Integer)
13+
Process ->> Trace: Trace.start
14+
create participant Tracer as Matcha.Trace.Tracer
15+
Trace -->> Tracer: Tracer.Supervisor.start
16+
create participant Handler as Matcha.Trace.Handler
17+
Tracer -->> Handler: Handler.Supervisor.start
18+
create participant WorkerSupervisor as Matcha.Trace.WorkerSupervisor
19+
Handler -->> WorkerSupervisor: Task.Supervisor.start
20+
WorkerSupervisor -->> Handler: :ok
21+
Handler -->> Tracer: :ok
22+
Tracer ->> erlang: :erlang.trace(module: Integer, handler: Handler)
23+
Tracer -->> Trace: :ok
24+
Trace -->> Process: :ok
25+
26+
Note over Process: Integer.parse("3")
27+
erlang ->> Tracer: GenServer.cast({:traced, :call, {Integer, :parse, ["3"]}})
28+
Tracer ->> Handler: cast({:traced, :call, {Integer, :parse, ["3"]}})
29+
Handler -->> WorkerSupervisor: Task.Supervisor.start_child
30+
create participant Worker
31+
WorkerSupervisor -->> Worker: Task.start
32+
Handler ->> Worker: Worker.handle({:traced, :call, {Integer, :parse, ["3"]}})
33+
Worker ->> Worker: format_message()
34+
destroy Worker
35+
Worker --x Process: IO.puts
36+
Note over Process: Traced call:<br />`&Integer.parse/1`<br />with arguments:<br />`["3"]`
37+
38+
Note over Tracer: Limit reached
39+
Tracer -->> Handler: terminate
40+
Handler -->> WorkerSupervisor: terminate
41+
destroy WorkerSupervisor
42+
WorkerSupervisor -->> Handler: :ok
43+
destroy Handler
44+
Handler -->> Tracer: :ok
45+
Tracer -->> Tracer: terminate
46+
destroy Tracer
47+
Tracer -->> Tracer: :ok
48+
49+
Note over Process: Integer.parse("5")
50+
erlang ->> Tracer: GenServer.cast({:traced, :call, {Integer, :parse, ["3"]}})
51+
Note over Tracer: Tracing stopped
52+
```
53+
454
"""
555

656
alias Matcha.Trace
@@ -13,7 +63,7 @@ defmodule Matcha.Trace.Tracer do
1363
trace: Trace.t(),
1464
caller: pid() | nil,
1565
io_device: IO.device(),
16-
handler: (Trace.Handler.t(), Trace.message() -> any()) | nil
66+
handler: pid()
1767
}
1868

1969
def options(options \\ []) do

0 commit comments

Comments
 (0)