[logger] Move out overload protection macros from logger_h_common.hrl

The new file logger_olp.hrl is added.

9 files changed, 219 insertions, 180 deletions

diff --git a/lib/kernel/src/Makefile b/lib/kernel/src/Makefile
index c3fee02334..3d1506ea08 100644
--- a/lib/kernel/src/Makefile
+++ b/lib/kernel/src/Makefile
@@ -153,7 +153,7 @@ INTERNAL_HRL_FILES= application_master.hrl disk_log.hrl \
         inet_dns.hrl inet_res.hrl \
         inet_boot.hrl inet_config.hrl inet_int.hrl \
 	inet_dns_record_adts.hrl \
-	logger_internal.hrl logger_h_common.hrl
+	logger_internal.hrl logger_olp.hrl logger_h_common.hrl
 
 ERL_FILES= $(MODULES:%=%.erl)
 
@@ -281,7 +281,7 @@ $(EBIN)/logger_config.beam: logger_internal.hrl ../include/logger.hrl
 $(EBIN)/logger_disk_log_h.beam: logger_h_common.hrl logger_internal.hrl ../include/logger.hrl ../include/file.hrl
 $(EBIN)/logger_filters.beam: logger_internal.hrl ../include/logger.hrl
 $(EBIN)/logger_formatter.beam: logger_internal.hrl ../include/logger.hrl
-$(EBIN)/logger_olp.beam: logger_h_common.hrl logger_internal.hrl
+$(EBIN)/logger_olp.beam: logger_olp.hrl logger_internal.hrl
 $(EBIN)/logger_proxy.beam: logger_internal.hrl
 $(EBIN)/logger_server.beam: logger_internal.hrl ../include/logger.hrl
 $(EBIN)/logger_simple_h.beam: logger_internal.hrl ../include/logger.hrl
diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl
index 6f55c5997d..51fe8f3157 100644
--- a/lib/kernel/src/logger_h_common.erl
+++ b/lib/kernel/src/logger_h_common.erl
@@ -223,6 +223,8 @@ start(OlpOpts0, #{id := Name, module:=Module, config:=HConfig} = Config0) ->
 init(#{id := Name, module := Module, config := HConfig}) ->
     process_flag(trap_exit, true),
 
+    ?init_test_hooks(),
+
     case Module:init(Name, HConfig) of
         {ok,HState} ->
             %% Storing common config in state to avoid copying
diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl
index f2d642f6f0..004a61d9d9 100644
--- a/lib/kernel/src/logger_h_common.hrl
+++ b/lib/kernel/src/logger_h_common.hrl
@@ -1,50 +1,22 @@
-
-%%%-----------------------------------------------------------------
-%%% Overload protection configuration
-
-%%! *** NOTE *** 
-%%! It's important that:
-%%! SYNC_MODE_QLEN =< DROP_MODE_QLEN =< FLUSH_QLEN
-%%! and that DROP_MODE_QLEN >= 2.
-%%! Otherwise the handler could end up in drop mode with no new
-%%! log requests to process. This would cause all future requests
-%%! to be dropped (no switch to async mode would ever take place).
-
-%% This specifies the message_queue_len value where the log
-%% requests switch from asynchronous casts to synchronous calls.
--define(SYNC_MODE_QLEN, 10).
-%% Above this message_queue_len, log requests will be dropped,
-%% i.e. no log requests get sent to the handler process.
--define(DROP_MODE_QLEN, 200).
-%% Above this message_queue_len, the handler process will flush
-%% its mailbox and only leave this number of messages in it.
--define(FLUSH_QLEN, 1000).
-
-%% Never flush more than this number of messages in one go,
-%% or the handler will be unresponsive for seconds (keep this
-%% number as large as possible or the mailbox could grow large).
--define(FLUSH_MAX_N, 5000).
-
-%% BURST_LIMIT_MAX_COUNT is the max number of log requests allowed
-%% to be written within a BURST_LIMIT_WINDOW_TIME time frame.
--define(BURST_LIMIT_ENABLE, true).
--define(BURST_LIMIT_MAX_COUNT, 500).
--define(BURST_LIMIT_WINDOW_TIME, 1000).
-
-%% This enables/disables the feature to automatically get the
-%% handler terminated if it gets too loaded (and can't keep up).
--define(OVERLOAD_KILL_ENABLE, false).
-%% If the message_queue_len goes above this size even after
-%% flushing has been performed, the handler is terminated.
--define(OVERLOAD_KILL_QLEN, 20000).
-%% If the memory usage exceeds this level
--define(OVERLOAD_KILL_MEM_SIZE, 3000000).
-
-%% This is the default time that the handler will wait before
-%% restarting and accepting new requests. The value 'infinity'
-%% disables restarts.
--define(OVERLOAD_KILL_RESTART_AFTER, 5000).
-%%-define(OVERLOAD_KILL_RESTART_AFTER, infinity).
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 1997-2015. 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%
+%%
 
 %% The handler sends asynchronous write requests to the process
 %% controlling the i/o device, but every once in this interval
@@ -65,10 +37,6 @@
 -define(FILESYNC_REPEAT_INTERVAL, 5000).
 %%-define(FILESYNC_REPEAT_INTERVAL, no_repeat).
 
-%% This is the time in milliseconds after last load message received
-%% that we notify the callback about being idle.
--define(IDLE_DETECT_TIME, 100).
-
 %% Default disk log option values
 -define(DISK_LOG_TYPE, wrap).
 -define(DISK_LOG_MAX_NO_FILES, 10).
@@ -81,43 +49,6 @@
         list_to_atom(lists:concat([MODULE,"_",Name]))).
 
 %%%-----------------------------------------------------------------
-%%% Overload protection macros
-
--define(timestamp(), erlang:monotonic_time(microsecond)).
-
--define(get_mode(Tid),
-        case ets:lookup(Tid, mode) of
-            [{mode,M}] -> M;
-            _          -> async
-        end).
-
--define(set_mode(Tid, M),
-        begin ets:insert(Tid, {mode,M}), M end).
-
--define(change_mode(Tid, M0, M1),
-        if M0 == M1 ->
-                M0;
-           true ->
-                ets:insert(Tid, {mode,M1}),
-                M1
-        end).
-
--define(min(X1, X2),
-        if X2 == undefined -> X1;
-           X2 < X1 -> X2;
-           true -> X1
-        end).
-
--define(max(X1, X2),
-        if 
-            X2 == undefined -> X1;
-            X2 > X1 -> X2;
-            true -> X1
-        end).
-
--define(diff_time(OS_T1, OS_T0), OS_T1-OS_T0).
-
-%%%-----------------------------------------------------------------
 %%% The test hook macros make it possible to observe and manipulate
 %%% internal handler functionality. When enabled, these macros will
 %%% slow down execution and therefore should not be include in code
@@ -181,7 +112,6 @@
               [{_,ERROR}] -> ERROR
           catch _:_       -> disk_log:sync(LOG) end).
 
-  -define(DEFAULT_CALL_TIMEOUT, 5000).
 
 -else.                                          % DEFAULTS!
   -define(TEST_HOOKS_TAB, undefined).
@@ -194,87 +124,4 @@
   -define(file_datasync(DEVICE), file:datasync(DEVICE)).
   -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)).
   -define(disk_log_sync(LOG), disk_log:sync(LOG)).
