756 lines
27 KiB
Erlang
756 lines
27 KiB
Erlang
%%%----------------------------------------------------------------------
|
|
%%% File : ejabberd_hooks.erl
|
|
%%% Author : Alexey Shchepin <alexey@process-one.net>
|
|
%%% Purpose : Manage hooks
|
|
%%% Created : 8 Aug 2004 by Alexey Shchepin <alexey@process-one.net>
|
|
%%%
|
|
%%%
|
|
%%% ejabberd, Copyright (C) 2002-2022 ProcessOne
|
|
%%%
|
|
%%% This program is free software; you can redistribute it and/or
|
|
%%% modify it under the terms of the GNU General Public License as
|
|
%%% published by the Free Software Foundation; either version 2 of the
|
|
%%% License, or (at your option) any later version.
|
|
%%%
|
|
%%% This program is distributed in the hope that it will be useful,
|
|
%%% but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
%%% MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
|
|
%%% General Public License for more details.
|
|
%%%
|
|
%%% You should have received a copy of the GNU General Public License along
|
|
%%% with this program; if not, write to the Free Software Foundation, Inc.,
|
|
%%% 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
|
|
%%%
|
|
%%%----------------------------------------------------------------------
|
|
-module(ejabberd_hooks).
|
|
-author('alexey@process-one.net').
|
|
-behaviour(gen_server).
|
|
|
|
%% External exports
|
|
-export([start_link/0,
|
|
add/3,
|
|
add/4,
|
|
add/5,
|
|
delete/3,
|
|
delete/4,
|
|
delete/5,
|
|
run/2,
|
|
run/3,
|
|
run_fold/3,
|
|
run_fold/4]).
|
|
%% gen_server callbacks
|
|
-export([init/1,
|
|
handle_call/3,
|
|
handle_cast/2,
|
|
code_change/3,
|
|
handle_info/2,
|
|
terminate/2]).
|
|
|
|
|
|
-export(
|
|
[
|
|
get_tracing_options/3,
|
|
trace_off/3,
|
|
trace_on/5,human_readable_time_string/1
|
|
]
|
|
).
|
|
|
|
-include("logger.hrl").
|
|
-include("ejabberd_stacktrace.hrl").
|
|
|
|
-record(state, {}).
|
|
-type hook() :: {Seq :: integer(), Module :: atom(), Function :: atom() | fun()}.
|
|
|
|
-define(TRACE_HOOK_KEY, '$trace_hook').
|
|
-define(TIMING_KEY, '$trace_hook_timer').
|
|
%%%----------------------------------------------------------------------
|
|
%%% API
|
|
%%%----------------------------------------------------------------------
|
|
start_link() ->
|
|
gen_server:start_link({local, ?MODULE}, ?MODULE, [], []).
|
|
|
|
-spec add(atom(), fun(), integer()) -> ok.
|
|
%% @doc See add/4.
|
|
add(Hook, Function, Seq) when is_function(Function) ->
|
|
add(Hook, global, undefined, Function, Seq).
|
|
|
|
-spec add(atom(), HostOrModule :: binary() | atom(), fun() | atom() , integer()) -> ok.
|
|
add(Hook, Host, Function, Seq) when is_function(Function) ->
|
|
add(Hook, Host, undefined, Function, Seq);
|
|
|
|
%% @doc Add a module and function to this hook.
|
|
%% The integer sequence is used to sort the calls: low number is called before high number.
|
|
add(Hook, Module, Function, Seq) ->
|
|
add(Hook, global, Module, Function, Seq).
|
|
|
|
-spec add(atom(), binary() | global, atom(), atom() | fun(), integer()) -> ok.
|
|
add(Hook, Host, Module, Function, Seq) ->
|
|
gen_server:call(?MODULE, {add, Hook, Host, Module, Function, Seq}).
|
|
|
|
-spec delete(atom(), fun(), integer()) -> ok.
|
|
%% @doc See del/4.
|
|
delete(Hook, Function, Seq) when is_function(Function) ->
|
|
delete(Hook, global, undefined, Function, Seq).
|
|
|
|
-spec delete(atom(), binary() | atom(), atom() | fun(), integer()) -> ok.
|
|
delete(Hook, Host, Function, Seq) when is_function(Function) ->
|
|
delete(Hook, Host, undefined, Function, Seq);
|
|
|
|
%% @doc Delete a module and function from this hook.
|
|
%% It is important to indicate exactly the same information than when the call was added.
|
|
delete(Hook, Module, Function, Seq) ->
|
|
delete(Hook, global, Module, Function, Seq).
|
|
|
|
-spec delete(atom(), binary() | global, atom(), atom() | fun(), integer()) -> ok.
|
|
delete(Hook, Host, Module, Function, Seq) ->
|
|
gen_server:call(?MODULE, {delete, Hook, Host, Module, Function, Seq}).
|
|
|
|
-spec run(atom(), list()) -> ok.
|
|
%% @doc Run the calls of this hook in order, don't care about function results.
|
|
%% If a call returns stop, no more calls are performed.
|
|
run(Hook, Args) ->
|
|
run(Hook, global, Args).
|
|
|
|
-spec run(atom(), binary() | global, list()) -> ok.
|
|
run(Hook, Host, Args) ->
|
|
try ets:lookup(hooks, {Hook, Host}) of
|
|
[{_, Ls}] ->
|
|
case erlang:get(?TRACE_HOOK_KEY) of
|
|
undefined ->
|
|
run1(Ls, Hook, Args);
|
|
TracingHooksOpts ->
|
|
case do_get_tracing_options(Hook, Host, TracingHooksOpts) of
|
|
undefined ->
|
|
run1(Ls, Hook, Args);
|
|
TracingOpts ->
|
|
foreach_start_hook_tracing(TracingOpts, Hook, Host, Args),
|
|
run2(Ls, Hook, Args, Host, TracingOpts)
|
|
end
|
|
end;
|
|
[] ->
|
|
ok
|
|
catch _:badarg ->
|
|
ok
|
|
end.
|
|
|
|
-spec run_fold(atom(), T, list()) -> T.
|
|
%% @doc Run the calls of this hook in order.
|
|
%% The arguments passed to the function are: [Val | Args].
|
|
%% The result of a call is used as Val for the next call.
|
|
%% If a call returns 'stop', no more calls are performed.
|
|
%% If a call returns {stop, NewVal}, no more calls are performed and NewVal is returned.
|
|
run_fold(Hook, Val, Args) ->
|
|
run_fold(Hook, global, Val, Args).
|
|
|
|
-spec run_fold(atom(), binary() | global, T, list()) -> T.
|
|
run_fold(Hook, Host, Val, Args) ->
|
|
try ets:lookup(hooks, {Hook, Host}) of
|
|
[{_, Ls}] ->
|
|
case erlang:get(?TRACE_HOOK_KEY) of
|
|
undefined ->
|
|
run_fold1(Ls, Hook, Val, Args);
|
|
TracingHooksOpts ->
|
|
case do_get_tracing_options(Hook, Host, TracingHooksOpts) of
|
|
undefined ->
|
|
run_fold1(Ls, Hook, Val, Args);
|
|
TracingOpts ->
|
|
fold_start_hook_tracing(TracingOpts, Hook, Host, [Val | Args]),
|
|
run_fold2(Ls, Hook, Val, Args, Host, TracingOpts)
|
|
end
|
|
end;
|
|
[] ->
|
|
Val
|
|
catch _:badarg ->
|
|
Val
|
|
end.
|
|
|
|
get_tracing_options(Hook, Host, Pid) when Pid == erlang:self() ->
|
|
do_get_tracing_options(Hook, Host, erlang:get(?TRACE_HOOK_KEY));
|
|
get_tracing_options(Hook, Host, Pid) when erlang:is_pid(Pid) ->
|
|
case erlang:process_info(Pid, dictionary) of
|
|
{_, DictPropList} ->
|
|
case lists:keyfind(?TRACE_HOOK_KEY, 1, DictPropList) of
|
|
{_, TracingHooksOpts} ->
|
|
do_get_tracing_options(Hook, Host, TracingHooksOpts);
|
|
_ ->
|
|
undefined
|
|
end;
|
|
_ ->
|
|
undefined
|
|
end.
|
|
|
|
trace_on(Hook, Host, Pid, #{}=Opts, Timeout) when Pid == erlang:self() ->
|
|
do_trace_on(Hook, Host, Opts, Timeout);
|
|
trace_on(Hook, Host, Proc, #{}=Opts, Timeout) ->
|
|
try sys:replace_state(
|
|
Proc,
|
|
fun(State) ->
|
|
do_trace_on(Hook, Host, Opts, Timeout),
|
|
State
|
|
end,
|
|
15000
|
|
) of
|
|
_ -> % process state
|
|
ok
|
|
catch
|
|
_:Reason ->
|
|
{error, Reason}
|
|
end.
|
|
|
|
trace_off(Hook, Host, Pid) when Pid == erlang:self() ->
|
|
do_trace_off(Hook, Host);
|
|
trace_off(Hook, Host, Proc) ->
|
|
try sys:replace_state(
|
|
Proc,
|
|
fun(State) ->
|
|
do_trace_off(Hook, Host),
|
|
State
|
|
end,
|
|
15000
|
|
) of
|
|
_ -> % process state
|
|
ok
|
|
catch
|
|
_:Reason ->
|
|
{error, Reason}
|
|
end.
|
|
|
|
%%%----------------------------------------------------------------------
|
|
%%% Callback functions from gen_server
|
|
%%%----------------------------------------------------------------------
|
|
init([]) ->
|
|
_ = ets:new(hooks, [named_table, {read_concurrency, true}]),
|
|
{ok, #state{}}.
|
|
|
|
handle_call({add, Hook, Host, Module, Function, Seq}, _From, State) ->
|
|
HookFormat = {Seq, Module, Function},
|
|
Reply = handle_add(Hook, Host, HookFormat),
|
|
{reply, Reply, State};
|
|
handle_call({delete, Hook, Host, Module, Function, Seq}, _From, State) ->
|
|
HookFormat = {Seq, Module, Function},
|
|
Reply = handle_delete(Hook, Host, HookFormat),
|
|
{reply, Reply, State};
|
|
handle_call(Request, From, State) ->
|
|
?WARNING_MSG("Unexpected call from ~p: ~p", [From, Request]),
|
|
{noreply, State}.
|
|
|
|
-spec handle_add(atom(), atom(), hook()) -> ok.
|
|
handle_add(Hook, Host, El) ->
|
|
case ets:lookup(hooks, {Hook, Host}) of
|
|
[{_, Ls}] ->
|
|
case lists:member(El, Ls) of
|
|
true ->
|
|
ok;
|
|
false ->
|
|
NewLs = lists:merge(Ls, [El]),
|
|
ets:insert(hooks, {{Hook, Host}, NewLs}),
|
|
ok
|
|
end;
|
|
[] ->
|
|
NewLs = [El],
|
|
ets:insert(hooks, {{Hook, Host}, NewLs}),
|
|
ok
|
|
end.
|
|
|
|
-spec handle_delete(atom(), atom(), hook()) -> ok.
|
|
handle_delete(Hook, Host, El) ->
|
|
case ets:lookup(hooks, {Hook, Host}) of
|
|
[{_, Ls}] ->
|
|
NewLs = lists:delete(El, Ls),
|
|
ets:insert(hooks, {{Hook, Host}, NewLs}),
|
|
ok;
|
|
[] ->
|
|
ok
|
|
end.
|
|
|
|
handle_cast(Msg, State) ->
|
|
?WARNING_MSG("Unexpected cast: ~p", [Msg]),
|
|
{noreply, State}.
|
|
|
|
handle_info(Info, State) ->
|
|
?WARNING_MSG("Unexpected info: ~p", [Info]),
|
|
{noreply, State}.
|
|
|
|
terminate(_Reason, _State) ->
|
|
ok.
|
|
|
|
code_change(_OldVsn, State, _Extra) ->
|
|
{ok, State}.
|
|
|
|
%%%----------------------------------------------------------------------
|
|
%%% Internal functions
|
|
%%%----------------------------------------------------------------------
|
|
-spec run1([hook()], atom(), list()) -> ok.
|
|
run1([], _Hook, _Args) ->
|
|
ok;
|
|
run1([{_Seq, Module, Function} | Ls], Hook, Args) ->
|
|
Res = safe_apply(Hook, Module, Function, Args),
|
|
case Res of
|
|
'EXIT' ->
|
|
run1(Ls, Hook, Args);
|
|
stop ->
|
|
ok;
|
|
_ ->
|
|
run1(Ls, Hook, Args)
|
|
end.
|
|
|
|
-spec run_fold1([hook()], atom(), T, list()) -> T.
|
|
run_fold1([], _Hook, Val, _Args) ->
|
|
Val;
|
|
run_fold1([{_Seq, Module, Function} | Ls], Hook, Val, Args) ->
|
|
Res = safe_apply(Hook, Module, Function, [Val | Args]),
|
|
case Res of
|
|
'EXIT' ->
|
|
run_fold1(Ls, Hook, Val, Args);
|
|
stop ->
|
|
Val;
|
|
{stop, NewVal} ->
|
|
NewVal;
|
|
NewVal ->
|
|
run_fold1(Ls, Hook, NewVal, Args)
|
|
end.
|
|
|
|
-spec safe_apply(atom(), atom(), atom() | fun(), list()) -> any().
|
|
safe_apply(Hook, Module, Function, Args) ->
|
|
?DEBUG("Running hook ~p: ~p:~p/~B",
|
|
[Hook, Module, Function, length(Args)]),
|
|
try if is_function(Function) ->
|
|
apply(Function, Args);
|
|
true ->
|
|
apply(Module, Function, Args)
|
|
end
|
|
catch ?EX_RULE(E, R, St) when E /= exit; R /= normal ->
|
|
Stack = ?EX_STACK(St),
|
|
?ERROR_MSG("Hook ~p crashed when running ~p:~p/~p:~n" ++
|
|
string:join(
|
|
["** ~ts"|
|
|
["** Arg " ++ integer_to_list(I) ++ " = ~p"
|
|
|| I <- lists:seq(1, length(Args))]],
|
|
"~n"),
|
|
[Hook, Module, Function, length(Args),
|
|
misc:format_exception(2, E, R, Stack)|Args]),
|
|
'EXIT'
|
|
end.
|
|
|
|
%%%----------------------------------------------------------------------
|
|
%%% Internal tracing functions
|
|
%%%----------------------------------------------------------------------
|
|
|
|
do_trace_on(Hook, Host, Opts, Timeout) when erlang:is_list(Host) ->
|
|
do_trace_on(Hook, erlang:list_to_binary(Host), Opts, Timeout);
|
|
do_trace_on(Hook, Host, Opts, undefined) ->
|
|
case erlang:get(?TRACE_HOOK_KEY) of
|
|
_ when Hook == all andalso Host == <<"*">> ->
|
|
% Trace everything:
|
|
erlang:put(?TRACE_HOOK_KEY, #{all => #{<<"*">> => Opts}});
|
|
#{all := #{<<"*">> := _}} -> % Already tracing everything
|
|
% Update Opts:
|
|
erlang:put(?TRACE_HOOK_KEY, #{all => #{<<"*">> => Opts}});
|
|
#{all := HostOpts} when Hook == all -> % Already Tracing everything for some hosts
|
|
% Add/Update Host and Opts:
|
|
erlang:put(?TRACE_HOOK_KEY, #{all => HostOpts#{Host => Opts}});
|
|
#{all := _} -> % Already tracing everything and Hook is not all
|
|
ok;
|
|
#{} when Hook == all ->
|
|
% Remove other hooks by just adding all:
|
|
erlang:put(?TRACE_HOOK_KEY, #{all => #{Host => Opts}});
|
|
#{}=TraceHooksOpts when Host == <<"*">> -> % Want to trace a hook for all hosts
|
|
erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => #{Host => Opts}});
|
|
#{}=TraceHooksOpts ->
|
|
case maps:get(Hook, TraceHooksOpts, #{}) of
|
|
#{<<"*">> := _} -> % Already tracing this hook for all hosts
|
|
ok;
|
|
HostOpts ->
|
|
erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => HostOpts#{Host => Opts}})
|
|
end;
|
|
undefined ->
|
|
erlang:put(?TRACE_HOOK_KEY, #{Hook => #{Host => Opts}})
|
|
end,
|
|
ok;
|
|
do_trace_on(Hook, Host, Opts, TimeoutSeconds) -> % Trace myself `Timeout` time
|
|
Timeout = timer:seconds(TimeoutSeconds),
|
|
ParentPid = erlang:self(),
|
|
try erlang:spawn(
|
|
fun() ->
|
|
MonitorRef = erlang:monitor(process, ParentPid),
|
|
receive
|
|
{_, MonitorRef, _, _, _} ->
|
|
ok
|
|
after Timeout ->
|
|
trace_off(Hook, Host, ParentPid)
|
|
end,
|
|
erlang:exit(normal)
|
|
end
|
|
) of
|
|
_ ->
|
|
do_trace_on(Hook, Host, Opts, undefined) % ok
|
|
catch
|
|
_:Reason -> % system_limit
|
|
{error, Reason}
|
|
end.
|
|
|
|
do_trace_off(Hook, Host) when erlang:is_list(Host) ->
|
|
do_trace_off(Hook, erlang:list_to_binary(Host));
|
|
do_trace_off(Hook, Host) ->
|
|
case erlang:get(?TRACE_HOOK_KEY) of
|
|
_ when Hook == all andalso Host == <<"*">> ->
|
|
% Remove all tracing:
|
|
erlang:erase(?TRACE_HOOK_KEY);
|
|
#{all := HostOpts} when Hook == all -> % Already tracing all hooks
|
|
% Remove Host:
|
|
HostOpts2 = maps:remove(Host, HostOpts),
|
|
if
|
|
HostOpts2 == #{} ->
|
|
% Remove all tracing:
|
|
erlang:erase(?TRACE_HOOK_KEY);
|
|
true ->
|
|
erlang:put(?TRACE_HOOK_KEY, #{all => HostOpts2})
|
|
end;
|
|
#{}=TraceHooksOpts when Host == <<"*">> ->
|
|
% Remove tracing of this hook for all hosts:
|
|
TraceHooksOpts2 = maps:remove(Hook, TraceHooksOpts),
|
|
if
|
|
TraceHooksOpts2 == #{} ->
|
|
% Remove all tracing:
|
|
erlang:erase(?TRACE_HOOK_KEY);
|
|
true ->
|
|
erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts2)
|
|
end;
|
|
#{}=TraceHooksOpts ->
|
|
case maps:get(Hook, TraceHooksOpts, undefined) of
|
|
#{}=HostOpts ->
|
|
NewHostOpts = maps:remove(Host, HostOpts),
|
|
if
|
|
NewHostOpts == #{} ->
|
|
% Remove hook:
|
|
erlang:put(?TRACE_HOOK_KEY, maps:remove(Hook, TraceHooksOpts));
|
|
true ->
|
|
erlang:put(?TRACE_HOOK_KEY, TraceHooksOpts#{Hook => NewHostOpts})
|
|
end;
|
|
_ ->
|
|
ok
|
|
end;
|
|
undefined ->
|
|
ok
|
|
end,
|
|
ok.
|
|
|
|
do_get_tracing_options(Hook, Host, MaybeMap) ->
|
|
case MaybeMap of
|
|
undefined ->
|
|
undefined;
|
|
#{all := #{<<"*">> := Opts}} -> % Tracing everything
|
|
Opts;
|
|
#{all := HostOpts} -> % Tracing all hooks for some hosts
|
|
maps:get(Host, HostOpts, undefined);
|
|
#{}=TraceHooksOpts ->
|
|
HostOpts = maps:get(Hook, TraceHooksOpts, #{}),
|
|
case maps:get(Host, HostOpts, undefined) of
|
|
undefined ->
|
|
maps:get(<<"*">>, HostOpts, undefined);
|
|
Opts ->
|
|
Opts
|
|
end
|
|
end.
|
|
|
|
run2([], Hook, Args, Host, Opts) ->
|
|
foreach_stop_hook_tracing(Opts, Hook, Host, Args, undefined),
|
|
ok;
|
|
run2([{Seq, Module, Function} | Ls], Hook, Args, Host, TracingOpts) ->
|
|
foreach_start_callback_tracing(TracingOpts, Hook, Host, Module, Function, Args, Seq),
|
|
Res = safe_apply(Hook, Module, Function, Args),
|
|
foreach_stop_callback_tracing(TracingOpts, Hook, Host, Module, Function, Args, Seq, Res),
|
|
case Res of
|
|
'EXIT' ->
|
|
run2(Ls, Hook, Args, Host, TracingOpts);
|
|
stop ->
|
|
foreach_stop_hook_tracing(TracingOpts, Hook, Host, Args, {Module, Function, Seq, Ls}),
|
|
ok;
|
|
_ ->
|
|
run2(Ls, Hook, Args, Host, TracingOpts)
|
|
end.
|
|
|
|
run_fold2([], Hook, Val, Args, Host, Opts) ->
|
|
fold_stop_hook_tracing(Opts, Hook, Host, [Val | Args], undefined),
|
|
Val;
|
|
run_fold2([{Seq, Module, Function} | Ls], Hook, Val, Args, Host, TracingOpts) ->
|
|
fold_start_callback_tracing(TracingOpts, Hook, Host, Module, Function, [Val | Args], Seq),
|
|
Res = safe_apply(Hook, Module, Function, [Val | Args]),
|
|
fold_stop_callback_tracing(TracingOpts, Hook, Host, Module, Function, [Val | Args], Seq, Res),
|
|
case Res of
|
|
'EXIT' ->
|
|
run_fold2(Ls, Hook, Val, Args, Host, TracingOpts);
|
|
stop ->
|
|
fold_stop_hook_tracing(TracingOpts, Hook, Host, [Val | Args], {Module, Function, Seq, {old, Val}, Ls}),
|
|
Val;
|
|
{stop, NewVal} ->
|
|
fold_stop_hook_tracing(TracingOpts, Hook, Host, [Val | Args], {Module, Function, Seq, {new, NewVal}, Ls}),
|
|
NewVal;
|
|
NewVal ->
|
|
run_fold2(Ls, Hook, NewVal, Args, Host, TracingOpts)
|
|
end.
|
|
|
|
foreach_start_hook_tracing(TracingOpts, Hook, Host, Args) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, start_hook, [Args], foreach).
|
|
|
|
foreach_stop_hook_tracing(TracingOpts, Hook, Host, Args, BreakCallback) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], foreach).
|
|
|
|
foreach_start_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], foreach).
|
|
|
|
foreach_stop_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq, Res) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], foreach).
|
|
|
|
fold_start_hook_tracing(TracingOpts, Hook, Host, Args) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, start_hook, [Args], fold).
|
|
|
|
fold_stop_hook_tracing(TracingOpts, Hook, Host, Args, BreakCallback) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, stop_hook, [Args, BreakCallback], fold).
|
|
|
|
fold_start_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, start_callback, [Mod, Func, Args, Seq], fold).
|
|
|
|
fold_stop_callback_tracing(TracingOpts, Hook, Host, Mod, Func, Args, Seq, Res) ->
|
|
run_event_handlers(TracingOpts, Hook, Host, stop_callback, [Mod, Func, Args, Seq, Res], fold).
|
|
|
|
run_event_handlers(TracingOpts, Hook, Host, Event, EventArgs, RunType) ->
|
|
EventHandlerList = maps:get(event_handler_list, TracingOpts, default_tracing_event_handler_list()),
|
|
EventHandlerOpts = maps:get(event_handler_options, TracingOpts, #{}),
|
|
if
|
|
erlang:is_list(EventHandlerList) ->
|
|
lists:foreach(
|
|
fun(EventHandler) ->
|
|
try
|
|
if
|
|
erlang:is_function(EventHandler) ->
|
|
erlang:apply(
|
|
EventHandler,
|
|
[Event, EventArgs, RunType, Hook, Host, EventHandlerOpts, TracingOpts]
|
|
);
|
|
true ->
|
|
EventHandler:handle_hook_tracing_event(
|
|
Event,
|
|
EventArgs,
|
|
RunType,
|
|
Hook,
|
|
Host,
|
|
EventHandlerOpts,
|
|
TracingOpts
|
|
)
|
|
end
|
|
of
|
|
_ ->
|
|
ok
|
|
catch
|
|
?EX_RULE(E, R, St) ->
|
|
Stack = ?EX_STACK(St),
|
|
?ERROR_MSG(
|
|
"(~0p|~ts|~0p) Tracing event '~0p' handler exception(~0p): ~0p: ~0p",
|
|
[Hook, Host, erlang:self(), EventHandler, E, R, Stack]
|
|
),
|
|
ok
|
|
end
|
|
end,
|
|
EventHandlerList
|
|
); % ok
|
|
true ->
|
|
?ERROR_MSG("(~0p|~ts|~0p) Bad event handler list: ~0p", [Hook, Host, erlang:self(), EventHandlerList]),
|
|
ok
|
|
end.
|
|
|
|
default_tracing_event_handler_list() ->
|
|
[fun tracing_timing_event_handler/7].
|
|
|
|
tracing_timing_event_handler(start_hook, EventArgs, RunType, Hook, Host, _, TracingOpts) ->
|
|
HookStart = erlang:system_time(nanosecond),
|
|
% Generate new event:
|
|
run_event_handlers(TracingOpts, Hook, Host, start_hook_timing, EventArgs ++ [HookStart], RunType);
|
|
tracing_timing_event_handler(stop_hook, EventArgs, RunType, Hook, Host, _, TracingOpts) ->
|
|
HookStop = erlang:system_time(nanosecond),
|
|
TimingMap = #{} = erlang:get(?TIMING_KEY),
|
|
{HookStart, CallbackList} = maps:get({Hook, Host}, TimingMap),
|
|
{CallbackListTiming, CallbackListTotal} = lists:foldl(
|
|
fun({_, _, _, CallbackStart, CallbackStop}=CallbackTimingInfo, {CallbackListTimingX, Total}) ->
|
|
{CallbackListTimingX ++ [CallbackTimingInfo], Total + (CallbackStop - CallbackStart)}
|
|
end,
|
|
{[], 0},
|
|
CallbackList
|
|
),
|
|
% Generate new event:
|
|
run_event_handlers(
|
|
TracingOpts,
|
|
Hook,
|
|
Host,
|
|
stop_hook_timing,
|
|
EventArgs ++ [HookStart, HookStop, CallbackListTiming, CallbackListTotal],
|
|
RunType
|
|
);
|
|
tracing_timing_event_handler(start_callback, EventArgs, RunType, Hook, Host, _, TracingOpts) ->
|
|
CallbackStart = erlang:system_time(nanosecond),
|
|
% Generate new event:
|
|
run_event_handlers(TracingOpts, Hook, Host, start_callback_timing, EventArgs ++ [CallbackStart], RunType);
|
|
tracing_timing_event_handler(stop_callback, EventArgs, RunType, Hook, Host, _, TracingOpts) ->
|
|
CallbackStop = erlang:system_time(nanosecond),
|
|
TimingMap = #{} = erlang:get(?TIMING_KEY),
|
|
{_, [{_, _, _, CallbackStart} | _]} = maps:get({Hook, Host}, TimingMap),
|
|
run_event_handlers(
|
|
TracingOpts,
|
|
Hook,
|
|
Host,
|
|
stop_callback_timing,
|
|
EventArgs ++ [CallbackStart, CallbackStop],
|
|
RunType
|
|
),
|
|
ok;
|
|
tracing_timing_event_handler(start_hook_timing, [_, HookStart], RunType, Hook, Host, EventHandlerOpts, _) ->
|
|
tracing_output(EventHandlerOpts, "(~0p|~ts|~0p|~0p) Timing started\n", [Hook, Host, erlang:self(), RunType]),
|
|
case erlang:get(?TIMING_KEY) of
|
|
#{}=TimingMap ->
|
|
erlang:put(?TIMING_KEY, TimingMap#{{Hook, Host} => {HookStart, []}});
|
|
_ ->
|
|
erlang:put(?TIMING_KEY, #{{Hook, Host} => {HookStart, []}})
|
|
end,
|
|
ok;
|
|
tracing_timing_event_handler(
|
|
stop_hook_timing,
|
|
[_, _, HookStart, HookStop, CallbackListTiming, CallbackListTotal],
|
|
RunType,
|
|
Hook,
|
|
Host,
|
|
EventHandlerOpts,
|
|
_
|
|
) ->
|
|
if
|
|
erlang:length(CallbackListTiming) < 2 -> % We don't need sorted timing result
|
|
ok;
|
|
true ->
|
|
CallbackListTimingText =
|
|
lists:foldl(
|
|
fun({Mod, Func, Arity, Diff}, CallbackListTimingText) ->
|
|
CallbackListTimingText
|
|
++ "\n\t"
|
|
++ mfa_string({Mod, Func, Arity})
|
|
++ " -> "
|
|
++ human_readable_time_string(Diff)
|
|
end,
|
|
"",
|
|
lists:keysort(
|
|
4,
|
|
[
|
|
{Mod, Func, Arity, CallbackStop - CallbackStart} ||
|
|
{Mod, Func, Arity, CallbackStart, CallbackStop} <- CallbackListTiming
|
|
]
|
|
)
|
|
),
|
|
tracing_output(
|
|
EventHandlerOpts,
|
|
"(~0p|~ts|~0p|~0p) All callbacks took ~ts to run. Sorted running time:"
|
|
++ CallbackListTimingText
|
|
++ "\n",
|
|
[Hook, Host, erlang:self(), RunType, human_readable_time_string(CallbackListTotal)]
|
|
),
|
|
tracing_output(
|
|
EventHandlerOpts,
|
|
"(~0p|~ts|~0p|~0p) Time calculations for all callbacks took ~ts\n",
|
|
[
|
|
Hook,
|
|
Host,
|
|
erlang:self(),
|
|
RunType,
|
|
human_readable_time_string((HookStop - HookStart) - CallbackListTotal)
|
|
]
|
|
)
|
|
end,
|
|
tracing_output(EventHandlerOpts, "(~0p|~ts|~0p|~0p) Timing stopped\n", [Hook, Host, erlang:self(), RunType]),
|
|
TimingMap = #{} = erlang:get(?TIMING_KEY),
|
|
NewTimingMap = maps:remove({Hook, Host}, TimingMap),
|
|
if
|
|
NewTimingMap == #{} ->
|
|
erlang:erase(?TIMING_KEY);
|
|
true ->
|
|
erlang:put(?TIMING_KEY, NewTimingMap)
|
|
end,
|
|
ok;
|
|
tracing_timing_event_handler(start_callback_timing, [Mod, Func, Args, _, CallbackStart], _, Hook, Host, _, _) ->
|
|
TimingMap = #{} = erlang:get(?TIMING_KEY),
|
|
{HookStart, Callbacks} = maps:get({Hook, Host}, TimingMap),
|
|
erlang:put(
|
|
?TIMING_KEY,
|
|
TimingMap#{
|
|
{Hook, Host} => {HookStart, [{Mod, Func, erlang:length(Args), CallbackStart} | Callbacks]}
|
|
}
|
|
),
|
|
ok;
|
|
tracing_timing_event_handler(
|
|
stop_callback_timing,
|
|
[Mod, Func, _, _, _, CallbackStart, CallbackStop],
|
|
RunType,
|
|
Hook,
|
|
Host,
|
|
EventHandlerOpts,
|
|
_
|
|
) ->
|
|
TimingMap = #{} = erlang:get(?TIMING_KEY),
|
|
{HookStart, [{Mod, Func, Arity, CallbackStart} | Callbacks]} = maps:get({Hook, Host}, TimingMap),
|
|
maps:get(output_for_each_callback, maps:get(timing, EventHandlerOpts, #{}), false) andalso tracing_output(
|
|
EventHandlerOpts,
|
|
"(~0p|~ts|~0p|~0p) "
|
|
++ mfa_string({Mod, Func, Arity})
|
|
++ " took "
|
|
++ human_readable_time_string(CallbackStop - CallbackStart)
|
|
++ "\n",
|
|
[Hook, Host, erlang:self(), RunType]
|
|
),
|
|
erlang:put(
|
|
?TIMING_KEY,
|
|
TimingMap#{
|
|
{Hook, Host} => {HookStart, [{Mod, Func, Arity, CallbackStart, CallbackStop} | Callbacks]}
|
|
}
|
|
),
|
|
ok;
|
|
tracing_timing_event_handler(_, _, _, _, _, _, _) ->
|
|
ok.
|
|
|
|
tracing_output(#{output_function := OutputF}, Text, Args) ->
|
|
try
|
|
OutputF(Text, Args)
|
|
of
|
|
_ ->
|
|
ok
|
|
catch
|
|
?EX_RULE(E, R, St) ->
|
|
Stack = ?EX_STACK(St),
|
|
?ERROR_MSG("Tracing output function exception(~0p): ~0p: ~0p", [E, R, Stack]),
|
|
ok
|
|
end;
|
|
tracing_output(#{output_log_level := Output}, Text, Args) ->
|
|
if
|
|
Output == debug ->
|
|
?DEBUG(Text, Args);
|
|
true -> % info
|
|
?INFO_MSG(Text, Args)
|
|
end,
|
|
ok;
|
|
tracing_output(Opts, Text, Args) ->
|
|
tracing_output(Opts#{output_log_level => info}, Text, Args).
|
|
|
|
mfa_string({_, Fun, _}) when erlang:is_function(Fun) ->
|
|
io_lib:format("~0p", [Fun]);
|
|
mfa_string({Mod, Func, Arity}) ->
|
|
erlang:atom_to_list(Mod) ++ ":" ++ erlang:atom_to_list(Func) ++ "/" ++ erlang:integer_to_list(Arity).
|
|
|
|
human_readable_time_string(TimeNS) ->
|
|
{Time, Unit, Decimals} =
|
|
if
|
|
TimeNS >= 1000000000 ->
|
|
{TimeNS / 1000000000, "", 10};
|
|
TimeNS >= 1000000 ->
|
|
{TimeNS / 1000000, "m", 7};
|
|
TimeNS >= 1000 ->
|
|
{TimeNS / 1000, "μ", 4};
|
|
true ->
|
|
{TimeNS / 1, "n", 0}
|
|
end,
|
|
erlang:float_to_list(Time, [{decimals, Decimals}, compact]) ++ Unit ++ "s".
|