From fcacc60891caa3f9ae9d585c808412c11e6b27f5 Mon Sep 17 00:00:00 2001
From: Siri Hansen <siri@erlang.org>
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(-)

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