Merge branch 'maint'

2 files changed, 95 insertions, 0 deletions

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"}.
diff --git a/lib/kernel/test/logger_stress_SUITE.erl b/lib/kernel/test/logger_stress_SUITE.erl
index 4072e8c86a..1a278fb1b2 100644
--- a/lib/kernel/test/logger_stress_SUITE.erl
+++ b/lib/kernel/test/logger_stress_SUITE.erl
@@ -67,6 +67,10 @@ all() ->
      reject_events,
      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,
@@ -123,6 +127,20 @@ 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.
+
+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.
@@ -140,6 +158,20 @@ 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.
+
+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) ->
@@ -221,6 +253,68 @@ remote_emulator_to_disk_log(cleanup,_Config) ->
 
 %%%-----------------------------------------------------------------
 %%% Internal functions
+measure_handler_time(Module,HCfg,Config) ->
+    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,
+                              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]),
+    T0 = erlang:monotonic_time(millisecond),
+    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,
+    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("Stats: ~p",[Stats]),
+    ct_event:notify(#event{name = benchmark_data,
+                           data = [{value,IOPS}]}),
+    {comment,io_lib:format("~.2f events written pr ~w",[IOPS,Unit])}.
+
+nlogs_wait(N,{F,A},Module) ->
+    group_leader(whereis(user),self()),
+    [?LOG_NOTICE(F,A) || _ <- lists:seq(1,N)],
+    wait(Module).
+
+wait(Module) ->
+    case Module:filesync(default) of
+        {error,handler_busy} ->
+            wait(Module);
+        ok ->
+            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"