[logger] Add idle timer in logger_olp

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,