aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorSiri Hansen <[email protected]>2019-03-05 21:01:43 +0100
committerSiri Hansen <[email protected]>2019-03-07 14:22:52 +0100
commitfcacc60891caa3f9ae9d585c808412c11e6b27f5 (patch)
tree29d9267adbe923aab5f995b72981b4b959a06b57
parent09f69a9c87e24c2bdcbbc2bdf1436146b2a825e6 (diff)
downloadotp-fcacc60891caa3f9ae9d585c808412c11e6b27f5.tar.gz
otp-fcacc60891caa3f9ae9d585c808412c11e6b27f5.tar.bz2
otp-fcacc60891caa3f9ae9d585c808412c11e6b27f5.zip
[logger] Add benchmark of big log events with chars_limit and max_size
-rw-r--r--lib/kernel/test/logger_stress_SUITE.erl59
1 files changed, 46 insertions, 13 deletions
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"