Merge branch 'siri/logger/bench' into maint

* siri/logger/bench:
  [logger] Add benchmark of big log events with chars_limit and max_size
  [logger] Add max memory usage to statistics in logger_olp
  Skip logger benchmarks in normal kernel test
  [logger] Add benchmark of events per millisecond for handlers

4 files changed, 104 insertions, 3 deletions

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).
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"