gistfile1.erl

-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).