From 5edfab1ce644ee51cae85529a0adb732010a4ddb Mon Sep 17 00:00:00 2001 From: Knut Nesheim Date: Sun, 25 Sep 2011 17:41:29 +0200 Subject: [PATCH] Initial commit. --- .gitignore | 5 + README | 91 +++++++++++++ bin/start.sh | 11 ++ rebar.config | 4 + src/example_server.erl | 78 +++++++++++ src/gcprof.app.src | 12 ++ src/gcprof.erl | 25 ++++ src/gcprof_aggregator.erl | 105 +++++++++++++++ src/gcprof_app.erl | 16 +++ src/gcprof_server.erl | 91 +++++++++++++ src/gcprof_sup.erl | 32 +++++ src/gcprof_tracer.erl | 172 ++++++++++++++++++++++++ test/gcprof_aggregator_tests.erl | 22 ++++ test/gcprof_server_tests.erl | 86 ++++++++++++ test/gcprof_tracer_tests.erl | 219 +++++++++++++++++++++++++++++++ 15 files changed, 969 insertions(+) create mode 100644 .gitignore create mode 100644 README create mode 100755 bin/start.sh create mode 100644 rebar.config create mode 100644 src/example_server.erl create mode 100644 src/gcprof.app.src create mode 100644 src/gcprof.erl create mode 100644 src/gcprof_aggregator.erl create mode 100644 src/gcprof_app.erl create mode 100644 src/gcprof_server.erl create mode 100644 src/gcprof_sup.erl create mode 100644 src/gcprof_tracer.erl create mode 100644 test/gcprof_aggregator_tests.erl create mode 100644 test/gcprof_server_tests.erl create mode 100644 test/gcprof_tracer_tests.erl diff --git a/.gitignore b/.gitignore new file mode 100644 index 0000000..e24092f --- /dev/null +++ b/.gitignore @@ -0,0 +1,5 @@ +*~ +ebin +.eunit +erl_crash.dump +deps \ No newline at end of file diff --git a/README b/README new file mode 100644 index 0000000..83c09f5 --- /dev/null +++ b/README @@ -0,0 +1,91 @@ +# gcprof - garbage collection profiler + +gcprof is a tool to measure garbage collection in a production +system. For every message a process receives, gcprof tells you how +much time was spent in garbage collection and how many passes was +done. + + +## How does it work + +`gcprof:trace(pid(), identity_f())` triggers tracing of garbage +collection in the specified process. Every time the process receives a +message, the resulting garbage collections is associated with that +message. The identity fun is used to identify that message. + +The runtime of garbage collections is aggregated and grouped on the +identity. The results can be retrieved by calling +`gcprof_aggregator:get_stats/0`. This will reset the current stats, so +it is suitable for periodic polling. + +The convenience method `gcprof:trace_me(identity_f())` can be used +from within the process you wish to trace. + + +## Identity + +The identity fun is given the message your process received and must +produce an identity. The results will be grouped by identity, so it +makes sense to keep the number of unique ids low. The identity will be +the `key` in `gcprof_aggregator:get_stats/0`. + +For example: + + fun ({'$gen_call', {_, _}, do_some_stuff}) -> + my_identity; + ({'$gen_call', {_, _}, {request, Arg1, Arg2}) -> + {request, Arg1}; + (init) -> + init; + (_) -> + undefined + end + +There is one special message you may also handle and that is +`init`. Any garbage collection done after triggering the trace, but +before your process received any messages is associated with this +identity. Please note that as starting a trace is asynchronous, some +information might be lost. + + +## Sampling + +As you may not want to trace all processes executing the code that +triggers tracing, there is a very simple way of deciding which +processes to sample. + +Example: + + IdentityF = fun ..., + Id = 1000000, + Divisor = 100, + gcprof:sample_me(IdentityF, Id rem Divisor) + +`sample_me/2` only samples if the second argument is 0. So in the +above case, given an even distribution of ids, only 1% will of the +processes be sampled. + + +## Impact on your system + +`gcprof:trace/2` uses a `gen_server:cast/2` under the hood so your +process do not have to wait for gcprof. This also means that if gcprof +is not running, nothing happens. + +If gcprof would crash, the processes would be restarted. When the +gcprof tracer process goes away, the VM stops whatever traces was +active. + + +## Ideas for the future + +At the moment, there are some race conditions in some of the tests +that makes them occasionally fail. This should be fixed. + +To trace code without modifying the target, a future version of gcprof +could trace a specific function call and start tracing of the process +invoking that function. Superuseful for the `init/1` gen_server +callback for example. + + + diff --git a/bin/start.sh b/bin/start.sh new file mode 100755 index 0000000..806cde8 --- /dev/null +++ b/bin/start.sh @@ -0,0 +1,11 @@ +#!/bin/sh +SCRIPT_PATH=`dirname $0` +cd $SCRIPT_PATH/.. + +erl -pa deps/*/ebin ebin \ + -boot start_sasl \ + -s gcprof \ + -K true \ + +P 1000000 \ + +A 8 \ + -name gcprof@$(hostname) \ No newline at end of file diff --git a/rebar.config b/rebar.config new file mode 100644 index 0000000..3d21c0b --- /dev/null +++ b/rebar.config @@ -0,0 +1,4 @@ +{deps, [ + {basho_stats, "1.0.1", {git, "git://github.com/basho/basho_stats.git", "master"}} +]}. +{cover_enabled, true}. \ No newline at end of file diff --git a/src/example_server.erl b/src/example_server.erl new file mode 100644 index 0000000..b2c6c08 --- /dev/null +++ b/src/example_server.erl @@ -0,0 +1,78 @@ +-module(example_server). + +-behaviour(gen_server). + +%% API +-export([run/2]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +-define(SERVER, ?MODULE). + +-record(state, {}). + +%%%=================================================================== +%%% API +%%%=================================================================== + +start(Id) -> + gen_server:start(?MODULE, [Id], []). + +req(Pid) -> + gen_server:call(Pid, create_garbage). + +run(Servers, Requests) -> + RunF = fun(Id) -> + {ok, Pid} = start(Id), + timer:sleep(1), + [req(Pid) || _ <- lists:seq(1, Requests)], + exit(Pid, kill) + end, + + lists:foreach(fun (Id) -> + spawn(fun () -> RunF(Id) end) + end, lists:seq(1, Servers)). + + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([Id]) -> + gcprof:sample_me(fun identity/1, Id rem 10), + {ok, #state{}}. + +handle_call(create_garbage, _From, State) -> + Pid = spawn(fun() -> + receive _ -> ok + end + end), + L = lists:seq(1, 100000), + Pid ! L, + {reply, ok, State}; + +handle_call(_Request, _From, State) -> + Reply = ok, + {reply, Reply, State}. + +handle_cast(_Msg, State) -> + {noreply, State}. + +handle_info(_Info, State) -> + {noreply, State}. + +terminate(_Reason, _State) -> + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== + +identity({'$gen_call', {_, _}, create_garbage}) -> create_garbage; +identity(_) -> undefined. + diff --git a/src/gcprof.app.src b/src/gcprof.app.src new file mode 100644 index 0000000..8a16904 --- /dev/null +++ b/src/gcprof.app.src @@ -0,0 +1,12 @@ +{application, gcprof, + [ + {description, ""}, + {vsn, "1"}, + {registered, []}, + {applications, [ + kernel, + stdlib + ]}, + {mod, { gcprof_app, []}}, + {env, []} + ]}. diff --git a/src/gcprof.erl b/src/gcprof.erl new file mode 100644 index 0000000..cd6b986 --- /dev/null +++ b/src/gcprof.erl @@ -0,0 +1,25 @@ +-module(gcprof). +-export([start/0, stop/0]). +-export([trace/2, trace_me/1, sample_me/2]). + +start() -> application:start(gcprof). +stop() -> application:stop(gcprof). + +%% @doc: Starts tracing garbage collections in the given +%% process. Note: gen_server:cast is used, so at some point in the +%% future, tracing *might* start. +trace(Pid, IdentityF) -> + gen_server:cast(gcprof_server, {start_trace, Pid, IdentityF}). + +%% @doc: Starts tracing garbage collections in the calling process. +trace_me(IdentityF) -> + trace(self(), IdentityF). + +%% @doc: Traces the calling process if the second argument is +%% 0. Allows tracing if the result of a modulo operation is 0. +sample_me(IdentityF, 0) -> + trace(self(), IdentityF); +sample_me(_, _) -> + ok. + + diff --git a/src/gcprof_aggregator.erl b/src/gcprof_aggregator.erl new file mode 100644 index 0000000..9590907 --- /dev/null +++ b/src/gcprof_aggregator.erl @@ -0,0 +1,105 @@ +-module(gcprof_aggregator). + +-behaviour(gen_server). + +%% API +-export([start_link/0, results/4, get_stats/0]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +-define(SERVER, ?MODULE). +-define(NEW_HISTOGRAM, basho_stats_histogram:new(0, 1000000, 1000000)). + +-record(state, {}). + +%%%=================================================================== +%%% API +%%%=================================================================== + +start_link() -> + gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). + +results(Pid, Identity, Runtime, Invocations) -> + gen_server:cast(?MODULE, {results, Pid, Identity, Runtime, Invocations}). + +get_stats() -> + gen_server:call(?MODULE, get_stats). + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([]) -> + {ok, #state{}}. + +handle_call(get_stats, _From, State) -> + {reply, {ok, do_get_stats()}, State}; + +handle_call(_Request, _From, State) -> + Reply = ok, + {reply, Reply, State}. + +handle_cast({results, _Pid, Identity, Runtime, Invocations}, State) -> + ok = update_histogram({Identity, runtime}, Runtime), + ok = update_histogram({Identity, invocations}, Invocations), + %%ok = update_histogram({Pid, runtime}, Runtime), + %%ok = update_histogram({Pid, invocations}, Invocations), + {noreply, State}; + +handle_cast(_Msg, State) -> + {noreply, State}. + + +handle_info(_Info, State) -> + {noreply, State}. + +terminate(_Reason, _State) -> + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== + +get_or_create_histogram(Key) -> + case get(Key) of + undefined -> ?NEW_HISTOGRAM; + {histogram, Value} -> Value + end. + +update_histogram(Key, Value) -> + Hist = get_or_create_histogram(Key), + NewHist = basho_stats_histogram:update(Value, Hist), + erlang:put(Key, {histogram, NewHist}), + ok. + + +do_get_stats() -> + Ts = lists:filter(fun ({_, {histogram, Hist}}) -> + basho_stats_histogram:observations(Hist) =/= 0; + (_) -> + false + end, get()), + [erlang:put(Key, {histogram, ?NEW_HISTOGRAM}) || {Key, _Value} <- Ts], + lists:map(fun (T) -> format_timing(T) end, Ts). + +format_timing({Identity, {histogram, Hist}}) -> + {Min, Mean, Max, _, SD} = + basho_stats_histogram:summary_stats(Hist), + + [ + {key, Identity}, + {observations, basho_stats_histogram:observations(Hist)}, + {min, Min}, + {mean, Mean}, + {max, Max}, + {sd, SD}, + {quantile_25, basho_stats_histogram:quantile(0.250, Hist)}, + {quantile_75, basho_stats_histogram:quantile(0.750, Hist)}, + {quantile_99, basho_stats_histogram:quantile(0.990, Hist)}, + {quantile_999, basho_stats_histogram:quantile(0.999, Hist)} + ]. diff --git a/src/gcprof_app.erl b/src/gcprof_app.erl new file mode 100644 index 0000000..56c7374 --- /dev/null +++ b/src/gcprof_app.erl @@ -0,0 +1,16 @@ +-module(gcprof_app). + +-behaviour(application). + +%% Application callbacks +-export([start/2, stop/1]). + +%% =================================================================== +%% Application callbacks +%% =================================================================== + +start(_StartType, _StartArgs) -> + gcprof_sup:start_link(). + +stop(_State) -> + ok. diff --git a/src/gcprof_server.erl b/src/gcprof_server.erl new file mode 100644 index 0000000..05d7042 --- /dev/null +++ b/src/gcprof_server.erl @@ -0,0 +1,91 @@ +-module(gcprof_server). + +-behaviour(gen_server). + +%% API +-export([start_link/0]). + +%% gen_server callbacks +-export([init/1, handle_call/3, handle_cast/2, handle_info/2, + terminate/2, code_change/3]). + +-define(SERVER, ?MODULE). + +-record(state, {tracer, identity_fs = orddict:new(), processes = ordsets:new()}). + +%%%=================================================================== +%%% API +%%%=================================================================== + +start_link() -> + gen_server:start_link({local, ?SERVER}, ?MODULE, [], []). + +%%%=================================================================== +%%% gen_server callbacks +%%%=================================================================== + +init([]) -> + {ok, #state{tracer = gcprof_tracer:start_link(self())}}. + +handle_call(_Request, _From, State) -> + Reply = ok, + {reply, Reply, State}. + +handle_cast({start_trace, Pid, IdentityF}, State) -> + case catch(erlang:trace(Pid, true, ['receive', timestamp, garbage_collection])) of + {'EXIT', {badarg, _}} -> + %% Process died before we could start tracing + error_logger:info_msg("badarg while setting up trace~n"), + {noreply, State}; + 1 -> + erlang:monitor(process, Pid), + State#state.tracer ! {start, Pid}, + NewIdentityFs = orddict:store(Pid, IdentityF, State#state.identity_fs), + NewProcesses = ordsets:add_element(Pid, State#state.processes), + {noreply, State#state{identity_fs = NewIdentityFs, processes = NewProcesses}} + end; + +handle_cast(_Msg, State) -> + {noreply, State}. + +handle_info(TraceMsg, State) when element(1, TraceMsg) =:= trace_ts -> + case State#state.tracer of + undefined -> + Tracer = gcprof_tracer:start_link(self()), + Tracer ! TraceMsg, + erlang:monitor(process, Tracer), + {noreply, State#state{tracer = Tracer}}; + Tracer -> + Tracer ! TraceMsg, + {noreply, State} + end; + +handle_info({'DOWN', _, process, Pid, _}, State) -> + case ordsets:is_element(Pid, State#state.processes) of + true -> + State#state.tracer ! {down, Pid}, + {noreply, State#state{processes = ordsets:del_element(Pid, State#state.processes)}}; + false -> + {noreply, State} + end; + + +handle_info({results, Pid, Message, Runtime, Invocations}, State) -> + IdentityF = orddict:fetch(Pid, State#state.identity_fs), + gcprof_aggregator:results(Pid, IdentityF(Message), Runtime, Invocations), + %%NewIdentityFs = orddict:erase(Pid, State#state.identity_fs), + {noreply, State}; + +handle_info(_Info, State) -> + error_logger:info_msg("got info: ~p~n", [_Info]), + {noreply, State}. + +terminate(_Reason, _State) -> + ok. + +code_change(_OldVsn, State, _Extra) -> + {ok, State}. + +%%%=================================================================== +%%% Internal functions +%%%=================================================================== diff --git a/src/gcprof_sup.erl b/src/gcprof_sup.erl new file mode 100644 index 0000000..cdfd970 --- /dev/null +++ b/src/gcprof_sup.erl @@ -0,0 +1,32 @@ + +-module(gcprof_sup). + +-behaviour(supervisor). + +%% API +-export([start_link/0]). + +%% Supervisor callbacks +-export([init/1]). + +%% Helper macro for declaring children of supervisor +-define(CHILD(I, Type), {I, {I, start_link, []}, permanent, 5000, Type, [I]}). + +%% =================================================================== +%% API functions +%% =================================================================== + +start_link() -> + supervisor:start_link({local, ?MODULE}, ?MODULE, []). + +%% =================================================================== +%% Supervisor callbacks +%% =================================================================== + +init([]) -> + Children = [ + ?CHILD(gcprof_server, worker), + ?CHILD(gcprof_aggregator, worker) + ], + {ok, {{one_for_one, 5, 10}, Children}}. + diff --git a/src/gcprof_tracer.erl b/src/gcprof_tracer.erl new file mode 100644 index 0000000..a4d82a7 --- /dev/null +++ b/src/gcprof_tracer.erl @@ -0,0 +1,172 @@ +-module(gcprof_tracer). + +-export([start_link/1, loop/2, do_receive/1]). + +-define(PROCESS_INTERVAL, 100). + + +start_link(Parent) -> + spawn_link(fun() -> + loop(Parent, []) + end). + +loop(Parent, Acc) -> + erlang:send_after(?PROCESS_INTERVAL, self(), process), + Messages = lists:reverse(do_receive(lists:reverse(Acc))), + + NewMessages = case process(Messages) of + {GCData, NewM} -> + send_results(Parent, GCData), + NewM + end, + ?MODULE:loop(Parent, NewMessages). + + + +%% @doc: Consumes trace messages from the queue. +process(Messages) -> + process(Messages, [], []). + + +process([{start, Pid} = Msg| Rest], Result, Q) -> + %% A process just started tracing. If there are any gc messages + %% before the first receive, these should be associated with the + %% starting of the process to allow tracing gc in the init of a + %% gen_server for example. + + case catch(find_gcs_until_receive(Rest, Pid)) of + receive_not_found -> + %% No receive yet for this process, do nothing and wait + %% for more data + process(Rest, Result, [Msg | Q]); + [] -> + %% No gcs found, but first receive found, discard the + %% starting message + process(Rest, Result, Q); + GCs when is_list(GCs) -> + %% Associated gcs with the starting message + NewRest = delete_element(GCs, Rest), + process(NewRest, [{Msg, GCs} | Result], Q) + end; + + +process([{trace_ts, Pid, 'receive', _, _} = Msg| Rest], Result, Q) -> + %% The process received a message. Find all gcs until the next + %% receive. + + case catch(find_gcs_until_receive(Rest, Pid)) of + receive_not_found -> + %% No next receive found, do nothing and wait for more + %% data + process(Rest, Result, [Msg | Q]); + + GCs when is_list(GCs) -> + NewRest = delete_element(GCs, Rest), + + %% If the process shutdown after the current receive, the + %% last element in GCs will be the "down" message. Delete + %% it. + NewGCs = lists:delete({down, Pid}, GCs), + + process(NewRest, [{Msg, NewGCs} | Result], Q) + end; + +process([M | Rest], Result, Q) -> + process(Rest, Result, [M | Q]); + +process([], Result, Q) -> + {lists:reverse(Result), lists:reverse(Q)}. + + + +%% @doc: Deletes the given elements from the list in a single pass +%% through the list. The elements must occur in the same order as they +%% occur in the list. +delete_element([E | Es], [E | T]) -> + delete_element(Es, T); +delete_element(Es, [H | T]) -> + [H | delete_element(Es, T)]; +delete_element([], L) -> + L. + + + + +%% @doc: Returns a list of gc trace messages for the given pid until +%% the next receive or down message. +find_gcs_until_receive([], _Pid) -> + throw(receive_not_found); + +find_gcs_until_receive([{trace_ts, Pid, GCType, _, _} = Msg | Messages], Pid) + when GCType =:= gc_start; + GCType =:= gc_end -> + [Msg | find_gcs_until_receive(Messages, Pid)]; + +find_gcs_until_receive([{trace_ts, Pid, 'receive', _, _} | _], Pid) -> + []; +find_gcs_until_receive([{down, Pid} = Msg | _], Pid) -> + [Msg]; + +find_gcs_until_receive([_ | Messages], Pid) -> + find_gcs_until_receive(Messages, Pid). + + + + +%% @doc: Receive loop. When the message 'process' is received, the +%% current queue of trace messages is returned. Anything else is +%% received without filtering, to not give any preference to any type +%% of message which would mess up the ordering of trace messages. +do_receive(Messages) -> + receive + process -> + Messages; + Msg -> + ?MODULE:do_receive([Msg | Messages]) + end. + + +send_results(Parent, GCData) -> + lists:foreach(fun ({Receive, GCs}) -> + {Pid, Message} = case Receive of + {trace_ts, P, 'receive', M, _} -> + {P, M}; + {start, P} -> + {P, init} + end, + + Pairs = find_gc_pairs(GCs), + Runtime = gc_time(Pairs), + Invocations = length(Pairs), + Parent ! {results, Pid, Message, Runtime, Invocations} + end, GCData). + + +gc_time(GCs) -> + lists:foldl(fun ({StartMsg, EndMsg}, Acc) -> + timer:now_diff(element(5, EndMsg), element(5, StartMsg)) + Acc + end, 0, GCs). + +%% heap_reclaimed(GCs) -> +%% lists:foldl(fun ({StartMsg, EndMsg}, Acc) -> +%% StartInfo = element(4, StartMsg), +%% EndInfo = element(4, EndMsg), + +%% {heap_size, StartHeap} = lists:keyfind(heap_size, 1, StartInfo), +%% {heap_size, EndHeap} = lists:keyfind(heap_size, 1, EndInfo), + +%% (StartHeap - EndHeap) + Acc +%% end, 0, GCs). + + +%% @doc: Returns a list of {Start, End} garbage collection +%% messages. Any excess gc_start at the end that has no gc_end is +%% discarded. +find_gc_pairs([]) -> + []; + +find_gc_pairs([Start | [End | Rest]]) -> + [{Start, End} | find_gc_pairs(Rest)]; + +find_gc_pairs([_ | _Rest]) -> + []. diff --git a/test/gcprof_aggregator_tests.erl b/test/gcprof_aggregator_tests.erl new file mode 100644 index 0000000..a561800 --- /dev/null +++ b/test/gcprof_aggregator_tests.erl @@ -0,0 +1,22 @@ +-module(gcprof_aggregator_tests). + +-include_lib("eunit/include/eunit.hrl"). + +aggregator_test() -> + {ok, Pid} = gcprof_aggregator:start_link(), + gcprof_aggregator:results(self(), create_garbage, 1000, 100), + + {ok, [Invocations, Runtime]} = gcprof_aggregator:get_stats(), + + ?assertEqual({observations, 1}, lists:keyfind(observations, 1, Invocations)), + ?assertEqual({key, {create_garbage, invocations}}, lists:keyfind(key, 1, Invocations)), + ?assertEqual({mean, 100.0}, lists:keyfind(mean, 1, Invocations)), + + ?assertEqual({observations, 1}, lists:keyfind(observations, 1, Runtime)), + ?assertEqual({key, {create_garbage, runtime}}, lists:keyfind(key, 1, Runtime)), + ?assertEqual({mean, 1000.0}, lists:keyfind(mean, 1, Runtime)), + + unlink(Pid), + exit(Pid, kill). + + diff --git a/test/gcprof_server_tests.erl b/test/gcprof_server_tests.erl new file mode 100644 index 0000000..399a44a --- /dev/null +++ b/test/gcprof_server_tests.erl @@ -0,0 +1,86 @@ +-module(gcprof_server_tests). + +-include_lib("eunit/include/eunit.hrl"). + + +server_test_() -> + {foreach, + fun() -> + application:start(gcprof) + end, + fun(_) -> + application:stop(gcprof) + end, + [ + ?_test(simple_with_shutdown()), + ?_test(garbage_in_init()), + ?_test(example_single()) + ] + }. + + +simple_with_shutdown() -> + ?assertEqual({ok, []}, gcprof_aggregator:get_stats()), + + IdentityF = fun (garbage) -> + garbage; + (_) -> + undefined + end, + + Pid = spawn(fun() -> + receive + garbage -> + lists:seq(1, 1000) + end + end), + gcprof:trace(Pid, IdentityF), + %% Allow time for registering with gcprof_server + timer:sleep(10), + Pid ! garbage, + %% Allow time for processing interval to trigger + timer:sleep(200), + + {ok, Stats} = gcprof_aggregator:get_stats(), + [Invocations, Runtime] = lists:sort(Stats), + + ?assertEqual({key, {garbage, runtime}}, lists:keyfind(key, 1, Runtime)), + ?assertEqual({observations, 1}, lists:keyfind(observations, 1, Runtime)), + + ?assertEqual({key, {garbage, invocations}}, lists:keyfind(key, 1, Invocations)), + ?assertEqual({observations, 1}, lists:keyfind(observations, 1, Invocations)). + + +garbage_in_init() -> + ?assertEqual({ok, []}, gcprof_aggregator:get_stats()), + + IdentityF = fun (init) -> + init; + (_) -> undefined + end, + + Pid = spawn(fun () -> + gcprof:trace_me(IdentityF), + erlang:yield(), + lists:seq(1, 10000) + end), + Pid ! garbage, + timer:sleep(200), + {ok, [Invocations, Runtime]} = gcprof_aggregator:get_stats(), + + ?assertEqual({key, {init, runtime}}, lists:keyfind(key, 1, Runtime)), + ?assertEqual({observations, 1}, lists:keyfind(observations, 1, Runtime)), + + ?assertEqual({key, {init, invocations}}, lists:keyfind(key, 1, Invocations)), + ?assertEqual({observations, 1}, lists:keyfind(observations, 1, Invocations)). + + +example_single() -> + ?assertEqual({ok, []}, gcprof_aggregator:get_stats()), + example_server:run(1, 2), + timer:sleep(200). + + + + + diff --git a/test/gcprof_tracer_tests.erl b/test/gcprof_tracer_tests.erl new file mode 100644 index 0000000..a867aab --- /dev/null +++ b/test/gcprof_tracer_tests.erl @@ -0,0 +1,219 @@ +-module(gcprof_tracer_tests). + +-include_lib("eunit/include/eunit.hrl"). + + +tracer_test() -> + Tracer = gcprof_tracer:start_link(self()), + lists:foreach(fun (M) -> Tracer ! M end, messages()), + + receive + {results, Pid, Message, Runtime, Invocations} -> + ?assertEqual(self(), Pid), + ?assertEqual(1090, Runtime), + ?assertEqual(2, Invocations), + ?assertEqual(create_garbage, (identity_f())(Message)) + end. + +process_cycle_test() -> + Tracer = gcprof_tracer:start_link(self()), + lists:foreach(fun (M) -> Tracer ! M end, messages_with_init_and_shutdown()), + + fun() -> + receive + {results, Pid, Message, Runtime, Invocations} -> + ?assertEqual(self(), Pid), + ?assertEqual(9, Runtime), + ?assertEqual(1, Invocations), + ?assertEqual(init, (identity_f())(Message)) + end + end(), + + fun() -> + receive + {results, Pid, Message, Runtime, Invocations} -> + ?assertEqual(self(), Pid), + ?assertEqual(1081, Runtime), + ?assertEqual(1, Invocations), + ?assertEqual(create_garbage, (identity_f())(Message)) + end + end(), + + fun() -> + receive + {results, Pid, Message, Runtime, Invocations} -> + ?assertEqual(self(), Pid), + ?assertEqual(1081, Runtime), + ?assertEqual(1, Invocations), + ?assertEqual(create_garbage, (identity_f())(Message)) + end + end(). + + + + +identity_f() -> + fun ({'$gen_call', {_, _}, create_garbage}) -> + create_garbage; + (init) -> + init; + (_) -> + undefined + end. + + +messages() -> + Pid = self(), + [{trace_ts,Pid,'receive', + {'$gen_call',{Pid,make_ref()},create_garbage}, + {1316,876550,919801}}, + {trace_ts,Pid,gc_start, + [{old_heap_block_size,0}, + {heap_block_size,233}, + {mbuf_size,0}, + {recent_size,0}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,220}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,919843}}, + {trace_ts,Pid,gc_end, + [{old_heap_block_size,0}, + {heap_block_size,233}, + {mbuf_size,0}, + {recent_size,141}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,141}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,919852}}, + {trace_ts,Pid,gc_start, + [{old_heap_block_size,0}, + {heap_block_size,17711}, + {mbuf_size,0}, + {recent_size,11005}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,17693}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,920573}}, + {trace_ts,Pid,gc_end, + [{old_heap_block_size,28657}, + {heap_block_size,17711}, + {mbuf_size,0}, + {recent_size,0}, + {stack_size,12}, + {old_heap_size,11005}, + {heap_size,6688}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,921654}}, + {trace_ts,Pid,'receive', + {'$gen_call',{Pid,make_ref()},create_garbage}, + {1316,876550,921690}}]. + + +messages_with_init_and_shutdown() -> + Pid = self(), + [ + {start, Pid}, + {trace_ts,Pid,gc_start, + [{old_heap_block_size,0}, + {heap_block_size,233}, + {mbuf_size,0}, + {recent_size,0}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,220}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,919843}}, + {trace_ts,Pid,gc_end, + [{old_heap_block_size,0}, + {heap_block_size,233}, + {mbuf_size,0}, + {recent_size,141}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,141}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,919852}}, + {trace_ts,Pid,'receive', + {'$gen_call',{Pid,make_ref()},create_garbage}, + {1316,876550,919801}}, + {trace_ts,Pid,gc_start, + [{old_heap_block_size,0}, + {heap_block_size,17711}, + {mbuf_size,0}, + {recent_size,11005}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,17693}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,920573}}, + {trace_ts,Pid,gc_end, + [{old_heap_block_size,28657}, + {heap_block_size,17711}, + {mbuf_size,0}, + {recent_size,0}, + {stack_size,12}, + {old_heap_size,11005}, + {heap_size,6688}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,921654}}, + {trace_ts,Pid,'receive', + {'$gen_call',{Pid,make_ref()},create_garbage}, + {1316,876550,921690}}, + {trace_ts,Pid,gc_start, + [{old_heap_block_size,0}, + {heap_block_size,17711}, + {mbuf_size,0}, + {recent_size,11005}, + {stack_size,12}, + {old_heap_size,0}, + {heap_size,17693}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,920573}}, + {trace_ts,Pid,gc_end, + [{old_heap_block_size,28657}, + {heap_block_size,17711}, + {mbuf_size,0}, + {recent_size,0}, + {stack_size,12}, + {old_heap_size,11005}, + {heap_size,6688}, + {bin_vheap_size,0}, + {bin_vheap_block_size,46368}, + {bin_old_vheap_size,0}, + {bin_old_vheap_block_size,46368}], + {1316,876550,921654}}, + {down, Pid}]. + + + +