From f68e91a318912a34f38ea437365c8843af54f66f Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Thu, 20 Dec 2018 16:49:45 +0100 Subject: [logger] Add idle timer in logger_olp --- lib/kernel/src/logger_h_common.hrl | 8 +-- lib/kernel/src/logger_olp.erl | 97 +++++++++++++---------------- lib/kernel/test/Makefile | 1 + lib/kernel/test/logger.spec | 1 + lib/kernel/test/logger_disk_log_h_SUITE.erl | 9 +-- lib/kernel/test/logger_olp_SUITE.erl | 89 ++++++++++++++++++++++++++ lib/kernel/test/logger_std_h_SUITE.erl | 8 +-- 7 files changed, 143 insertions(+), 70 deletions(-) create mode 100644 lib/kernel/test/logger_olp_SUITE.erl (limited to 'lib/kernel') 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, -- cgit v1.2.3