aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
Diffstat
-rw-r--r--lib/kernel/src/logger_h_common.hrl8
-rw-r--r--lib/kernel/src/logger_olp.erl97
-rw-r--r--lib/kernel/test/Makefile1
-rw-r--r--lib/kernel/test/logger.spec1
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl9
-rw-r--r--lib/kernel/test/logger_olp_SUITE.erl89
-rw-r--r--lib/kernel/test/logger_std_h_SUITE.erl8
7 files changed, 143 insertions, 70 deletions
diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl
index f2c2dc2a4e..f2d642f6f0 100644
--- a/lib/kernel/src/logger_h_common.hrl
+++ b/lib/kernel/src/logger_h_common.hrl
@@ -65,11 +65,9 @@
-define(FILESYNC_REPEAT_INTERVAL, 5000).
%%-define(FILESYNC_REPEAT_INTERVAL, no_repeat).
-%% This is the time after last message received that we think/hope
-%% that the handler has an empty mailbox (no new log request has
-%% come in).
--define(IDLE_DETECT_TIME_MSEC, 100).
--define(IDLE_DETECT_TIME_USEC, 100000).
+%% 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).
diff --git a/lib/kernel/src/logger_olp.erl b/lib/kernel/src/logger_olp.erl
index fbc2e81882..f35577d43a 100644
--- a/lib/kernel/src/logger_olp.erl
+++ b/lib/kernel/src/logger_olp.erl
@@ -188,6 +188,7 @@ init([Name,Module,Args,Options]) ->
%% (sending) the option data with each message
State0 = ?merge_with_stats(
Options#{id => Name,
+ idle=> true,
module => Module,
mode_ref => ModeRef,
mode => async,
@@ -216,34 +217,35 @@ init([Name,Module,Args,Options]) ->
%% This is the synchronous load event.
handle_call({'$olp_load', Msg}, _From, State) ->
- {Result,State1} = do_load(Msg, call, State),
+ {Result,State1} = do_load(Msg, call, State#{idle=>false}),
%% Result == ok | dropped
- {reply,Result, State1};
+ reply_return(Result,State1);
handle_call(get_ref,_From,#{id:=Name,mode_ref:=ModeRef}=State) ->
- {reply,{Name,self(),ModeRef},State};
+ reply_return({Name,self(),ModeRef},State);
handle_call({set_opts,Opts0},_From,State) ->
Opts = maps:merge(maps:with(?OPT_KEYS,State),Opts0),
case check_opts(Opts) of
ok ->
- {reply, ok, maps:merge(State,Opts)};
+ reply_return(ok, maps:merge(State,Opts));
Error ->
- {reply, Error, State}
+ reply_return(Error, State)
end;
handle_call(get_opts,_From,State) ->
- {reply, maps:with(?OPT_KEYS,State), State};
+ reply_return(maps:with(?OPT_KEYS,State), State);
handle_call(info, _From, State) ->
- {reply, State, State};
+ reply_return(State, State);
handle_call(reset, _From, #{module:=Module,cb_state:=CBState}=State) ->
State1 = ?merge_with_stats(State),
CBState1 = try_callback_call(Module,reset_state,[CBState],CBState),
- {reply, ok, State1#{last_qlen => 0,
- last_load_ts => ?timestamp(),
- cb_state => CBState1}};
+ reply_return(ok, State1#{idle => true,
+ last_qlen => 0,
+ last_load_ts => ?timestamp(),
+ cb_state => CBState1});
handle_call(stop, _From, State) ->
{stop, {shutdown,stopped}, ok, State};
@@ -251,37 +253,36 @@ handle_call(stop, _From, State) ->
handle_call(Msg, From, #{module:=Module,cb_state:=CBState}=State) ->
case try_callback_call(Module,handle_call,[Msg, From, CBState]) of
{reply,Reply,CBState1} ->
- {reply,Reply,State#{cb_state=>CBState1}};
- {reply,Reply,CBState1,Timeout}->
- {reply,Reply,State#{cb_state=>CBState1},Timeout};
+ reply_return(Reply,State#{cb_state=>CBState1});
{noreply,CBState1} ->
- {noreply,State#{cb_state=>CBState1}};
- {noreply,CBState1,Timeout} ->
- {noreply,State#{cb_state=>CBState1},Timeout}
+ noreply_return(State#{cb_state=>CBState1})
end.
%% This is the asynchronous load event.
handle_cast({'$olp_load', Msg}, State) ->
- {_Result,State1} = do_load(Msg, cast, State),
- {noreply,State1};
+ {_Result,State1} = do_load(Msg, cast, State#{idle=>false}),
+ noreply_return(State1);
handle_cast(Msg, #{module:=Module, cb_state:=CBState} = State) ->
case try_callback_call(Module,handle_cast,[Msg, CBState]) of
{noreply,CBState1} ->
- {noreply,State#{cb_state=>CBState1}};
- {noreply,CBState1,Timeout} ->
- {noreply,State#{cb_state=>CBState1},Timeout}
+ noreply_return(State#{cb_state=>CBState1})
end.
+handle_info(timeout, #{mode_ref:=_ModeRef, mode:=Mode} = State) ->
+ State1 = notify(idle,State),
+ State2 = maybe_notify_mode_change(async,State1),
+ {noreply, State2#{idle => true,
+ mode => ?change_mode(_ModeRef, Mode, async),
+ burst_msg_count => 0}};
handle_info(Msg, #{module := Module, cb_state := CBState} = State) ->
case try_callback_call(Module,handle_info,[Msg, CBState]) of
{noreply,CBState1} ->
- {noreply,State#{cb_state=>CBState1}};
- {noreply,CBState1,Timeout} ->
- {noreply,State#{cb_state=>CBState1},Timeout};
+ noreply_return(State#{cb_state=>CBState1});
{load,CBState1} ->
- {_,State1} = do_load(Msg, cast, State#{cb_state=>CBState1}),
- {noreply,State1}
+ {_,State1} = do_load(Msg, cast, State#{idle=>false,
+ cb_state=>CBState1}),
+ noreply_return(State1)
end.
terminate({shutdown,{overloaded,_QLen,_Mem}},
@@ -368,7 +369,7 @@ flush(T1, State=#{id := _Name, mode := Mode, last_load_ts := _T0, mode_ref := Mo
State2 = ?update_max_time(?diff_time(T1,_T0),State1),
State3 = ?update_max_qlen(QLen1,State2),
- State4 = maybe_notify_mode_change(async,QLen1,State3),
+ State4 = maybe_notify_mode_change(async,State3),
{dropped,?update_other(flushed,FLUSHED,NewFlushed,
State4#{mode => ?change_mode(ModeRef,Mode,async),
last_qlen => QLen1,
@@ -379,9 +380,8 @@ handle_load(Mode, T1, Msg, _CallOrCast,
State = #{id := _Name,
module := Module,
cb_state := CBState,
- mode_ref := ModeRef,
last_qlen := LastQLen,
- last_load_ts := T0}) ->
+ last_load_ts := _T0}) ->
%% check if we need to limit the number of writes
%% during a burst of log events
{DoWrite,State1} = limit_burst(State),
@@ -397,28 +397,11 @@ handle_load(Mode, T1, Msg, _CallOrCast,
end,
State2 = State1#{cb_state=>CBState1},
- %% Check if the time since the previous load message is long
- %% enough - and the queue length small enough - to assume the
- %% mailbox has been emptied, and if so, reset mode to async. Note
- %% that this is the best we can do to detect an idle handler
- %% without setting a timer after each log call/cast. If the time
- %% between two consecutive log events is fast and no new event
- %% comes in after the last one, idle state won't be detected!
- Time = ?diff_time(T1,T0),
- State3 =
- if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso
- (Time > ?IDLE_DETECT_TIME_USEC) ->
- S1 = notify(idle,State2),
- S2 = maybe_notify_mode_change(async,LastQLen1,S1),
- S2#{mode => ?change_mode(ModeRef, Mode, async),
- burst_msg_count => 0};
- true ->
- State2#{mode => Mode}
- end,
+ State3 = State2#{mode => Mode},
State4 = ?update_calls_or_casts(_CallOrCast,1,State3),
State5 = ?update_max_qlen(LastQLen1,State4),
State6 =
- ?update_max_time(Time,
+ ?update_max_time(?diff_time(T1,_T0),
State5#{last_qlen := LastQLen1,
last_load_ts => T1}),
State7 = case Result of
@@ -525,7 +508,7 @@ 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,QLen,State2),
+ State3 = maybe_notify_mode_change(Mode1,State2),
{Mode1, QLen, Mem,
?update_other(flushes,FLUSHES,_NewFlushes,
State3#{last_qlen => QLen})}.
@@ -596,13 +579,13 @@ overload_levels_ok(Options) ->
FQL = maps:get(flush_qlen, Options, ?FLUSH_QLEN),
(DMQL > 1) andalso (SMQL =< DMQL) andalso (DMQL =< FQL).
-maybe_notify_mode_change(drop,_QLen,#{mode:=Mode0}=State)
+maybe_notify_mode_change(drop,#{mode:=Mode0}=State)
when Mode0=/=drop ->
notify({mode_change,Mode0,drop},State);
-maybe_notify_mode_change(Mode1,_QLen,#{mode:=drop}=State)
+maybe_notify_mode_change(Mode1,#{mode:=drop}=State)
when Mode1==async; Mode1==sync ->
notify({mode_change,drop,Mode1},State);
-maybe_notify_mode_change(_,_,State) ->
+maybe_notify_mode_change(_,State) ->
State.
notify(Note,#{module:=Module,cb_state:=CBState}=State) ->
@@ -624,3 +607,13 @@ try_callback_call(Module, Function, Args, DefRet) ->
erlang:raise(error,undef,S)
end
end.
+
+noreply_return(#{idle:=true}=State) ->
+ {noreply,State};
+noreply_return(#{idle:=false}=State) ->
+ {noreply,State,?IDLE_DETECT_TIME}.
+
+reply_return(Reply,#{idle:=true}=State) ->
+ {reply,Reply,State};
+reply_return(Reply,#{idle:=false}=State) ->
+ {reply,Reply,State,?IDLE_DETECT_TIME}.
diff --git a/lib/kernel/test/Makefile b/lib/kernel/test/Makefile
index e510cf6531..8a6ffe7e72 100644
--- a/lib/kernel/test/Makefile
+++ b/lib/kernel/test/Makefile
@@ -76,6 +76,7 @@ MODULES= \
logger_filters_SUITE \
logger_formatter_SUITE \
logger_legacy_SUITE \
+ logger_olp_SUITE \
logger_proxy_SUITE \
logger_simple_h_SUITE \
logger_std_h_SUITE \
diff --git a/lib/kernel/test/logger.spec b/lib/kernel/test/logger.spec
index 553b4f7078..3aec37951d 100644
--- a/lib/kernel/test/logger.spec
+++ b/lib/kernel/test/logger.spec
@@ -7,6 +7,7 @@
logger_filters_SUITE,
logger_formatter_SUITE,
logger_legacy_SUITE,
+ logger_olp_SUITE,
logger_proxy_SUITE,
logger_simple_h_SUITE,
logger_std_h_SUITE]}.
diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl
index 1fc7605914..2b7b48bec0 100644
--- a/lib/kernel/test/logger_disk_log_h_SUITE.erl
+++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl
@@ -647,13 +647,8 @@ sync(Config) ->
{ok,#{config := HConfig}} = logger:get_handler_config(?MODULE),
HConfig1 = HConfig#{filesync_repeat_interval => no_repeat},
ok = logger:update_handler_config(?MODULE, config, HConfig1),
-
no_repeat = maps:get(filesync_repeat_interval,
maps:get(cb_state,logger_disk_log_h:info(?MODULE))),
- %% The following timer is to make sure the time from last log
- %% ("first") to next ("second") is long enough, so the a flush is
- %% triggered by the idle timeout between "fourth" and "fifth".
- timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
start_tracer([{logger_disk_log_h,disk_log_write,3},
{disk_log,sync,1}],
@@ -663,10 +658,10 @@ sync(Config) ->
{disk_log,sync}]),
logger:notice("second", ?domain),
- timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
+ timer:sleep(?IDLE_DETECT_TIME*2),
logger:notice("third", ?domain),
%% wait for automatic disk_log_sync
- check_tracer(?IDLE_DETECT_TIME_MSEC*2),
+ check_tracer(?IDLE_DETECT_TIME*2),
try_read_file(Log, {ok,<<"first\nsecond\nthird\n">>}, 1000),
diff --git a/lib/kernel/test/logger_olp_SUITE.erl b/lib/kernel/test/logger_olp_SUITE.erl
new file mode 100644
index 0000000000..8d08996755
--- /dev/null
+++ b/lib/kernel/test/logger_olp_SUITE.erl
@@ -0,0 +1,89 @@
+%%
+%% %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_olp_SUITE).
+
+-compile(export_all).
+
+-include_lib("kernel/src/logger_h_common.hrl").
+
+suite() ->
+ [{timetrap,{seconds,30}}].
+
+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() ->
+ [idle_timer].
+
+%%%-----------------------------------------------------------------
+%%% Test cases
+idle_timer(_Config) ->
+ {ok,Pid,Olp} = logger_olp:start_link(?MODULE,?MODULE,self(),#{}),
+ [logger_olp:load(Olp,{msg,N}) || N<-lists:seq(1,3)],
+ timer:sleep(?IDLE_DETECT_TIME*2),
+ [{load,{msg,1}},
+ {load,{msg,2}},
+ {load,{msg,3}},
+ {notify,idle}] = test_server:messages_get(),
+ logger_olp:cast(Olp,hello),
+ timer:sleep(?IDLE_DETECT_TIME*2),
+ [{cast,hello}] = test_server:messages_get(),
+ ok.
+idle_timer(cleanup,_Config) ->
+ logger_olp:stop(?MODULE),
+ ok.
+
+%%%-----------------------------------------------------------------
+%%% Olp callbacks
+init(P) ->
+ {ok,P}.
+
+handle_load(M,P) ->
+ P ! {load,M},
+ P.
+
+handle_cast(M,P) ->
+ P ! {cast,M},
+ {noreply,P}.
+
+notify(N,P) ->
+ P ! {notify,N},
+ P.
diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl
index e8f1c34f44..b6ff87d058 100644
--- a/lib/kernel/test/logger_std_h_SUITE.erl
+++ b/lib/kernel/test/logger_std_h_SUITE.erl
@@ -673,10 +673,6 @@ sync(Config) ->
#{filesync_repeat_interval => no_repeat}),
no_repeat = maps:get(filesync_repeat_interval,
maps:get(cb_state, logger_std_h:info(?MODULE))),
- %% The following timer is to make sure the time from last log
- %% ("second") to next ("third") is long enough, so the a flush is
- %% triggered by the idle timeout between "thrid" and "fourth".
- timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
start_tracer([{logger_std_h, write_to_dev, 5},
{file, datasync, 1}],
[{logger_std_h, write_to_dev, <<"third\n">>},
@@ -685,10 +681,10 @@ sync(Config) ->
{file,datasync}]),
logger:notice("third", ?domain),
%% wait for automatic filesync
- timer:sleep(?IDLE_DETECT_TIME_MSEC*2),
+ timer:sleep(?IDLE_DETECT_TIME*2),
logger:notice("fourth", ?domain),
%% wait for automatic filesync
- check_tracer(?IDLE_DETECT_TIME_MSEC*2),
+ check_tracer(?IDLE_DETECT_TIME*2),
%% switch repeated filesync on and verify that the looping works
SyncInt = 1000,
generated by cgit v1.2.3 (git 2.25.1) at 2024-12-29 15:44:23 +0000