Skip to content

Instantly share code, notes, and snippets.

@nivertech
Created October 30, 2011 12:19
Show Gist options
  • Save nivertech/1325848 to your computer and use it in GitHub Desktop.
Save nivertech/1325848 to your computer and use it in GitHub Desktop.
-module(calltime_trace).
-behaviour(gen_server).
%% The purpose of this module is to continiously log calltime statistics
%% of a function calculated over short intervals. The tracing support of the
%% erlang runtime system is to trace entry and return from the function in
%% all processes. The tracing is aborted if the time it takes to process all
%% trace messages generated during an interval lags behind with more than a
%% full interval. If the tracing lags behind with a smaller amount of time
%% the logger attempts to compensate for the lag.
-export([start/5]).
%% gen_server functions
-export([init/1, handle_call/3, handle_cast/2,
handle_info/2, code_change/3, terminate/2]).
start(Module, Function, Arity, Interval, Output) ->
Opts = [
{module, Module},
{function, Function},
{arity, Arity},
{interval, Interval},
{filename, Output}],
gen_server:start(?MODULE, Opts, []).
-record(state, {
module, function, arity, interval, filename,
timeout, table, output, calltimes}).
%% @private
init(Opts) ->
{module, Module} = lists:keyfind(module, 1, Opts),
{function, Function} = lists:keyfind(function, 1, Opts),
{arity, Arity} = lists:keyfind(arity, 1, Opts),
{interval, Interval} = lists:keyfind(interval, 1, Opts),
{filename, Output} = lists:keyfind(filename, 1, Opts),
io:format("~p~n", [Output]),
{ok, File} = file:open(Output, [write]),
TRef = erlang:start_timer(Interval, self(), now()),
Tab = ets:new(calltimes_trace, [private,set]),
erlang:trace(all, true, [call, return_to, timestamp]),
erlang:trace_pattern({Module, Function, Arity}, true, [local]),
erlang:process_flag(trap_exit, true),
io:format(File, "\"timestamp\",\"min-avg\",\"total-avg\",\"max-avg\"~n", []),
State = #state{
module=Module, function=Function, arity=Arity,
interval=Interval, timeout=TRef,
filename=Output, output=File,
table=Tab, calltimes=[]},
{ok, State}.
%% @private
handle_call(Msg, _From, State) ->
{stop, Msg, State}.
%% @private
handle_cast(Msg, State) ->
{stop, Msg, State}.
%% @private
handle_info({timeout, _TRef, Time}, State) ->
#state{interval=Interval, calltimes=Times, output=File} = State,
Now = now(),
Diff = timer:now_diff(Now, Time) div 1000, %% ms
case Diff - Interval of
Lag when Lag > Interval ->
{stop, normal, State};
Lag ->
TRef = erlang:start_timer(Interval - Lag, self(), Now),
ok = output_result(Times, File),
{noreply, State#state{timeout=TRef, calltimes=[]}}
end;
handle_info({trace_ts, Pid, call, {_M,_F,_A}, Time}, State) ->
#state{table=Table} = State,
enter_function(Pid, Time, Table),
{noreply, State};
handle_info({trace_ts, Pid, return_to,{_M,_F,_A}, Time}, State) ->
#state{table=Table, calltimes=Times} = State,
Calltime = leave_function(Pid, Time, Table),
{noreply, State#state{calltimes=[Calltime|Times]}};
handle_info(Msg, State) ->
{stop, Msg, State}.
%% @private
code_change(_Prev, State, _Extra) ->
{ok, State}.
%% @private
terminate(_Reason, State) ->
#state{module=Module,function=Function,arity=Arity} = State,
erlang:trace_pattern({Module, Function, Arity}, false, [local]),
erlang:trace(all, false, [call, return_to, timestamp]),
ignore.
%% @private
enter_function(Pid, Time, Tab) ->
true = ets:insert_new(Tab, {Pid,Time}).
%% @private
leave_function(Pid, Time, Tab) ->
Time1 = ets:lookup_element(Tab, Pid, 2),
true = ets:delete(Tab, Pid),
timer:now_diff(Time, Time1).
%% @private
output_result([], File) ->
output_result([0], File);
output_result(Times, File) ->
Max = lists:max(Times),
Min = lists:min(Times),
Tot = lists:sum(Times),
Cnt = length(Times),
Avg = Tot / Cnt,
{{Y,Mo,D},{H,Mi,S}} = erlang:localtime(),
Fmt = "\"~b-~b-~b ~b:~b:~b\", ~b, ~.1f, ~b~n",
Arg = [Y, Mo, D, H, Mi, S, Min, Avg, Max],
io:format(File, Fmt, Arg).
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment