xprof

%% -*- erlang-indent-level: 4;indent-tabs-mode: nil -*-
%% ex: ts=4 sw=4 et

%% @doc Gen server that tracks all calls to a particular function. It
%% registers itself localy under a atom that consists of MFA and xprof_monitor
%% prefix. The same name is used to create public ETS table that holds entries
%% with call time stats for every second.
-module(xprof_tracer_handler).

-behaviour(gen_server).

-export([start_link/1, data/2, capture/3, get_captured_data/2]).

-export([trace_mfa_off/1]).

%% gen_server callbacks
-export([init/1,
         handle_call/3,
         handle_cast/2,
         handle_info/2,
         terminate/2,
         code_change/3]).

-record(state, {mfa, name, last_ts, hdr_ref, window_size,
                capture_spec, capture_id=0, capture_counter=0}).

-define(ONE_SEC, 1000000). %% Second in microseconds
-define(WINDOW_SIZE, 10*60). %% 10 min window size

%% @doc Starts new process registered localy.
-spec start_link(xprof:mfaspec()) -> {ok, pid()}.
start_link(MFA) ->
    Name = xprof_lib:mfa2atom(MFA),
    gen_server:start_link({local, Name}, ?MODULE, [MFA, Name], []).

%% @doc Returns histogram data for seconds that occured after FromEpoch.
-spec data(xprof:mfaid(), non_neg_integer()) -> [proplists:proplist()] |
                                                {error, not_found}.
data(MFA, FromEpoch) ->
    Name = xprof_lib:mfa2atom(MFA),
    try
        ets:select(Name, [{
                            {{sec, '$1'},'$2'},
                            [{'>','$1',FromEpoch}],
                            ['$2']
                          }])
    catch
        error:badarg ->
            {error, not_found}
    end.

%% @doc Starts capturing args and results from function calls that lasted longer
%% than specified time threshold.
-spec capture(xprof:mfaid(), non_neg_integer(), non_neg_integer()) ->
                     {ok, non_neg_integer()}.
capture(MFA = {M,F,A}, Threshold, Limit) ->
    lager:info("Capturing ~p calls to ~w:~w/~w that exceed ~p ms:",
               [Limit, M, F, A, Threshold]),

    Name = xprof_lib:mfa2atom(MFA),
    gen_server:call(Name, {capture, Threshold, Limit}).

%% @doc
-spec get_captured_data(mfa(), non_neg_integer()) ->
                               empty | {ok,
                                        {Id :: non_neg_integer(),
                                         Threshold :: non_neg_integer(),
                                         Limit :: non_neg_integer()},
                                        list(any())}.
get_captured_data(MFA, Offset) ->
    Name = xprof_lib:mfa2atom(MFA),
    Items = lists:sort(ets:select(Name,
                                  [{
                                     {{args_res, '$1'},
                                      {'$2', '$3','$4','$5'}},
                                     [{'>','$1',Offset}],
                                     [['$1', '$2', '$3', '$4', '$5']]
                                   }])),

    [{capture_spec, Id, Threshold, Limit}] = ets:lookup(Name, capture_spec),
    {ok, {Id, Threshold, Limit}, Items}.


%% gen_server callbacks

init([MFA, Name]) ->
    {ok, HDR} = init_storage(Name),
    %% add trace pattern with args capturing turned off
    capture_args_trace_off(MFA),
    {ok, #state{mfa=MFA, hdr_ref=HDR, name=Name,
                last_ts=os:timestamp(),
                window_size=?WINDOW_SIZE}, 1000}.

handle_call({capture, Threshold, Limit}, _From,
            State = #state{mfa = MFA}) ->
    NewId = State#state.capture_id + 1,
    NewState = State#state{capture_spec = {Threshold, Limit},
                           capture_id = NewId,
                           capture_counter = 1},
    init_new_capture_in_ets(NewState),
    capture_args_trace_on(MFA),
    {reply, {ok, NewId}, NewState};
handle_call(Request, _From, State) ->
    lager:warning("Received unknown message: ~p", [Request]),
    {reply, ignored, State}.

handle_cast(_Msg, State) ->
    {noreply, State}.

handle_info({trace_ts, Pid, call, _MFA, Args, StartTime}, State) ->
    put_ts_args(Pid, StartTime, Args),

    {Timeout, NewState} = maybe_make_snapshot(State),
    {noreply, NewState, Timeout};
handle_info({trace_ts, Pid, return_from, _MFA, Ret, EndTime}, State) ->

    NewState = case get_ts_args(Pid) of
                   undefined ->
                       State;
                   {StartTime, Args} ->
                       CallTime = timer:now_diff(EndTime, StartTime),
                       record_results(Pid, CallTime, Args, Ret, State)
               end,

    {Timeout, NewState2} = maybe_make_snapshot(NewState),
    {noreply, NewState2, Timeout};
handle_info(timeout, State) ->
    {Timeout, NewState} = maybe_make_snapshot(State),
    {noreply, NewState, Timeout};
handle_info(_Info, State) ->
    {noreply, State}.

terminate(_Reason, _State) ->
    ok.

code_change(_OldVsn, State, _Extra) ->
    {ok, State}.

%% Internal functions

init_storage(Name) ->
    ets:new(Name, [public, named_table]),
    ets:insert(Name, {capture_spec, -1, -1, -1}),
    hdr_histogram:open(1000000,3).

maybe_make_snapshot(State = #state{name=Name, last_ts=LastTS,
                                   window_size=WindSize}) ->
    NowTS = os:timestamp(),
    case timer:now_diff(NowTS, LastTS) of
        DiffMicro when DiffMicro >= ?ONE_SEC ->
            save_snapshot(NowTS, State),
            remove_outdated_snapshots(Name, xprof_lib:now2epoch(NowTS)-WindSize),
            {calc_next_timeout(DiffMicro), State#state{last_ts=NowTS}};
        DiffMicro ->
            {calc_next_timeout(DiffMicro), State}
    end.

calc_next_timeout(DiffMicro) ->
    DiffMilli = DiffMicro div 1000,
    1000 - DiffMilli rem 1000.

save_snapshot(NowTS, #state{name=Name, hdr_ref=Ref}) ->
    Epoch = xprof_lib:now2epoch(NowTS),
    ets:insert(Name, [{{sec, Epoch}, get_current_hist_stats(Ref, Epoch)}]),
    hdr_histogram:reset(Ref).

get_current_hist_stats(HistRef, Time) ->
    [{time, Time},
     {min,      hdr_histogram:min(HistRef)},
     {mean,     hdr_histogram:mean(HistRef)},
     {median,   hdr_histogram:median(HistRef)},
     {max,      hdr_histogram:max(HistRef)},
     {stddev,   hdr_histogram:stddev(HistRef)},
     {p25,      hdr_histogram:percentile(HistRef,25.0)},
     {p50,      hdr_histogram:percentile(HistRef,50.0)},
     {p75,      hdr_histogram:percentile(HistRef,75.0)},
     {p90,      hdr_histogram:percentile(HistRef,90.0)},
     {p99,      hdr_histogram:percentile(HistRef,99.0)},
     {p9999999, hdr_histogram:percentile(HistRef,99.9999)},
     {memsize,  hdr_histogram:get_memory_size(HistRef)},
     {count,    hdr_histogram:get_total_count(HistRef)}].

remove_outdated_snapshots(Name, TS) ->
    ets:select_delete(Name,
                      [{
                         {{sec, '$1'},'_'},
                         [{'<','$1',TS}],
                         [true]
                       }]).

init_new_capture_in_ets(State) ->
    #state{name=Name, capture_id=Id,
           capture_spec={Threshold, Limit}} = State,

    ets:select_delete(Name,
                      [{
                         {{args_res, '_'},'_'},
                         [],
                         [true]
                       }]),
    ets:insert(Name, {capture_spec, Id, Threshold, Limit}).

%% @doc Count the depth of recursion in this process
put_ts_args(Pid, StartTime, Args) ->
    case get({Pid, call_count}) of
        undefined ->
            put({Pid, args}, Args),
            put({Pid, ts}, StartTime),
            put({Pid, call_count}, 1);
        CC ->
            put({Pid, call_count}, CC + 1)
    end.

%% @doc Only return start time of the outermost call
get_ts_args(Pid) ->
    case get({Pid, call_count}) of
        undefined ->
            %% we missed the call of this function
            undefined;
        1 ->
            erase({Pid, call_count}),
            StartTime = erase({Pid, ts}),
            {StartTime, erase({Pid, args})};
        CC when CC > 1 ->
            put({Pid, call_count}, CC - 1),
            undefined
    end.

record_results(Pid, CallTime, Args, Res,
               State = #state{mfa = MFA,
                              name = Name,
                              hdr_ref = Ref,
                              capture_spec = CaptureSpec,
                              capture_counter = Count}) ->

    hdr_histogram:record(Ref, CallTime),

    case CaptureSpec of
        {Threshold, Limit}
          when CallTime > Threshold * 1000 andalso Count =< Limit ->
            ets:insert(Name, {{args_res, Count},
                              {Pid, CallTime, Args, Res}}),
            %% reached limit - turn off args tracing
            Count =:= Limit andalso
                capture_args_trace_off(MFA),
            State#state{capture_counter = Count + 1};
        _ ->
            State
    end.

-spec capture_args_trace_on(xprof:mfaspec()) -> any().
capture_args_trace_on({M, F, {_MSOff, MSOn}}) ->
    erlang:trace_pattern({M, F, '_'}, MSOn, [local]);
capture_args_trace_on(MFA) ->
    MatchSpec = [{'_', [], [{return_trace}, {message, '$_'}]}],
    erlang:trace_pattern(MFA, MatchSpec, [local]).

-spec capture_args_trace_off(xprof:mfaspec()) -> any().
capture_args_trace_off({M, F, {MSOff, _MSOn}}) ->
    erlang:trace_pattern({M, F, '_'}, MSOff, [local]);
capture_args_trace_off(MFA) ->
    MatchSpec = [{'_', [], [{return_trace}, {message, arity}]}],
    erlang:trace_pattern(MFA, MatchSpec, [local]).

-spec trace_mfa_off(xprof:mfaid()) -> any().
trace_mfa_off({M, F, '*'}) ->
    %% FIXME: this will turn off tracing also
    %% for the same function with a given arity
    erlang:trace_pattern({M, F, '_'}, false, [local]);
trace_mfa_off(MFA) ->
    erlang:trace_pattern(MFA, false, [local]).