aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel/test/logger_bench_SUITE.erl
diff options
context:
space:
mode:
Diffstat (limited to 'lib/kernel/test/logger_bench_SUITE.erl')
-rw-r--r--lib/kernel/test/logger_bench_SUITE.erl500
1 files changed, 0 insertions, 500 deletions
diff --git a/lib/kernel/test/logger_bench_SUITE.erl b/lib/kernel/test/logger_bench_SUITE.erl
deleted file mode 100644
index d47122ea9d..0000000000
--- a/lib/kernel/test/logger_bench_SUITE.erl
+++ /dev/null
@@ -1,500 +0,0 @@
-%%
-%% %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).