defmodule Untangle.Time do
@moduledoc """
Provides timing utilities for measuring function execution time.
This module offers decorators for measuring and logging the execution time of functions:
- `time()`: Basic measurement of single function calls
- `time_process()`: Tracks count and total time across multiple calls
- `time_tree()`: Captures timing across process trees
"""
use Decorator.Define,
time: 0,
time_process: 0,
time_tree: 0,
time: 1,
time_process: 1,
time_tree: 1
require Logger
# Check at compile time if ProcessTree is available
@disable? !Untangle.log_level?(:debug)
@process_tree_available Code.ensure_loaded?(ProcessTree)
@doc """
Decorator that measures and logs execution time of functions.
When applied to a function, this decorator will:
- Measure the function's execution time if the logger level is set to `:debug`
- Log the execution time if it exceeds a configured threshold (default: 10,000 microseconds)
- Return the function's result unchanged
## Configuration
The minimum time threshold for logging can be configured in your application:
```elixir
config :untangle, :time_slow_min, 10_000 # microseconds
```
## Examples
defmodule Demo do
use Untangle.Time
@decorate time()
def slow_function(ms) do
Process.sleep(ms)
:ok
end
end
"""
def time(slow_ms \\ nil, fn_body, context) do
# At compile time, check if we're in debug environment
if @disable? do
# Not in debug mode at compile time, just return original function
quote do
unquote(fn_body)
end
else
# In debug mode or can't determine at compile time, include runtime check
quote do
if Untangle.log_level?(:debug) do
start = :erlang.monotonic_time()
result = unquote(fn_body)
finish = :erlang.monotonic_time()
time = :erlang.convert_time_unit(finish - start, :native, :microsecond)
if time > (unquote(slow_ms) || Application.get_env(:untangle, :time_slow_min, 10_000)) do
Logger.debug(
"#{time / 1_000} ms to run #{unquote(context.module)}.#{unquote(context.name)}/#{unquote(context.arity)}"
)
end
result
else
unquote(fn_body)
end
end
end
end
@doc """
Decorator that aggregates execution counts and times across multiple calls.
When applied to a function, this decorator will:
- Track each call in the process dictionary
- Count the number of executions
- Sum total execution time
- Log detailed statistics when execution time exceeds threshold
- Return the function's result unchanged
## Examples
defmodule Demo do
use Untangle.Time
@decorate time_process()
def repeated_function(ms) do
Process.sleep(ms)
:ok
end
end
After multiple calls, logs will include call count and total time.
"""
def time_process(slow_ms \\ nil, fn_body, context) do
# At compile time, check if we're in debug environment
if @disable? do
# Not in debug mode at compile time, just return original function
quote do
unquote(fn_body)
end
else
function_key = "#{context.module}.#{context.name}/#{context.arity}"
quote do
if Untangle.log_level?(:debug) do
# Get current stats or initialize
previous_data =
Process.get({:untangle_time_process, unquote(Macro.escape(function_key))}, %{
count: 0,
time: 0
})
# Measure this execution
start = :erlang.monotonic_time()
result = unquote(fn_body)
finish = :erlang.monotonic_time()
time = :erlang.convert_time_unit(finish - start, :native, :microsecond)
# Update accumulated data with this process's information
current_data = %{
count: previous_data.count + 1,
time: previous_data.time + time
}
if time > (unquote(slow_ms) || Application.get_env(:untangle, :time_slow_min, 10_000)) do
Logger.debug(
"#{time / 1_000} ms to run #{unquote(Macro.escape(function_key))} " <>
"(call ##{current_data.count}, total: #{current_data.time / 1_000} ms, avg: #{current_data.time / current_data.count / 1_000} ms)"
)
end
# Store updated data
Process.put({:untangle_time_process, unquote(Macro.escape(function_key))}, current_data)
result
else
unquote(fn_body)
end
end
end
end
@doc """
Decorator that measures execution time across a process tree.
When applied to a function, this decorator will:
- Track execution time of the function in the current process and all processes it spawns
- Log detailed timing statistics when execution completes
- Return the function's result unchanged
Requires the [ProcessTree](https://www.hex.pm/packages/process_tree) library to be added to your app's dependencies.
## Examples
defmodule Demo do
use Untangle.Time
@decorate time_tree()
def spawn_function(depth \\ 1) do
Process.sleep(50)
if depth < 3 do
Task.async(fn ->
Demo.spawn_function(depth + 1)
end)
|> Task.await()
end
:ok
end
end
"""
def time_tree(slow_ms \\ nil, fn_body, context) do
# At compile time, check if we're in debug mode and ProcessTree is available
cond do
@disable? ->
# Not in debug mode at compile time, just return original function
quote do
unquote(fn_body)
end
not @process_tree_available ->
# ProcessTree not available at compile time, fall back to time_process
time_process(fn_body, context)
true ->
# Both debug mode possible and ProcessTree available, include runtime check
function_key = "#{context.module}.#{context.name}/#{context.arity}"
quote do
if Untangle.log_level?(:debug) do
# Get accumulated time from parent processes, if any
parent_data =
ProcessTree.get({:untangle_time_tree, unquote(Macro.escape(function_key))},
cache: false,
default: %{count: 0, time: 0}
)
# TODO: at the moment this will only return the execution times from the current process or the first parent process that has recorded data, rather than the sum of the data from all parents
# Execute function while tracking time
start = :erlang.monotonic_time()
result = unquote(fn_body)
finish = :erlang.monotonic_time()
# Calculate this process's execution time
time = :erlang.convert_time_unit(finish - start, :native, :microsecond)
# Update accumulated data with this process's information
current_data = %{
count: parent_data.count + 1,
time: parent_data.time + time
}
# Log results including parent process data
if time > (unquote(slow_ms) || Application.get_env(:untangle, :time_slow_min, 10_000)) do
if parent_data.count > 0 do
# Include parent process information if available
Logger.debug(
"#{time / 1_000} ms to run #{unquote(Macro.escape(function_key))} " <>
"(#{current_data.count} executions in process tree, total time: #{current_data.time / 1_000} ms, avg: #{current_data.time / current_data.count / 1_000} ms)"
)
else
# Just log this process's information
Logger.debug("#{time / 1_000} ms to run #{unquote(Macro.escape(function_key))}")
end
end
# Store this data in process dictionary for child processes
Process.put({:untangle_time_tree, unquote(Macro.escape(function_key))}, current_data)
result
else
unquote(fn_body)
end
end
end
end
def disabled?, do: @disable?
end
