aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorSiri Hansen <[email protected]>2019-02-13 16:35:13 +0100
committerSiri Hansen <[email protected]>2019-03-07 14:22:51 +0100
commit5782a2ebc187c37c5d2a90480b5aa4f1d7fef70f (patch)
treef6ae28c91ce71bea69ed0f008ab4e8decb1db09e
parent595c159823089d0186ec2617c174356d1ff2de65 (diff)
downloadotp-5782a2ebc187c37c5d2a90480b5aa4f1d7fef70f.tar.gz
otp-5782a2ebc187c37c5d2a90480b5aa4f1d7fef70f.tar.bz2
otp-5782a2ebc187c37c5d2a90480b5aa4f1d7fef70f.zip
[logger] Add benchmark of events per millisecond for handlers
-rw-r--r--lib/kernel/test/logger_stress_SUITE.erl61
1 files changed, 61 insertions, 0 deletions
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"