aboutsummaryrefslogtreecommitdiffstats
path: root/lib
diff options
context:
space:
mode:
Diffstat (limited to 'lib')
-rw-r--r--lib/kernel/doc/src/logger_chapter.xml12
-rw-r--r--lib/kernel/src/logger_h_common.erl16
-rw-r--r--lib/kernel/src/logger_h_common.hrl2
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl65
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl94
5 files changed, 123 insertions, 66 deletions
diff --git a/lib/kernel/doc/src/logger_chapter.xml b/lib/kernel/doc/src/logger_chapter.xml
index 0bc3b37476..5fb81034dc 100644
--- a/lib/kernel/doc/src/logger_chapter.xml
+++ b/lib/kernel/doc/src/logger_chapter.xml
@@ -700,7 +700,17 @@ my_report_cb(R) ->
<p>For the overload protection algorithm to work properly, it is a
requirement that:</p>
- <p><c>toggle_sync_qlen &lt; drop_new_reqs_qlen &lt; flush_reqs_qlen</c></p>
+ <p><c>toggle_sync_qlen =&lt; drop_new_reqs_qlen =&lt; flush_reqs_qlen</c></p>
+
+ <p>and that:</p>
+
+ <p><c>drop_new_reqs_qlen &gt; 1</c></p>
+
+ <p>If <c>toggle_sync_qlen</c> is set to <c>0</c>, the handler will handle all
+ requests synchronously. Setting the value of <c>toggle_sync_qlen</c> to the same
+ as <c>drop_new_reqs_qlen</c>, disables the synchronous mode. Likewise, setting
+ the value of <c>drop_new_reqs_qlen</c> to the same as <c>flush_reqs_qlen</c>,
+ disables the drop mode.</p>
<p>During high load scenarios, the length of the handler message queue
rarely grows in a linear and predictable way. Instead, whenever the
diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl
index 7caad366ae..901c4c0dad 100644
--- a/lib/kernel/src/logger_h_common.erl
+++ b/lib/kernel/src/logger_h_common.erl
@@ -135,7 +135,8 @@ call_cast_or_drop(Name, Bin) ->
_:{timeout,_} ->
?observe(Name,{dropped,1})
end;
- drop -> ?observe(Name,{dropped,1})
+ drop ->
+ ?observe(Name,{dropped,1})
catch
%% if the ETS table doesn't exist (maybe because of a
%% handler restart), we can only drop the request
@@ -152,12 +153,15 @@ check_load(State = #{id:=Name, mode := Mode,
flush_reqs_qlen := FlushQLen}) ->
{_,Mem} = process_info(self(), memory),
?observe(Name,{max_mem,Mem}),
- %% make sure the handler process doesn't get scheduled
- %% out between the message_queue_len check below and the
- %% action that follows (flush or write).
{_,QLen} = process_info(self(), message_queue_len),
?observe(Name,{max_qlen,QLen}),
-
+ %% When the handler process gets scheduled in, it's impossible
+ %% to predict the QLen. We could jump "up" arbitrarily from say
+ %% async to sync, async to drop, sync to flush, etc. However, when
+ %% the handler process manages the log requests (without flushing),
+ %% one after the other, we will move "down" from drop to sync and
+ %% from sync to async. This way we don't risk getting stuck in
+ %% drop or sync mode with an empty mailbox.
{Mode1,_NewDrops,_NewFlushes} =
if
QLen >= FlushQLen ->
@@ -292,7 +296,7 @@ overload_levels_ok(HandlerConfig) ->
TSQL = maps:get(toggle_sync_qlen, HandlerConfig, ?TOGGLE_SYNC_QLEN),
DNRQL = maps:get(drop_new_reqs_qlen, HandlerConfig, ?DROP_NEW_REQS_QLEN),
FRQL = maps:get(flush_reqs_qlen, HandlerConfig, ?FLUSH_REQS_QLEN),
- (TSQL < DNRQL) andalso (DNRQL < FRQL).
+ (DNRQL > 1) andalso (TSQL =< DNRQL) andalso (DNRQL =< FRQL).
error_notify(Term) ->
?internal_log(error, Term).
diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl
index 89378dbb10..ed365ce6eb 100644
--- a/lib/kernel/src/logger_h_common.hrl
+++ b/lib/kernel/src/logger_h_common.hrl
@@ -124,7 +124,7 @@
%%% slow down execution and therefore should not be include in code
%%% to be officially released.
-%% -define(TEST_HOOKS, true).
+-define(TEST_HOOKS, true).
-ifdef(TEST_HOOKS).
-define(TEST_HOOKS_TAB, logger_h_test_hooks).
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index c7c6137380..6a4ec72d5e 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -66,7 +66,19 @@ end_per_testcase(Case, Config) ->
ok.
groups() ->
- [].
+ [
+ {retry_op_switch_to_sync,
+ [{repeat_until_all_ok,10}],
+ [op_switch_to_sync]},
+
+ {retry_op_switch_to_drop,
+ [{repeat_until_all_ok,10}],
+ [op_switch_to_drop]},
+
+ {retry_op_switch_to_flush,
+ [{repeat_until_all_ok,10}],
+ [op_switch_to_flush]}
+ ].
all() ->
[start_stop_handler,
@@ -87,9 +99,9 @@ all() ->
disk_log_events,
write_failure,
sync_failure,
- op_switch_to_sync,
- op_switch_to_drop,
- op_switch_to_flush,
+ {group,retry_op_switch_to_sync},
+ {group,retry_op_switch_to_drop},
+ {group,retry_op_switch_to_flush},
limit_burst_disabled,
limit_burst_enabled_one,
limit_burst_enabled_period,
@@ -369,10 +381,18 @@ config_fail(_Config) ->
#{logger_disk_log_h => #{bad => bad},
filter_default=>log,
formatter=>{?MODULE,self()}}),
- {error,{handler_not_added,{invalid_levels,{42,42,_}}}} =
+
+ {error,{handler_not_added,{invalid_levels,{_,1,_}}}} =
logger:add_handler(?MODULE,logger_disk_log_h,
- #{logger_disk_log_h => #{toggle_sync_qlen=>42,
+ #{logger_disk_log_h => #{drop_new_reqs_qlen=>1}}),
+ {error,{handler_not_added,{invalid_levels,{43,42,_}}}} =
+ logger:add_handler(?MODULE,logger_disk_log_h,
+ #{logger_disk_log_h => #{toggle_sync_qlen=>43,
drop_new_reqs_qlen=>42}}),
+ {error,{handler_not_added,{invalid_levels,{_,43,42}}}} =
+ logger:add_handler(?MODULE,logger_disk_log_h,
+ #{logger_disk_log_h => #{drop_new_reqs_qlen=>43,
+ flush_reqs_qlen=>42}}),
ok = logger:add_handler(?MODULE,logger_disk_log_h,
#{filter_default=>log,
@@ -852,13 +872,13 @@ internal_log(Type, Term) ->
op_switch_to_sync(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+ NumOfReqs = 500,
NewHConfig =
- HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 3,
- drop_new_reqs_qlen => 501,
- flush_reqs_qlen => 2000,
+ HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2,
+ drop_new_reqs_qlen => NumOfReqs+1,
+ flush_reqs_qlen => 2*NumOfReqs,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- NumOfReqs = 500,
send_burst({n,NumOfReqs}, seq, {chars,79}, info),
NumOfReqs = count_lines(Log),
ok = file:delete(Log).
@@ -867,19 +887,20 @@ op_switch_to_sync(cleanup, _Config) ->
op_switch_to_drop(Config) ->
{Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
-
+ NumOfReqs = 300,
+ Procs = 2,
NewHConfig =
- HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2,
- drop_new_reqs_qlen => 3,
- flush_reqs_qlen => 600,
+ HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 1,
+ drop_new_reqs_qlen => 2,
+ flush_reqs_qlen => Procs*NumOfReqs+1,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- NumOfReqs = 500,
- send_burst({n,NumOfReqs}, seq, {chars,79}, info),
+ send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info),
Logged = count_lines(Log),
ct:pal("Number of messages dropped = ~w (~w)",
- [NumOfReqs-Logged,NumOfReqs]),
- true = (Logged < NumOfReqs),
+ [Procs*NumOfReqs-Logged,Procs*NumOfReqs]),
+ true = (Logged < (Procs*NumOfReqs)),
+ true = (Logged > 0),
ok = file:delete(Log).
op_switch_to_drop(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -894,17 +915,19 @@ op_switch_to_flush(Config) ->
NewHConfig =
HConfig#{logger_disk_log_h => DLHConfig#{toggle_sync_qlen => 2,
- drop_new_reqs_qlen => 99,
- flush_reqs_qlen => 100,
+ %% disable drop mode
+ drop_new_reqs_qlen => 500,
+ flush_reqs_qlen => 500,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
NumOfReqs = 1000,
- Procs = 500,
+ Procs = 200,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info),
Logged = count_lines(Log),
ct:pal("Number of messages flushed/dropped = ~w (~w)",
[(NumOfReqs*Procs)-Logged,NumOfReqs*Procs]),
true = (Logged < (NumOfReqs*Procs)),
+ true = (Logged > 0),
ok = file:delete(Log).
op_switch_to_flush(cleanup, _Config) ->
ok = stop_handler(?MODULE).
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index e940e0a026..ed5504431e 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -89,7 +89,19 @@ end_per_testcase(Case, Config) ->
ok.
groups() ->
- [].
+ [
+ {retry_op_switch_to_sync_file,
+ [{repeat_until_all_ok,10}],
+ [op_switch_to_sync_file]},
+
+ {retry_op_switch_to_drop_file,
+ [{repeat_until_all_ok,10}],
+ [op_switch_to_drop_file]},
+
+ {retry_op_switch_to_flush_file,
+ [{repeat_until_all_ok,10}],
+ [op_switch_to_flush_file]}
+ ].
all() ->
[add_remove_instance_tty,
@@ -110,11 +122,11 @@ all() ->
filesync,
write_failure,
sync_failure,
- op_switch_to_sync_file,
+ {group,retry_op_switch_to_sync_file},
op_switch_to_sync_tty,
- op_switch_to_drop_file,
+ {group,retry_op_switch_to_drop_file},
op_switch_to_drop_tty,
- op_switch_to_flush_file,
+ {group,retry_op_switch_to_flush_file},
op_switch_to_flush_tty,
limit_burst_disabled,
limit_burst_enabled_one,
@@ -289,10 +301,17 @@ config_fail(_Config) ->
#{logger_std_h => #{restart_type => bad},
filter_default=>log,
formatter=>{?MODULE,self()}}),
- {error,{handler_not_added,{invalid_levels,{42,42,_}}}} =
+ {error,{handler_not_added,{invalid_levels,{_,1,_}}}} =
+ logger:add_handler(?MODULE,logger_std_h,
+ #{logger_std_h => #{drop_new_reqs_qlen=>1}}),
+ {error,{handler_not_added,{invalid_levels,{43,42,_}}}} =
logger:add_handler(?MODULE,logger_std_h,
- #{logger_std_h => #{toggle_sync_qlen=>42,
+ #{logger_std_h => #{toggle_sync_qlen=>43,
drop_new_reqs_qlen=>42}}),
+ {error,{handler_not_added,{invalid_levels,{_,43,42}}}} =
+ logger:add_handler(?MODULE,logger_std_h,
+ #{logger_std_h => #{drop_new_reqs_qlen=>43,
+ flush_reqs_qlen=>42}}),
ok = logger:add_handler(?MODULE,logger_std_h,
#{filter_default=>log,
@@ -698,14 +717,14 @@ internal_log(Type, Term) ->
op_switch_to_sync_file(Config) ->
{Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
+ NumOfReqs = 500,
NewHConfig =
- HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3,
- drop_new_reqs_qlen => 501,
- flush_reqs_qlen => 2000,
+ HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2,
+ drop_new_reqs_qlen => NumOfReqs+1,
+ flush_reqs_qlen => 2*NumOfReqs,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
%% TRecvPid = start_op_trace(),
- NumOfReqs = 500,
send_burst({n,NumOfReqs}, seq, {chars,79}, info),
NumOfReqs = count_lines(Log),
%% true = analyse_trace(TRecvPid,
@@ -726,13 +745,13 @@ op_switch_to_sync_file(cleanup, _Config) ->
op_switch_to_sync_tty(Config) ->
{HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config),
+ NumOfReqs = 500,
NewHConfig =
HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 3,
- drop_new_reqs_qlen => 501,
- flush_reqs_qlen => 2000,
+ drop_new_reqs_qlen => NumOfReqs+1,
+ flush_reqs_qlen => 2*NumOfReqs,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- NumOfReqs = 500,
send_burst({n,NumOfReqs}, seq, {chars,79}, info),
ok.
op_switch_to_sync_tty(cleanup, _Config) ->
@@ -740,20 +759,21 @@ op_switch_to_sync_tty(cleanup, _Config) ->
op_switch_to_drop_file(Config) ->
{Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config),
-
+ NumOfReqs = 300,
+ Procs = 2,
NewHConfig =
- HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2,
- drop_new_reqs_qlen => 3,
- flush_reqs_qlen => 600,
+ HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 1,
+ drop_new_reqs_qlen => 2,
+ flush_reqs_qlen => Procs*NumOfReqs+1,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
%% TRecvPid = start_op_trace(),
- NumOfReqs = 500,
- send_burst({n,NumOfReqs}, seq, {chars,79}, info),
+ send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info),
Logged = count_lines(Log),
ct:pal("Number of messages dropped = ~w (~w)",
- [NumOfReqs-Logged,NumOfReqs]),
- true = (Logged < NumOfReqs),
+ [Procs*NumOfReqs-Logged,Procs*NumOfReqs]),
+ true = (Logged < (Procs*NumOfReqs)),
+ true = (Logged > 0),
%% true = analyse_trace(TRecvPid,
%% fun(Events) -> find_mode(async,Events) end),
%% true = analyse_trace(TRecvPid,
@@ -772,14 +792,15 @@ op_switch_to_drop_file(cleanup, _Config) ->
op_switch_to_drop_tty(Config) ->
{HConfig,StdHConfig} = start_handler(?MODULE, standard_io, Config),
+ NumOfReqs = 300,
+ Procs = 2,
NewHConfig =
- HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2,
- drop_new_reqs_qlen => 3,
- flush_reqs_qlen => 600,
+ HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 1,
+ drop_new_reqs_qlen => 2,
+ flush_reqs_qlen => Procs*NumOfReqs+1,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- NumOfReqs = 500,
- send_burst({n,NumOfReqs}, seq, {chars,79}, info),
+ send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info),
ok.
op_switch_to_drop_tty(cleanup, _Config) ->
ok = stop_handler(?MODULE).
@@ -794,21 +815,19 @@ op_switch_to_flush_file(Config) ->
NewHConfig =
HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2,
- drop_new_reqs_qlen => 99,
- flush_reqs_qlen => 100,
+ %% disable drop mode
+ drop_new_reqs_qlen => 500,
+ flush_reqs_qlen => 500,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- NumOfReqs = 10000,
- Procs = 100,
+ NumOfReqs = 1000,
+ Procs = 200,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info),
Logged = count_lines(Log),
ct:pal("Number of messages flushed/dropped = ~w (~w)",
[(NumOfReqs*Procs)-Logged,NumOfReqs*Procs]),
true = (Logged < (NumOfReqs*Procs)),
-
- %%! --- Thu Apr 12 13:46:00 2018 --- peppe was here!
- %%! TODO: Verify that handler has switched to flush mode
-
+ true = (Logged > 0),
ok = file:delete(Log),
ok.
op_switch_to_flush_file(cleanup, _Config) ->
@@ -822,12 +841,13 @@ op_switch_to_flush_tty(Config) ->
NewHConfig =
HConfig#{logger_std_h => StdHConfig#{toggle_sync_qlen => 2,
- drop_new_reqs_qlen => 99,
+ %% disable drop mode
+ drop_new_reqs_qlen => 100,
flush_reqs_qlen => 100,
enable_burst_limit => false}},
ok = logger:set_handler_config(?MODULE, NewHConfig),
- NumOfReqs = 10000,
- Procs = 10,
+ NumOfReqs = 1000,
+ Procs = 100,
send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info),
ok.
op_switch_to_flush_tty(cleanup, _Config) ->