[logger] Add logger_stress_SUITE

1 files changed, 456 insertions, 0 deletions

diff --git a/lib/kernel/test/logger_stress_SUITE.erl b/lib/kernel/test/logger_stress_SUITE.erl
new file mode 100644
index 0000000000..5ec724c524
--- /dev/null
+++ b/lib/kernel/test/logger_stress_SUITE.erl
@@ -0,0 +1,456 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 2018. All Rights Reserved.
+%%
+%% Licensed under the Apache License, Version 2.0 (the "License");
+%% you may not use this file except in compliance with the License.
+%% You may obtain a copy of the License at
+%%
+%%     http://www.apache.org/licenses/LICENSE-2.0
+%%
+%% Unless required by applicable law or agreed to in writing, software
+%% distributed under the License is distributed on an "AS IS" BASIS,
+%% WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+%% See the License for the specific language governing permissions and
+%% limitations under the License.
+%%
+%% %CopyrightEnd%
+%%
+-module(logger_stress_SUITE).
+
+-compile(export_all).
+
+-include_lib("common_test/include/ct_event.hrl").
+-include_lib("kernel/include/logger.hrl").
+-include_lib("kernel/src/logger_h_common.hrl").
+
+-ifdef(SAVE_STATS).
+  -define(COLLECT_STATS(_All_,_Procs_),
+          ct:pal("~p",[stats(_All_,_Procs_)])).
+-else.
+  -define(COLLECT_STATS(_All_,_Procs__), ok).
+-endif.
+
+-define(TEST_DURATION,120). % seconds
+
+suite() ->
+    [{timetrap,{minutes,3}},
+     {ct_hooks,[logger_test_lib]}].
+
+init_per_suite(Config) ->
+    Config.
+
+end_per_suite(_Config) ->
+    ok.
+
+init_per_group(_Group, Config) ->
+    Config.
+
+end_per_group(_Group, _Config) ->
+    ok.
+
+init_per_testcase(_TestCase, Config) ->
+    Config.
+
+end_per_testcase(Case, Config) ->
+    try apply(?MODULE,Case,[cleanup,Config])
+    catch error:undef -> ok
+    end,
+    ok.
+
+groups() ->
+    [].
+
+all() -> 
+    [allow_events,
+     reject_events,
+     std_handler,
+     disk_log_handler,
+     emulator_events,
+     remote_events,
+     remote_to_disk_log,
+     remote_emulator_events,
+     remote_emulator_to_disk_log].
+
+%%%-----------------------------------------------------------------
+%%% Test cases
+%%%-----------------------------------------------------------------
+%% Time from log macro call to handler callback
+allow_events(Config) ->
+    {ok,_,Node} =
+        logger_test_lib:setup(Config,
+                              [{logger,
+                                [{handler,default,?MODULE,#{}}]},
+                               {logger_level,notice}]),
+    N = 100000,
+    {T,_} = timer:tc(fun() -> rpc:call(Node,?MODULE,nlogs,[N]) end),
+    IOPS = N * 1000/T, % log events allowed per millisecond
+    ct_event:notify(#event{name = benchmark_data,
+                           data = [{value,IOPS}]}),
+    {comment,io_lib:format("~.2f accepted events pr millisecond",
+                           [IOPS])}.
+
+%% Time from log macro call to reject (log level)
+reject_events(Config) ->
+    {ok,_,Node} =
+        logger_test_lib:setup(Config,
+                              [{logger,
+                                [{handler,default,?MODULE,#{}}]},
+                               {logger_level,error}]),
+    N = 1000000,
+    {T,_} = timer:tc(fun() -> rpc:call(Node,?MODULE,nlogs,[N]) end),
+    IOPS = N * 1000/T, % log events rejeted per second
+    ct_event:notify(#event{name = benchmark_data,
+                           data = [{value,IOPS}]}),
+    {comment,io_lib:format("~.2f rejected events pr millisecond",
+                           [IOPS])}.
+
+%% 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_std_h file handler.
+std_handler(Config) ->
+    {ok,_,Node} =
+        logger_test_lib:setup(Config,
+                              [{logger,
+                                [{handler,default,logger_std_h,
+                                  #{config=>#{type=>{file,"default.log"}}}}]}]),
+
+    cascade({Node,{logger_backend,log_allowed,2},[]},
+            {Node,{logger_std_h,write,4},[{default,logger_std_h_default}]},
+            fun otp_cascading/0).
+std_handler(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.
+disk_log_handler(Config) ->
+    {ok,_,Node} =
+        logger_test_lib:setup(Config,
+                              [{logger,
+                                [{handler,default,logger_disk_log_h,#{}}]}]),
+    cascade({Node,{logger_backend,log_allowed,2},[]},
+            {Node,{logger_disk_log_h,write,4},
+             [{default,logger_disk_log_h_default}]},
+            fun otp_cascading/0).
+disk_log_handler(cleanup,_Config) ->
+    Files = filelib:wildcard("default.log.*"),
+    [_ = file:delete(F) || F <- Files],
+    ok.
+
+%% Cascading failure that produce log events from the emulator - how
+%% many of the produced log events pass through the proxy.
+emulator_events(Config) ->
+    {ok,_,Node} =
+        logger_test_lib:setup(Config,
+                              [{logger,
+                                [{handler,default,?MODULE,#{}}]}]),
+    cascade({Node,{?MODULE,producer,0},[]},
+            {Node,{?MODULE,log,2},[{proxy,logger_proxy}]},
+            fun em_cascading/0).
+
+%% Cascading failure that produce gen_server and proc_lib reports on
+%% remote node - how many of the produced log events pass through the
+%% proxy.
+remote_events(Config) ->
+    {ok,_,Node1} =
+        logger_test_lib:setup([{postfix,1}|Config],
+                              [{logger,
+                                [{handler,default,?MODULE,#{}}]}]),
+    {ok,_,Node2} =
+        logger_test_lib:setup([{postfix,2}|Config],[]),
+    cascade({Node2,{logger_backend,log_allowed,2},[{remote_proxy,logger_proxy}]},
+            {Node1,{?MODULE,log,2},[{local_proxy,logger_proxy}]},
+            fun otp_cascading/0).
+
+%% Cascading failure that produce gen_server and proc_lib reports on
+%% remote node - how many of the produced log events are actually
+%% written to a log with logger_disk_log_h wrap file handler.
+remote_to_disk_log(Config) ->
+    {ok,_,Node1} =
+        logger_test_lib:setup([{postfix,1}|Config],
+                              [{logger,
+                                [{handler,default,logger_disk_log_h,#{}}]}]),
+    {ok,_,Node2} =
+        logger_test_lib:setup([{postfix,2}|Config],[]),
+    cascade({Node2,{logger_backend,log_allowed,2},[{remote_proxy,logger_proxy}]},
+            {Node1,{logger_disk_log_h,write,4},
+             [{local_proxy,logger_proxy},
+              {local_default,logger_disk_log_h_default}]},
+            fun otp_cascading/0).
+remote_to_disk_log(cleanup,_Config) ->
+    Files = filelib:wildcard("default.log.*"),
+    [_ = file:delete(F) || F <- Files],
+    ok.
+
+%% Cascading failure that produce log events from the emulator on
+%% remote node - how many of the produced log events pass through the
+%% proxy.
+remote_emulator_events(Config) ->
+    {ok,_,Node1} =
+        logger_test_lib:setup([{postfix,1}|Config],
+                              [{logger,
+                                [{handler,default,?MODULE,#{}}]}]),
+    {ok,_,Node2} =
+        logger_test_lib:setup([{postfix,2}|Config],[]),
+    cascade({Node2,{?MODULE,producer,0},[{remote_proxy,logger_proxy}]},
+            {Node1,{?MODULE,log,2},[{local_proxy,logger_proxy}]},
+            fun em_cascading/0).
+
+%% Cascading failure that produce log events from the emulator on
+%% remote node - how many of the produced log events are actually
+%% written to a log with logger_disk_log_h wrap file handler.
+remote_emulator_to_disk_log(Config) ->
+    {ok,_,Node1} =
+        logger_test_lib:setup([{postfix,1}|Config],
+                              [{logger,
+                                [{handler,default,logger_disk_log_h,#{}}]}]),
+    {ok,_,Node2} =
+        logger_test_lib:setup([{postfix,2}|Config],[]),
+    cascade({Node2,{?MODULE,producer,0},[{remote_proxy,logger_proxy}]},
+            {Node1,{logger_disk_log_h,write,4},
+             [{local_proxy,logger_proxy},
+              {local_default,logger_disk_log_h_default}]},
+            fun em_cascading/0).
+remote_emulator_to_disk_log(cleanup,_Config) ->
+    Files = filelib:wildcard("default.log.*"),
+    [_ = file:delete(F) || F <- Files],
+    ok.
+
+%%%-----------------------------------------------------------------
+%%% Internal functions
+nlogs(N) ->
+    group_leader(whereis(user),self()),
+    Str = "\"#$%&'()*+,-./0123456789:;<=>?@ABCDEFGHIJKLMNOPQRSTUVWXYZ"
+        "[\\]^_`abcdefghijklmnopqr",
+    [?LOG_NOTICE(Str) || _ <- lists:seq(1,N)],
+    ok.
+
+%% cascade(ProducerInfo,ConsumerInfo,TestFun)
+cascade({PNode,PMFA,PStatProcs},{CNode,CMFA,CStatProcs},TestFun) ->
+    Tab  = ets:new(counter,[set,public]),
+    ets:insert(Tab,{producer,0}),
+    ets:insert(Tab,{consumer,0}),
+    dbg:tracer(process,{fun tracer/2,{Tab,PNode,CNode}}),
+    dbg:n(PNode),
+    dbg:n(CNode),
+    dbg:cn(node()),
+    dbg:p(all,[call,arity]),
+    dbg:tpl(PMFA,[]),
+    dbg:tpl(CMFA,[]),
+
+    Pid = rpc:call(CNode,?MODULE,wrap_test,[PNode,TestFun]),
+    MRef = erlang:monitor(process,Pid),
+    TO = ?TEST_DURATION*1000,
+    receive {'DOWN',MRef,_,_,Reason} ->
+            ct:fail({remote_pid_down,Reason})
+    after TO ->
+            All = ets:lookup_element(Tab,producer,2),
+            Written = ets:lookup_element(Tab,consumer,2),
+            dbg:stop_clear(),
+            ?COLLECT_STATS(All,
+                           [{PNode,P,Id} || {Id,P} <- PStatProcs] ++
+                               [{CNode,P,Id} || {Id,P} <- CStatProcs]),
+            Ratio = Written/All,
+            ct_event:notify(#event{name = benchmark_data,
+                                   data = [{value,Ratio}]}),
+            {comment,io_lib:format("~.2f (~p written, ~p produced)",
+                                   [Ratio,Written,All])}
+    end.
+
+wrap_test(Fun) ->
+    wrap_test(node(),Fun).
+wrap_test(Node,Fun) ->
+    reset(),
+    group_leader(whereis(user),self()),
+    rpc:call(Node,?MODULE,do_fun,[Fun]).
+
+do_fun(Fun) ->
+    reset(),
+    Fun().
+
+reset() ->
+    reset([logger_std_h_default, logger_disk_log_h_default, logger_proxy]).
+reset([P|Ps]) ->
+    is_pid(whereis(P)) andalso logger_olp:reset(P),
+    reset(Ps);
+reset([]) ->
+    ok.
+
+
+tracer({trace,_,call,{?MODULE,producer,_}},{Tab,_PNode,_CNode}=S) ->
+    ets:update_counter(Tab,producer,1),
+    S;
+tracer({trace,Pid,call,{logger_backend,log_allowed,_}},{Tab,PNode,_CNode}=S) when node(Pid)=:=PNode ->
+    ets:update_counter(Tab,producer,1),
+    S;
+tracer({trace,_,call,{?MODULE,log,_}},{Tab,_PNode,_CNode}=S) ->
+    ets:update_counter(Tab,consumer,1),
+    S;
+tracer({trace,_,call,{_,write,_}},{Tab,_PNode,_CNode}=S) ->
+    ets:update_counter(Tab,consumer,1),
+    S;
+tracer(_,S) ->
+    S.
+
+
+%%%-----------------------------------------------------------------
+%%% Collect statistics
+-define(STAT_KEYS,
+        [burst_drops,
+         calls,
+         casts,
+         drops,
+         flushed,
+         flushes,
+         freq,
+         last_qlen,
+         max_qlen,
+         time,
+         writes]).
+-define(EVENT_KEYS,
+        [calls,casts,flushed]).
+
+stats(All,Procs) ->
+    NI = [{Id,rpc:call(N,logger_olp,info,[P])} || {N,P,Id}<-Procs],
+    [{all,All}|[stats(Id,I,All) || {Id,I} <- NI]].
+
+stats(Id,Info,All) ->
+    S = maps:with(?STAT_KEYS,Info),
+    AllOnProc = lists:sum(maps:values(maps:with(?EVENT_KEYS,S))),
+    if All>0 ->
+            Writes = maps:get(writes,S),
+            {_,ActiveTime} = maps:get(time,S),
+            Rate = round(100*Writes/All),
+            RateOnProc =
+                if AllOnProc>0 ->
+                        round(100*Writes/AllOnProc);
+                   true ->
+                        0
+                end,
+            AvFreq =
+                if ActiveTime>0 ->
+                        round(Writes/ActiveTime);
+                   true ->
+                        0
+                end,
+            {Id,
+             {stats,S},
+             {rate,Rate},
+             {rate_on_proc,RateOnProc},
+             {av_freq,AvFreq}};
+       true ->
+            {Id,none}
+    end.
+
+%%%-----------------------------------------------------------------
+%%% Spawn a lot of processes that crash repeatedly, causing a lot of
+%%% error reports from the emulator.
+em_cascading() ->
+    spawn(fun() -> super() end).
+
+super() ->
+    process_flag(trap_exit,true),
+    spawn_link(fun server/0),
+    [spawn_link(fun client/0) || _<-lists:seq(1,10000)],
+    super_loop().
+
+super_loop() ->
+    receive
+        {'EXIT',_,server} ->
+            spawn_link(fun server/0),
+            super_loop();
+        {'EXIT',_,_} ->
+            _L = lists:sum(lists:seq(1,10000)),
+            spawn_link(fun client/0),
+            super_loop()
+    end.
+
+client() ->
+    receive
+    after 1 ->
+            case whereis(server) of
+                Pid when is_pid(Pid) ->
+                    ok;
+                undefined ->
+                    producer(),
+                    erlang:error(some_exception)
+            end
+    end,
+    client().
+
+server() ->
+    register(server,self()),
+    receive
+    after 3000 ->
+            exit(server)
+    end.
+        
+
+%%%-----------------------------------------------------------------
+%%% Create a supervisor tree with processes that crash repeatedly,
+%%% causing a lot of supervisor reports and crashreports
+otp_cascading() ->
+    {ok,Pid} = supervisor:start_link({local,otp_super}, ?MODULE, [otp_super]),
+    unlink(Pid),
+    Pid.
+
+otp_server_sup() ->
+    supervisor:start_link({local,otp_server_sup},?MODULE,[otp_server_sup]).
+
+otp_client_sup(N) ->
+    supervisor:start_link({local,otp_client_sup},?MODULE,[otp_client_sup,N]).
+
+otp_server() ->
+    gen_server:start_link({local,otp_server},?MODULE,[otp_server],[]).
+
+otp_client() ->
+    gen_server:start_link(?MODULE,[otp_client],[]).
+
+init([otp_super]) ->
+    {ok, {{one_for_one, 200, 10},
+            [{client_sup,
+                    {?MODULE, otp_client_sup, [10000]},
+                    permanent, 1000, supervisor, [?MODULE]},
+             {server_sup,
+                    {?MODULE, otp_server_sup, []},
+                    permanent, 1000, supervisor, [?MODULE]}
+            ]}};
+init([otp_server_sup]) ->
+    {ok, {{one_for_one, 2, 10},
+            [{server,
+                    {?MODULE, otp_server, []},
+                    permanent, 1000, worker, [?MODULE]}
+            ]}};
+init([otp_client_sup,N]) ->
+    spawn(fun() ->
+                  [supervisor:start_child(otp_client_sup,[])
+                   || _ <- lists:seq(1,N)]
+          end),
+    {ok, {{simple_one_for_one, N*10, 1},
+            [{client,
+                    {?MODULE, otp_client, []},
+                    permanent, 1000, worker, [?MODULE]}
+            ]}};
+init([otp_server]) ->
+    {ok, server, 10000};
+init([otp_client]) ->
+    {ok, client,1}.
+
+handle_info(timeout, client) ->
+    true = is_pid(whereis(otp_server)),
+    {noreply,client,1};
+handle_info(timeout, server) ->
+    exit(self(), some_error).
+
+%%%-----------------------------------------------------------------
+%%% Logger callbacks
+log(_LogEvent,_Config) ->
+    ok.
+
+%%%-----------------------------------------------------------------
+%%% Function to trace on for counting produced emulator messages
+producer() ->
+    ok.