%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 2018. All Rights Reserved.
%%
%% Licensed under the Apache License, Version 2.0 (the "License");
%% you may not use this file except in compliance with the License.
%% You may obtain a copy of the License at
%%
%% http://www.apache.org/licenses/LICENSE-2.0
%%
%% Unless required by applicable law or agreed to in writing, software
%% distributed under the License is distributed on an "AS IS" BASIS,
%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
%% See the License for the specific language governing permissions and
%% limitations under the License.
%%
%% %CopyrightEnd%
%%
-module(logger_bench_SUITE).
-compile(export_all).
%%%-----------------------------------------------------------------
%%% To include lager tests, add paths to lager and goldrush
%%% (goldrush is a dependency inside the lager repo)
%%%
%%% To print data to .csv files, add the following to a config file:
%%% {print_csv,[{console_handler,[{path,"/some/dir/"}]}]}.
%%%
%%%-----------------------------------------------------------------
-include_lib("common_test/include/ct.hrl").
-include_lib("common_test/include/ct_event.hrl").
-include_lib("kernel/include/logger.hrl").
-include_lib("kernel/src/logger_internal.hrl").
-define(msg,lists:flatten(string:pad("Log from "++atom_to_list(?FUNCTION_NAME)++
":"++integer_to_list(?LINE),
80,trailing,$*))).
-define(meta,#{mfa=>{?MODULE,?FUNCTION_NAME,?FUNCTION_ARITY},
pid=>self()}).
-define(NO_COMPARE,[profile]).
-define(TIMES,100000).
suite() ->
[{timetrap,{seconds,120}}].
init_per_suite(Config) ->
DataDir = ?config(data_dir,Config),
have_lager() andalso make(DataDir),
Config.
end_per_suite(_Config) ->
ok.
init_per_group(Group, Config) ->
H = remove_all_handlers(),
do_init_per_group(Group),
[{handlers,H}|Config].
do_init_per_group(minimal_handler) ->
ok = logger:add_handler(?MODULE,?MODULE,#{level=>error,filter_default=>log});
do_init_per_group(console_handler) ->
ok = logger:add_handler(?MODULE,logger_std_h,
#{filter_default=>stop,
filters=>?DEFAULT_HANDLER_FILTERS,
logger_std_h=>#{type=>standard_io,
toggle_sync_qlen => ?TIMES+1,
drop_new_reqs_qlen => ?TIMES+2,
flush_reqs_qlen => ?TIMES+3,
enable_burst_limit => false}}),
have_lager() andalso lager_helper:start(),
ok.
end_per_group(Group, Config) ->
case ?config(saved_config,Config) of
{_,[{bench,Bench}]} ->
print_compare_chart(Group,Bench);
_ ->
ok
end,
add_all_handlers(?config(handlers,Config)),
do_end_per_group(Group).
do_end_per_group(minimal_handler) ->
ok = logger:remove_handler(?MODULE);
do_end_per_group(console_handler) ->
ok = logger:remove_handler(?MODULE),
have_lager() andalso lager_helper:stop(),
ok.
init_per_testcase(_TestCase, Config) ->
Config.
end_per_testcase(Case, Config) ->
try apply(?MODULE,Case,[cleanup,Config])
catch error:undef -> ok
end,
wait_for_handlers(),
ok.
wait_for_handlers() ->
wait_for_handler(?MODULE),
wait_for_handler(lager_event).
wait_for_handler(Handler) ->
case whereis(Handler) of
undefined ->
io:format("~p: noproc1",[Handler]),
ok;
Pid ->
case process_info(Pid,message_queue_len) of
{_,0} ->
io:format("~p: queue=~p",[Handler,0]),
ok;
{_,Q} ->
io:format("~p: queue=~p",[Handler,Q]),
timer:sleep(2000),
wait_for_handler(Handler);
undefined ->
io:format("~p: noproc2",[Handler]),
ok
end
end.
groups() ->
[{minimal_handler,[],[log,
log_drop,
log_drop_by_handler,
macro,
macro_drop,
macro_drop_by_handler,
error_logger,
error_logger_drop,
error_logger_drop_by_handler
]},
{console_handler,[],[%profile,
log,
log_drop,
log_drop_by_handler,
%% log_handler_complete,
macro,
macro_drop,
macro_drop_by_handler,
%% macro_handler_complete,
error_logger,
error_logger_drop,
error_logger_drop_by_handler%% ,
%% error_logger_handler_complete
] ++ lager_cases()}
].
lager_cases() ->
case have_lager() of
true ->
[lager_log,
lager_log_drop,
lager_log_drop_by_handler,
%% lager_log_handler_complete,
lager_parsetrans,
lager_parsetrans_drop,
lager_parsetrans_drop_by_handler%% ,
%% lager_parsetrans_handler_complete
];
false ->
[]
end.
all() ->
[{group,minimal_handler},
{group,console_handler}
].
log(Config) ->
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [error,?msg], Times).
log_drop(Config) ->
Times = ?TIMES*100,
ok = logger:set_logger_config(level,error),
run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [info,?msg], Times).
log_drop(cleanup,_Config) ->
ok = logger:set_logger_config(level,info).
log_drop_by_handler(Config) ->
Times = ?TIMES,
%% just ensure correct levels
ok = logger:set_logger_config(level,info),
ok = logger:set_handler_config(?MODULE,level,error),
run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [info,?msg], Times).
log_handler_complete(Config) ->
ok = logger:set_handler_config(?MODULE,formatter,
{?MODULE,?DEFAULT_FORMAT_CONFIG}),
handler_complete(Config, ?FUNCTION_NAME, fun do_log_func/2, [error,?msg]).
log_handler_complete(cleanup,_Config) ->
ok=logger:set_handler_config(?MODULE,formatter,
{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}).
macro(Config) ->
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun do_log_macro/2,[error,?msg], Times).
macro_drop(Config) ->
Times = ?TIMES*100,
ok = logger:set_logger_config(level,error),
run_benchmark(Config,?FUNCTION_NAME,fun do_log_macro/2,[info,?msg], Times).
macro_drop(cleanup,_Config) ->
ok = logger:set_logger_config(level,info).
macro_drop_by_handler(Config) ->
Times = ?TIMES,
%% just ensure correct levels
ok = logger:set_logger_config(level,info),
ok = logger:set_handler_config(?MODULE,level,error),
run_benchmark(Config,?FUNCTION_NAME,fun do_log_macro/2, [info,?msg], Times).
macro_handler_complete(Config) ->
ok = logger:set_handler_config(?MODULE,formatter,
{?MODULE,?DEFAULT_FORMAT_CONFIG}),
handler_complete(Config, ?FUNCTION_NAME, fun do_log_macro/2, [error,?msg]).
macro_handler_complete(cleanup,_Config) ->
ok=logger:set_handler_config(?MODULE,formatter,
{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}).
error_logger(Config) ->
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun do_error_logger/2, [error,?msg], Times).
error_logger_drop(Config) ->
Times = ?TIMES*100,
ok = logger:set_logger_config(level,error),
run_benchmark(Config,?FUNCTION_NAME,fun do_error_logger/2, [info,?msg], Times).
error_logger_drop(cleanup,_Config) ->
ok = logger:set_logger_config(level,info).
error_logger_drop_by_handler(Config) ->
Times = ?TIMES,
%% just ensure correct levels
ok = logger:set_logger_config(level,info),
ok = logger:set_handler_config(?MODULE,level,error),
run_benchmark(Config,?FUNCTION_NAME,fun do_log_func/2, [info,?msg], Times).
error_logger_handler_complete(Config) ->
ok = logger:set_handler_config(?MODULE,formatter,
{?MODULE,?DEFAULT_FORMAT_CONFIG}),
handler_complete(Config, ?FUNCTION_NAME, fun do_error_logger/2, [error,?msg]).
error_logger_handler_complete(cleanup,_Config) ->
ok=logger:set_handler_config(?MODULE,formatter,
{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}).
lager_log(Config) ->
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_func/2, [error,?msg], Times).
lager_log_drop(Config) ->
Times = ?TIMES*100,
run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_func/2, [info,?msg], Times).
lager_log_drop_by_handler(Config) ->
%% This concept does not exist, so doing same as lager_log_drop/1
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_func/2, [info,?msg], Times).
lager_log_handler_complete(Config) ->
handler_complete(Config, ?FUNCTION_NAME, fun lager_helper:do_func/2, [error,?msg]).
lager_parsetrans(Config) ->
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_parsetrans/2, [error,?msg], Times).
lager_parsetrans_drop(Config) ->
Times = ?TIMES*100,
run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_parsetrans/2, [info,?msg], Times).
lager_parsetrans_drop_by_handler(Config) ->
%% This concept does not exist, so doing same as lager_parsetrans_drop/1
Times = ?TIMES,
run_benchmark(Config,?FUNCTION_NAME,fun lager_helper:do_parsetrans/2, [info,?msg], Times).
lager_parsetrans_handler_complete(Config) ->
handler_complete(Config, ?FUNCTION_NAME, fun lager_helper:do_parsetrans/2, [error,?msg]).
profile(Config) ->
Times = ?TIMES,
%% fprof:apply(fun repeated_apply/3,[fun lager_helper:do_func/2,[error,?msg],Times]),
fprof:apply(fun repeated_apply/3,[fun do_log_func/2,[error,?msg],Times]),
ok = fprof:profile(),
ok = fprof:analyse(dest,"../fprof.analyse"),
ok.
%%%-----------------------------------------------------------------
%%% Internal
%% Handler
log(_Log,_Config) ->
ok.
format(Log=#{meta:=#{pid:=Pid}},Config) when is_pid(Pid) ->
String = ?DEFAULT_FORMATTER:format(Log,Config),
Pid ! done,
String;
format(Log=#{meta:=#{pid:=PidStr}},Config) when is_list(PidStr) ->
String = ?DEFAULT_FORMATTER:format(Log,Config),
list_to_pid(PidStr) ! done,
String.
handler_complete(Config, TC, Fun, Args) ->
Times = ?TIMES,
Start = os:perf_counter(microsecond),
repeated_apply(Fun, Args, Times),
MSecs = wait_for_done(Start,Times),
calc_and_report(Config,TC,MSecs,Times).
wait_for_done(Start,0) ->
os:perf_counter(microsecond) - Start;
wait_for_done(Start,N) ->
receive
done ->
wait_for_done(Start,N-1)
after 20000 ->
ct:fail("missing " ++ integer_to_list(N) ++ " replys")
end.
%%%-----------------------------------------------------------------
%%% Benchmark stuff
run_benchmark(Config,Tag,Fun,Args,Times) ->
_ = erlang:apply(Fun, Args), % apply once to ensure level is cached
MSecs = measure_repeated_op(Fun, Args, Times),
%% fprof:profile(),
%% fprof:analyse(dest,"../"++atom_to_list(Tag)++".prof"),
calc_and_report(Config,Tag,MSecs,Times).
measure_repeated_op(Fun, Args, Times) ->
Start = os:perf_counter(microsecond),
%% fprof:apply(fun repeated_apply/3, [Fun, Args, Times]),
repeated_apply(Fun, Args, Times),
os:perf_counter(microsecond) - Start.
repeated_apply(_F, _Args, Times) when Times =< 0 ->
ok;
repeated_apply(F, Args, Times) ->
erlang:apply(F, Args),
repeated_apply(F, Args, Times - 1).
calc_and_report(Config,Tag,MSecs,Times) ->
IOPS = trunc(Times * (1000000 / MSecs)),
ct_event:notify(#event{ name = benchmark_data, data = [{value,IOPS}] }),
ct:print("~p:~n~p IOPS, ~p us", [Tag, IOPS, MSecs]),
ct:comment("~p IOPS, ~p us", [IOPS, MSecs]),
Bench = case ?config(saved_config,Config) of
{_,[{bench,B}]} -> B;
undefined -> []
end,
{save_config,[{bench,[{Tag,IOPS,MSecs}|Bench]}]}.
remove_all_handlers() ->
#{handlers:=Hs} = logger:i(),
[logger:remove_handler(Id) || {Id,_,_} <- Hs],
Hs.
add_all_handlers(Hs) ->
[logger:add_handler(Id,Mod,Config) || {Id,Mod,Config} <- Hs],
ok.
%%%-----------------------------------------------------------------
%%% Call logger in different ways
do_log_func(Level,Msg) ->
logger:Level(Msg,[],?meta).
do_log_macro(error,Msg) ->
?LOG_ERROR(Msg,[]);
do_log_macro(info,Msg) ->
?LOG_INFO(Msg,[]);
do_log_macro(debug,Msg) ->
?LOG_DEBUG(Msg,[]).
do_error_logger(error,Msg) ->
error_logger:error_msg(Msg,[]);
do_error_logger(info,Msg) ->
error_logger:info_msg(Msg,[]).
%%%-----------------------------------------------------------------
%%%
print_compare_chart(Group,Bench) ->
io:format("~-20s~12s~12s~12s~12s",
["Microseconds:","Log","Drop","HDrop","Complete"]),
io:format(user,"~-20s~12s~12s~12s~12s~n",
["Microseconds:","Log","Drop","HDrop","Complete"]),
{Log,Drop,HDrop,Comp} = sort_bench(Bench,[],[],[],[]),
print_compare_chart(Log,Drop,HDrop,Comp),
io:format(user,"~n",[]),
maybe_print_csv_files(Group,
[{log,Log},{drop,Drop},{hdrop,HDrop},{comp,Comp}]).
print_compare_chart([{What,LIOPS,LMSecs}|Log],
[{What,DIOPS,DMSecs}|Drop],
[{What,HIOPS,HMSecs}|HDrop],
[{What,CIOPS,CMSecs}|Comp]) ->
io:format("~-20w~12w~12w~12w~12w",[What,LMSecs,DMSecs,HMSecs,CMSecs]),
io:format(user,"~-20w~12w~12w~12w~12w~n",[What,LMSecs,DMSecs,HMSecs,CMSecs]),
print_compare_chart(Log,Drop,HDrop,Comp);
print_compare_chart([{What,LIOPS,LMSecs}|Log],
[{What,DIOPS,DMSecs}|Drop],
[{What,HIOPS,HMSecs}|HDrop],
[]=Comp) ->
io:format("~-20w~12w~12w~12w",[What,LMSecs,DMSecs,HMSecs]),
io:format(user,"~-20w~12w~12w~12w~n",[What,LMSecs,DMSecs,HMSecs]),
print_compare_chart(Log,Drop,HDrop,Comp);
print_compare_chart([],[],[],[]) ->
ok;
print_compare_chart(Log,Drop,HDrop,Comp) ->
ct:fail({Log,Drop,HDrop,Comp}).
sort_bench([{TC,IOPS,MSecs}|Bench],Log,Drop,HDrop,Comp) ->
case lists:member(TC,?NO_COMPARE) of
true ->
sort_bench(Bench,Log,Drop,HDrop,Comp);
false ->
TCStr = atom_to_list(TC),
{What,Type} =
case re:run(TCStr,"(.*)_(drop.*)",
[{capture,all_but_first,list}]) of
{match,[WhatStr,TypeStr]} ->
{list_to_atom(WhatStr),list_to_atom(TypeStr)};
nomatch ->
case re:run(TCStr,"(.*)_(handler_complete.*)",
[{capture,all_but_first,list}]) of
{match,[WhatStr,TypeStr]} ->
{list_to_atom(WhatStr),list_to_atom(TypeStr)};
nomatch ->
{TC,log}
end
end,
case Type of
log ->
sort_bench(Bench,[{What,IOPS,MSecs}|Log],Drop,HDrop,Comp);
drop ->
sort_bench(Bench,Log,[{What,IOPS,MSecs}|Drop],HDrop,Comp);
drop_by_handler ->
sort_bench(Bench,Log,Drop,[{What,IOPS,MSecs}|HDrop],Comp);
handler_complete ->
sort_bench(Bench,Log,Drop,HDrop,[{What,IOPS,MSecs}|Comp])
end
end;
sort_bench([],Log,Drop,HDrop,Comp) ->
{lists:keysort(1,Log),
lists:keysort(1,Drop),
lists:keysort(1,HDrop),
lists:keysort(1,Comp)}.
maybe_print_csv_files(Group,Data) ->
case ct:get_config({print_csv,Group}) of
undefined ->
ok;
Cfg ->
Path = proplists:get_value(path,Cfg,".."),
Files = [begin
File = filename:join(Path,F)++".csv",
case filelib:is_regular(File) of
true ->
{ok,Fd} = file:open(File,[append]),
Fd;
false ->
{ok,Fd} = file:open(File,[write]),
ok = file:write(Fd,
"error_logger,lager_log,"
"lager_parsetrans,logger_log,"
"logger_macro\n"),
Fd
end
end || {F,_} <- Data],
[print_csv_file(F,D) || {F,D} <- lists:zip(Files,Data)],
[file:close(Fd) || Fd <- Files],
ok
end.
print_csv_file(Fd,{_,Data}) ->
AllIOPS = [integer_to_list(IOPS) || {_,IOPS,_} <- Data],
ok = file:write(Fd,lists:join(",",AllIOPS)++"\n").
have_lager() ->
code:ensure_loaded(lager) == {module,lager}.
make(Dir) ->
{ok,Cwd} = file:get_cwd(),
ok = file:set_cwd(Dir),
up_to_date = make:all([load]),
ok = file:set_cwd(Cwd),
code:add_path(Dir).