-  -define(DEFAULT_CALL_TIMEOUT, 10000).
--endif.
-
-%%%-----------------------------------------------------------------
-%%% These macros enable statistics counters in the state of the
-%%% handler which is useful for analysing the overload protection
-%%% behaviour. These counters should not be included in code to be
-%%% officially released (as some counters will grow very large
-%%% over time).
-
-%% -define(SAVE_STATS, true).
--ifdef(SAVE_STATS).
-  -define(merge_with_stats(STATE),
-          begin
-              TIME = ?timestamp(),
-              STATE#{start => TIME, time => {TIME,0},
-                     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).
-
-  -define(update_max_qlen(QLEN, STATE),
-          begin #{max_qlen := QLEN0} = STATE,
-                STATE#{max_qlen => ?max(QLEN0,QLEN)} end).
-
-  -define(update_calls_or_casts(CALL_OR_CAST, INC, STATE),
-          case CALL_OR_CAST of
-              cast ->
-                  #{casts := CASTS0} = STATE,
-                  STATE#{casts => CASTS0+INC};
-              call ->
-                  #{calls := CALLS0} = STATE,
-                  STATE#{calls => CALLS0+INC}
-          end).
-
-  -define(update_max_time(TIME, STATE),
-          begin #{max_time := TIME0} = STATE,
-                STATE#{max_time => ?max(TIME0,TIME)} end).
-
-  -define(update_other(OTHER, VAR, INCVAL, STATE),
-          begin #{OTHER := VAR} = STATE,
-                STATE#{OTHER => VAR+INCVAL} end).
-
-  -define(update_freq(TIME,STATE),
-          begin
-              case STATE of
-                  #{freq := {START, 49, _}} ->
-                      STATE#{freq => {TIME, 0, trunc(1000000*50/(?diff_time(TIME,START)))}};
-                  #{freq := {START, N, FREQ}} ->
-                      STATE#{freq => {START, N+1, FREQ}}
-              end end).
-
-  -define(update_time(TIME,STATE),
-          begin #{start := START} = STATE,
-                STATE#{time => {TIME,trunc((?diff_time(TIME,START))/1000000)}} end).
-
--else.                                          % DEFAULT!
-  -define(merge_with_stats(STATE), STATE).
-  -define(update_max_qlen(_QLEN, 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).
-  -define(update_freq(_TIME, STATE), STATE).
-  -define(update_time(_TIME, STATE), STATE).
--endif.
-
-%%%-----------------------------------------------------------------
-%%% These macros enable callbacks that make it possible to analyse
-%%% the overload protection behaviour from outside the handler
-%%% process (including dropped requests on the client side).
-%%% An external callback module (?OBSERVER_MOD) is required which
-%%% is not part of the kernel application. For this reason, these
-%%% callbacks should not be included in code to be officially released.
-
-%%-define(OBSERVER_MOD, logger_test).
--ifdef(OBSERVER_MOD).
-  -define(start_observation(NAME), ?OBSERVER:start_observation(NAME)).
-  -define(observe(NAME,EVENT), ?OBSERVER:observe(NAME,EVENT)).
-
--else.                                          % DEFAULT!
-  -define(start_observation(_NAME), ok).
-  -define(observe(_NAME,_EVENT), ok).
 -endif.
-%%! <---
diff --git a/lib/kernel/src/logger_olp.erl b/lib/kernel/src/logger_olp.erl
index 0f9314b4a3..009280a9c9 100644
--- a/lib/kernel/src/logger_olp.erl
+++ b/lib/kernel/src/logger_olp.erl
@@ -20,7 +20,7 @@
 -module(logger_olp).
 -behaviour(gen_server).
 
--include("logger_h_common.hrl").
+-include("logger_olp.hrl").
 -include("logger_internal.hrl").
 
 %% API
@@ -172,7 +172,6 @@ init([Name,Module,Args,Options]) ->
     register(Name, self()),
     process_flag(message_queue_data, off_heap),
 
-    ?init_test_hooks(),
     ?start_observation(Name),
 
     try ets:new(Name, [public]) of
@@ -324,7 +323,7 @@ call({_Name, Pid, _ModeRef},Msg) ->
     call(Pid, Msg);
 call(Server, Msg) ->
     try
-        gen_server:call(Server, Msg, ?DEFAULT_CALL_TIMEOUT)
+        gen_server:call(Server, Msg)
     catch
         _:{timeout,_} -> {error,busy}
     end.
diff --git a/lib/kernel/src/logger_olp.hrl b/lib/kernel/src/logger_olp.hrl
new file mode 100644
index 0000000000..9b4f5ebf27
--- /dev/null
+++ b/lib/kernel/src/logger_olp.hrl
@@ -0,0 +1,180 @@
+%%
+%% %CopyrightBegin%
+%%
+%% Copyright Ericsson AB 1997-2015. 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%
+%%
+
+%%%-----------------------------------------------------------------
+%%% Overload protection configuration
+
+%%! *** NOTE *** 
+%%! It's important that:
+%%! SYNC_MODE_QLEN =< DROP_MODE_QLEN =< FLUSH_QLEN
+%%! and that DROP_MODE_QLEN >= 2.
+%%! Otherwise the process could end up in drop mode with no new
+%%! log requests to process. This would cause all future requests
+%%! to be dropped (no switch to async mode would ever take place).
+
+%% This specifies the message_queue_len value where the log
+%% requests switch from asynchronous casts to synchronous calls.
+-define(SYNC_MODE_QLEN, 10).
+%% Above this message_queue_len, log requests will be dropped,
+%% i.e. no log requests get sent to the process.
+-define(DROP_MODE_QLEN, 200).
+%% Above this message_queue_len, the process will flush its mailbox
+%% and only leave this number of messages in it.
+-define(FLUSH_QLEN, 1000).
+
+%% Never flush more than this number of messages in one go, or the
+%% process will be unresponsive for seconds (keep this number as large
+%% as possible or the mailbox could grow large).
+-define(FLUSH_MAX_N, 5000).
+
+%% BURST_LIMIT_MAX_COUNT is the max number of log requests allowed
+%% to be written within a BURST_LIMIT_WINDOW_TIME time frame.
+-define(BURST_LIMIT_ENABLE, true).
+-define(BURST_LIMIT_MAX_COUNT, 500).
+-define(BURST_LIMIT_WINDOW_TIME, 1000).
+
+%% This enables/disables the feature to automatically terminate the
+%% process if it gets too loaded (and can't keep up).
+-define(OVERLOAD_KILL_ENABLE, false).
+%% If the message_queue_len goes above this size even after
+%% flushing has been performed, the process is terminated.
+-define(OVERLOAD_KILL_QLEN, 20000).
+%% If the memory usage exceeds this level, the process is terminated.
+-define(OVERLOAD_KILL_MEM_SIZE, 3000000).
+
+%% This is the default time to wait before restarting and accepting
+%% new requests. The value 'infinity' disables restarts.
+-define(OVERLOAD_KILL_RESTART_AFTER, 5000).
+
+%% This is the time in milliseconds after last load message received
+%% that we notify the callback about being idle.
+-define(IDLE_DETECT_TIME, 100).
+
+%%%-----------------------------------------------------------------
+%%% Overload protection macros
+
+-define(timestamp(), erlang:monotonic_time(microsecond)).
+
+-define(get_mode(Tid),
+        case ets:lookup(Tid, mode) of
+            [{mode,M}] -> M;
+            _          -> async
+        end).
+
+-define(set_mode(Tid, M),
+        begin ets:insert(Tid, {mode,M}), M end).
+
+-define(change_mode(Tid, M0, M1),
+        if M0 == M1 ->
+                M0;
+           true ->
+                ets:insert(Tid, {mode,M1}),
+                M1
+        end).
+
+-define(max(X1, X2),
+        if 
+            X2 == undefined -> X1;
+            X2 > X1 -> X2;
+            true -> X1
+        end).
+
+-define(diff_time(OS_T1, OS_T0), OS_T1-OS_T0).
+
+%%%-----------------------------------------------------------------
+%%% These macros enable statistics counters in the state of the
+%%% process, which is useful for analysing the overload protection
+%%% behaviour. These counters should not be included in code to be
+%%% officially released (as some counters will grow very large over
+%%% time).
+
+%% -define(SAVE_STATS, true).
+-ifdef(SAVE_STATS).
+  -define(merge_with_stats(STATE),
+          begin
+              TIME = ?timestamp(),
+              STATE#{start => TIME, time => {TIME,0},
+                     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).
+
+  -define(update_max_qlen(QLEN, STATE),
+          begin #{max_qlen := QLEN0} = STATE,
+                STATE#{max_qlen => ?max(QLEN0,QLEN)} end).
+
+  -define(update_calls_or_casts(CALL_OR_CAST, INC, STATE),
+          case CALL_OR_CAST of
+              cast ->
+                  #{casts := CASTS0} = STATE,
+                  STATE#{casts => CASTS0+INC};
+              call ->
+                  #{calls := CALLS0} = STATE,
+                  STATE#{calls => CALLS0+INC}
+          end).
+
+  -define(update_max_time(TIME, STATE),
+          begin #{max_time := TIME0} = STATE,
+                STATE#{max_time => ?max(TIME0,TIME)} end).
+
+  -define(update_other(OTHER, VAR, INCVAL, STATE),
+          begin #{OTHER := VAR} = STATE,
+                STATE#{OTHER => VAR+INCVAL} end).
+
+  -define(update_freq(TIME,STATE),
+          begin
+              case STATE of
+                  #{freq := {START, 49, _}} ->
+                      STATE#{freq => {TIME, 0, trunc(1000000*50/(?diff_time(TIME,START)))}};
+                  #{freq := {START, N, FREQ}} ->
+                      STATE#{freq => {START, N+1, FREQ}}
+              end end).
+
+  -define(update_time(TIME,STATE),
+          begin #{start := START} = STATE,
+                STATE#{time => {TIME,trunc((?diff_time(TIME,START))/1000000)}} end).
+
+-else.                                          % DEFAULT!
+  -define(merge_with_stats(STATE), STATE).
+  -define(update_max_qlen(_QLEN, 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).
+  -define(update_freq(_TIME, STATE), STATE).
+  -define(update_time(_TIME, STATE), STATE).
+-endif.
+
+%%%-----------------------------------------------------------------
+%%% These macros enable callbacks that make it possible to analyse the
+%%% overload protection behaviour from outside the process (including
+%%% dropped requests on the client side). An external callback module
+%%% (?OBSERVER_MOD) is required which is not part of the kernel
+%%% application. For this reason, these callbacks should not be
+%%% included in code to be officially released.
+
+%%-define(OBSERVER_MOD, logger_test).
+-ifdef(OBSERVER_MOD).
+  -define(start_observation(NAME), ?OBSERVER:start_observation(NAME)).
+  -define(observe(NAME,EVENT), ?OBSERVER:observe(NAME,EVENT)).
+
+-else.                                          % DEFAULT!
+  -define(start_observation(_NAME), ok).
+  -define(observe(_NAME,_EVENT), ok).
+-endif.
diff --git a/lib/kernel/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl
index 63d1dbaba2..8c957578c8 100644
--- a/lib/kernel/src/logger_std_h.erl
+++ b/lib/kernel/src/logger_std_h.erl
@@ -36,6 +36,8 @@
 -export([log/2, adding_handler/1, removing_handler/1, changing_config/3,
          filter_config/1]).
 
+-define(DEFAULT_CALL_TIMEOUT, 5000).
+
 %%%===================================================================
 %%% API
 %%%===================================================================
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index 2b7b48bec0..ad342b5ef0 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -24,6 +24,7 @@
 -include_lib("common_test/include/ct.hrl").
 -include_lib("kernel/include/logger.hrl").
 -include_lib("kernel/src/logger_internal.hrl").
+-include_lib("kernel/src/logger_olp.hrl").
 -include_lib("kernel/src/logger_h_common.hrl").
 -include_lib("stdlib/include/ms_transform.hrl").
 -include_lib("kernel/include/file.hrl").
diff --git a/lib/kernel/test/logger_olp_SUITE.erl b/lib/kernel/test/logger_olp_SUITE.erl
index 8d08996755..8ba66e5a03 100644
--- a/lib/kernel/test/logger_olp_SUITE.erl
+++ b/lib/kernel/test/logger_olp_SUITE.erl
@@ -21,7 +21,7 @@
 
 -compile(export_all).
 
--include_lib("kernel/src/logger_h_common.hrl").
+-include_lib("kernel/src/logger_olp.hrl").
 
 suite() ->
     [{timetrap,{seconds,30}}].
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index b6ff87d058..25dcc20496 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -25,10 +25,15 @@
 -include_lib("kernel/include/logger.hrl").
 -include_lib("kernel/src/logger_internal.hrl").
 -include_lib("kernel/src/logger_h_common.hrl").
+-include_lib("kernel/src/logger_olp.hrl").
 -include_lib("stdlib/include/ms_transform.hrl").
 -include_lib("kernel/include/file.hrl").
 
--define(check_no_log, [] = test_server:messages_get()).
+-define(check_no_log,
+        begin
+            timer:sleep(?IDLE_DETECT_TIME*2),
+            [] = test_server:messages_get()
+        end).
 -define(check(Expected),
         receive
             {log,Expected} ->
@@ -420,10 +425,13 @@ crash_std_h(Config,Func,Var,Type,Log) ->
 %% logger would send the log event to the logger process here instead
 %% of logging it itself.
 log_on_remote_node(Node,Msg) ->
+    Pid = self(),
     _ = spawn_link(Node,
                    fun() -> erlang:group_leader(whereis(user),self()),
-                            logger:notice(Msg)
+                            logger:notice(Msg),
+                            Pid ! done
                    end),
+    receive done -> ok end,
     ok.