From 5782a2ebc187c37c5d2a90480b5aa4f1d7fef70f Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 13 Feb 2019 16:35:13 +0100 Subject: [logger] Add benchmark of events per millisecond for handlers --- lib/kernel/test/logger_stress_SUITE.erl | 61 +++++++++++++++++++++++++++++++++ 1 file changed, 61 insertions(+) (limited to 'lib') diff --git a/lib/kernel/test/logger_stress_SUITE.erl b/lib/kernel/test/logger_stress_SUITE.erl index 4072e8c86a..a62b03841d 100644 --- a/lib/kernel/test/logger_stress_SUITE.erl +++ b/lib/kernel/test/logger_stress_SUITE.erl @@ -67,6 +67,8 @@ all() -> reject_events, std_handler, disk_log_handler, + std_handler_time, + disk_log_handler_time, emulator_events, remote_events, remote_to_disk_log, @@ -123,6 +125,14 @@ std_handler(cleanup,_Config) -> _ = file:delete("default.log"), ok. +%% Disable overload protection and just print a lot - measure time. +%% The IOPS reported is the number of log events written per millisecond. +std_handler_time(Config) -> + measure_handler_time(logger_std_h,#{type=>{file,"default.log"}},Config). +std_handler_time(cleanup,_Config) -> + _ = file:delete("default.log"), + ok. + %% Cascading failure that produce gen_server and proc_lib reports - %% how many of the produced log events are actually written to a log %% with logger_disk_log_h wrap file handler. @@ -140,6 +150,14 @@ disk_log_handler(cleanup,_Config) -> [_ = file:delete(F) || F <- Files], ok. +%% Disable overload protection and just print a lot - measure time. +%% The IOPS reported is the number of log events written per millisecond. +disk_log_handler_time(Config) -> + measure_handler_time(logger_disk_log_h,#{type=>halt},Config). +disk_log_handler_time(cleanup,_Config) -> + _ = file:delete("default"), + ok. + %% Cascading failure that produce log events from the emulator - how %% many of the produced log events pass through the proxy. emulator_events(Config) -> @@ -221,6 +239,49 @@ remote_emulator_to_disk_log(cleanup,_Config) -> %%%----------------------------------------------------------------- %%% Internal functions +measure_handler_time(Module,HCfg,Config) -> + N = 100000, + {ok,_,Node} = + logger_test_lib:setup( + Config, + [{logger, + [{handler,default,Module, + #{formatter => {logger_formatter, + #{legacy_header=>false,single_line=>true%% , + %% chars_limit=>4096 + }}, + config=>maps:merge(#{sync_mode_qlen => N+1, + drop_mode_qlen => N+1, + flush_qlen => N+1, + burst_limit_enable => false, + filesync_repeat_interval => no_repeat}, + HCfg)}}]}]), + HPid = rpc:call(Node,erlang,whereis,[?name_to_reg_name(Module,default)]), + {links,[_,FCPid]} = rpc:call(Node,erlang,process_info,[HPid,links]), + T0 = erlang:monotonic_time(millisecond), + ok = rpc:call(Node,?MODULE,nlogs_wait,[N,Module]), + %% ok = rpc:call(Node,fprof,apply,[fun ?MODULE:nlogs_wait/2,[N div 10,Module],[{procs,[HPid,FCPid]}]]), + T1 = erlang:monotonic_time(millisecond), + T = T1-T0, + IOPS = N/T, + %% Stats = rpc:call(Node,logger_olp,info,[?name_to_reg_name(Module,default)]), + %% ct:pal("IOPS: ~p~nStats: ~p",[IOPS,Stats]), + ct_event:notify(#event{name = benchmark_data, + data = [{value,IOPS}]}), + {comment,io_lib:format("~.2f events written pr millisecond",[IOPS])}. + +nlogs_wait(N,Module) -> + nlogs(N), + wait(Module). + +wait(Module) -> + case Module:filesync(default) of + {error,handler_busy} -> + wait(Module); + ok -> + ok + end. + nlogs(N) -> group_leader(whereis(user),self()), Str = "\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ" -- cgit v1.2.3 From afcaab906cfcf78d5991277a82e39a775b2dc519 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 28 Feb 2019 21:07:00 +0100 Subject: Skip logger benchmarks in normal kernel test --- lib/kernel/test/kernel.spec | 1 + 1 file changed, 1 insertion(+) (limited to 'lib') diff --git a/lib/kernel/test/kernel.spec b/lib/kernel/test/kernel.spec index 62afc9f97b..eaa17f3a59 100644 --- a/lib/kernel/test/kernel.spec +++ b/lib/kernel/test/kernel.spec @@ -2,3 +2,4 @@ {config, "../test_server/ts.unix.config"}. {suites,"../kernel_test", all}. +{skip_suites,"../kernel_test",[logger_stress_SUITE],"Benchmarks only"}. -- cgit v1.2.3 From 09f69a9c87e24c2bdcbbc2bdf1436146b2a825e6 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Mon, 4 Mar 2019 11:15:23 +0100 Subject: [logger] Add max memory usage to statistics in logger_olp --- lib/kernel/src/logger_olp.erl | 5 +++-- lib/kernel/src/logger_olp.hrl | 7 ++++++- 2 files changed, 9 insertions(+), 3 deletions(-) (limited to 'lib') diff --git a/lib/kernel/src/logger_olp.erl b/lib/kernel/src/logger_olp.erl index 009280a9c9..8365383fe2 100644 --- a/lib/kernel/src/logger_olp.erl +++ b/lib/kernel/src/logger_olp.erl @@ -515,10 +515,11 @@ check_load(State = #{id:=_Name, mode_ref := ModeRef, mode := Mode, end, State1 = ?update_other(drops,DROPS,_NewDrops,State), State2 = ?update_max_qlen(QLen,State1), - State3 = maybe_notify_mode_change(Mode1,State2), + State3 = ?update_max_mem(Mem,State2), + State4 = maybe_notify_mode_change(Mode1,State3), {Mode1, QLen, Mem, ?update_other(flushes,FLUSHES,_NewFlushes, - State3#{last_qlen => QLen})}. + State4#{last_qlen => QLen})}. limit_burst(#{burst_limit_enable := false}=State) -> {true,State}; diff --git a/lib/kernel/src/logger_olp.hrl b/lib/kernel/src/logger_olp.hrl index 9b4f5ebf27..d68b5c048d 100644 --- a/lib/kernel/src/logger_olp.hrl +++ b/lib/kernel/src/logger_olp.hrl @@ -114,12 +114,16 @@ flushes => 0, flushed => 0, drops => 0, burst_drops => 0, casts => 0, calls => 0, writes => 0, max_qlen => 0, max_time => 0, - freq => {TIME,0,0}} end). + max_mem => 0, freq => {TIME,0,0}} end). -define(update_max_qlen(QLEN, STATE), begin #{max_qlen := QLEN0} = STATE, STATE#{max_qlen => ?max(QLEN0,QLEN)} end). + -define(update_max_mem(MEM, STATE), + begin #{max_mem := MEM0} = STATE, + STATE#{max_mem => ?max(MEM0,MEM)} end). + -define(update_calls_or_casts(CALL_OR_CAST, INC, STATE), case CALL_OR_CAST of cast -> @@ -154,6 +158,7 @@ -else. % DEFAULT! -define(merge_with_stats(STATE), STATE). -define(update_max_qlen(_QLEN, STATE), STATE). + -define(update_max_mem(_MEM, STATE), STATE). -define(update_calls_or_casts(_CALL_OR_CAST, _INC, STATE), STATE). -define(update_max_time(_TIME, STATE), STATE). -define(update_other(_OTHER, _VAR, _INCVAL, STATE), STATE). -- cgit v1.2.3 From fcacc60891caa3f9ae9d585c808412c11e6b27f5 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Tue, 5 Mar 2019 21:01:43 +0100 Subject: [logger] Add benchmark of big log events with chars_limit and max_size --- lib/kernel/test/logger_stress_SUITE.erl | 59 +++++++++++++++++++++++++-------- 1 file changed, 46 insertions(+), 13 deletions(-) (limited to 'lib') diff --git a/lib/kernel/test/logger_stress_SUITE.erl b/lib/kernel/test/logger_stress_SUITE.erl index a62b03841d..1a278fb1b2 100644 --- a/lib/kernel/test/logger_stress_SUITE.erl +++ b/lib/kernel/test/logger_stress_SUITE.erl @@ -68,7 +68,9 @@ all() -> std_handler, disk_log_handler, std_handler_time, + std_handler_time_big, disk_log_handler_time, + disk_log_handler_time_big, emulator_events, remote_events, remote_to_disk_log, @@ -133,6 +135,12 @@ std_handler_time(cleanup,_Config) -> _ = file:delete("default.log"), ok. +std_handler_time_big(Config) -> + measure_handler_time_big(logger_std_h,#{type=>{file,"default.log"}},Config). +std_handler_time_big(cleanup,_Config) -> + _ = file:delete("default.log"), + ok. + %% Cascading failure that produce gen_server and proc_lib reports - %% how many of the produced log events are actually written to a log %% with logger_disk_log_h wrap file handler. @@ -158,6 +166,12 @@ disk_log_handler_time(cleanup,_Config) -> _ = file:delete("default"), ok. +disk_log_handler_time_big(Config) -> + measure_handler_time_big(logger_disk_log_h,#{type=>halt},Config). +disk_log_handler_time_big(cleanup,_Config) -> + _ = file:delete("default"), + ok. + %% Cascading failure that produce log events from the emulator - how %% many of the produced log events pass through the proxy. emulator_events(Config) -> @@ -240,38 +254,49 @@ remote_emulator_to_disk_log(cleanup,_Config) -> %%%----------------------------------------------------------------- %%% Internal functions measure_handler_time(Module,HCfg,Config) -> - N = 100000, + measure_handler_time(Module,100000,small_fa(),millisecond,HCfg,#{},Config). + +measure_handler_time_big(Module,HCfg,Config) -> + FCfg = #{chars_limit=>4096, max_size=>1024}, + measure_handler_time(Module,100,big_fa(),second,HCfg,FCfg,Config). + +measure_handler_time(Module,N,FA,Unit,HCfg,FCfg,Config) -> {ok,_,Node} = logger_test_lib:setup( Config, [{logger, [{handler,default,Module, #{formatter => {logger_formatter, - #{legacy_header=>false,single_line=>true%% , - %% chars_limit=>4096 - }}, + maps:merge(#{legacy_header=>false, + single_line=>true},FCfg)}, config=>maps:merge(#{sync_mode_qlen => N+1, drop_mode_qlen => N+1, flush_qlen => N+1, burst_limit_enable => false, filesync_repeat_interval => no_repeat}, HCfg)}}]}]), - HPid = rpc:call(Node,erlang,whereis,[?name_to_reg_name(Module,default)]), - {links,[_,FCPid]} = rpc:call(Node,erlang,process_info,[HPid,links]), + %% HPid = rpc:call(Node,erlang,whereis,[?name_to_reg_name(Module,default)]), + %% {links,[_,FCPid]} = rpc:call(Node,erlang,process_info,[HPid,links]), T0 = erlang:monotonic_time(millisecond), - ok = rpc:call(Node,?MODULE,nlogs_wait,[N,Module]), - %% ok = rpc:call(Node,fprof,apply,[fun ?MODULE:nlogs_wait/2,[N div 10,Module],[{procs,[HPid,FCPid]}]]), + ok = rpc:call(Node,?MODULE,nlogs_wait,[N,FA,Module]), + %% ok = rpc:call(Node,fprof,apply,[fun ?MODULE:nlogs_wait/2,[N div 10,FA,Module],[{procs,[HPid,FCPid]}]]), T1 = erlang:monotonic_time(millisecond), T = T1-T0, - IOPS = N/T, + M = case Unit of + millisecond -> 1; + second -> 1000 + end, + IOPS = M*N/T, + ct:pal("N: ~p~nT: ~p~nIOPS: ~.2f events pr ~w",[N,T,IOPS,Unit]), %% Stats = rpc:call(Node,logger_olp,info,[?name_to_reg_name(Module,default)]), - %% ct:pal("IOPS: ~p~nStats: ~p",[IOPS,Stats]), + %% ct:pal("Stats: ~p",[Stats]), ct_event:notify(#event{name = benchmark_data, data = [{value,IOPS}]}), - {comment,io_lib:format("~.2f events written pr millisecond",[IOPS])}. + {comment,io_lib:format("~.2f events written pr ~w",[IOPS,Unit])}. -nlogs_wait(N,Module) -> - nlogs(N), +nlogs_wait(N,{F,A},Module) -> + group_leader(whereis(user),self()), + [?LOG_NOTICE(F,A) || _ <- lists:seq(1,N)], wait(Module). wait(Module) -> @@ -282,6 +307,14 @@ wait(Module) -> ok end. +small_fa() -> + Str = "\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ" + "[\\]^_`abcdefghijklmnopqr", + {"~ts",[Str]}. + +big_fa() -> + {"~p",[lists:duplicate(1048576,"a")]}. + nlogs(N) -> group_leader(whereis(user),self()), Str = "\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ" -- cgit v1.2.3