diff options
| -rw-r--r-- | lib/kernel/src/logger_disk_log_h.erl | 121 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.erl | 32 | ||||
| -rw-r--r-- | lib/kernel/src/logger_h_common.hrl | 25 | ||||
| -rw-r--r-- | lib/kernel/src/logger_std_h.erl | 122 | ||||
| -rw-r--r-- | lib/kernel/test/logger_disk_log_h_SUITE.erl | 54 | ||||
| -rw-r--r-- | lib/kernel/test/logger_std_h_SUITE.erl | 48 |
6 files changed, 232 insertions, 170 deletions
diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 00643b6a84..ba90fefcd3 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -63,7 +63,8 @@ start_link(Name, Config, HandlerState) -> sync(Name) when is_atom(Name) -> try - gen_server:call(Name, disk_log_sync, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + disk_log_sync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -79,7 +80,8 @@ sync(Name) -> info(Name) when is_atom(Name) -> try - gen_server:call(Name, info, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + info, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -94,7 +96,8 @@ info(Name) -> reset(Name) when is_atom(Name) -> try - gen_server:call(Name, reset, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + reset, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -117,10 +120,10 @@ adding_handler(#{id:=Name}=Config) -> case logger_h_common:overload_levels_ok(HState) of true -> case start(Name, Config1, HState) of - ok -> + {ok,Config2} -> %% Make sure wait_for_buffer is not stored, so we %% won't hang and wait for buffer on a restart - {ok, maps:remove(wait_for_buffer,Config1)}; + {ok, maps:remove(wait_for_buffer,Config2)}; Error -> Error end; @@ -136,13 +139,18 @@ adding_handler(#{id:=Name}=Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts}, +changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts, ?MODULE:=HConfig}, NewConfig=#{id:=Name, disk_log_opts:=DLOpts}) -> case check_config(changing, NewConfig) of - Result = {ok,NewConfig1} -> - try gen_server:call(Name, {change_config,OldConfig,NewConfig1}, + {ok,NewConfig1 = #{?MODULE:=NewHConfig}} -> + #{handler_pid:=HPid, + mode_tab:=ModeTab} = HConfig, + NewHConfig1 = NewHConfig#{handler_pid=>HPid, + mode_tab=>ModeTab}, + NewConfig2 = NewConfig1#{?MODULE=>NewHConfig1}, + try gen_server:call(HPid, {change_config,OldConfig,NewConfig2}, ?DEFAULT_CALL_TIMEOUT) of - ok -> Result; + ok -> {ok,NewConfig2}; HError -> HError catch _:{timeout,_} -> {error,handler_busy} @@ -225,12 +233,12 @@ removing_handler(#{id:=Name}) -> %%%----------------------------------------------------------------- %%% Get buffer when swapping from simple handler -swap_buffer(Name,Buffer) -> - case whereis(Name) of +swap_buffer(Name, Buffer) -> + case whereis(?name_to_reg_name(?MODULE,Name)) of undefined -> ok; - _ -> - Name ! {buffer,Buffer} + Pid -> + Pid ! {buffer,Buffer} end. %%%----------------------------------------------------------------- @@ -239,21 +247,22 @@ swap_buffer(Name,Buffer) -> LogEvent :: logger:log_event(), Config :: logger:config(). -log(LogEvent,Config=#{id:=Name}) -> +log(LogEvent, Config = #{id := Name, + ?MODULE := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> %% if the handler has crashed, we must drop this request %% and hope the handler restarts so we can try again - true = is_pid(whereis(Name)), - Bin = logger_h_common:log_to_binary(LogEvent,Config), - logger_h_common:call_cast_or_drop(Name, Bin). - + true = is_process_alive(HPid), + Bin = logger_h_common:log_to_binary(LogEvent, Config), + logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). %%%=================================================================== %%% gen_server callbacks %%%=================================================================== -init([Name, Config = #{disk_log_opts := LogOpts}, +init([Name, Config = #{?MODULE := HConfig, disk_log_opts := LogOpts}, State = #{dl_sync_int := DLSyncInt}]) -> - register(Name, self()), + register(?name_to_reg_name(?MODULE,Name), self()), process_flag(trap_exit, true), process_flag(message_queue_data, off_heap), @@ -262,25 +271,36 @@ init([Name, Config = #{disk_log_opts := LogOpts}, case open_disk_log(Name, LogOpts) of ok -> - catch ets:new(Name, [public, named_table]), - ?set_mode(Name, async), - proc_lib:init_ack({ok,self()}), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{id => Name, - mode => async, - dl_sync => DLSyncInt, - log_opts => LogOpts, - last_qlen => 0, - last_log_ts => T0, - burst_win_ts => T0, - burst_msg_count => 0, - last_op => sync, - prev_log_result => ok, - prev_sync_result => ok, - prev_disk_log_info => undefined}), - gen_server:cast(self(), repeated_disk_log_sync), - enter_loop(Config, State1); + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + T0 = ?timestamp(), + State1 = + ?merge_with_stats(State#{ + id => Name, + mode_tab => ModeTab, + mode => async, + dl_sync => DLSyncInt, + log_opts => LogOpts, + last_qlen => 0, + last_log_ts => T0, + burst_win_ts => T0, + burst_msg_count => 0, + last_op => sync, + prev_log_result => ok, + prev_sync_result => ok, + prev_disk_log_info => undefined}), + Config1 = + Config#{?MODULE => HConfig#{handler_pid => self(), + mode_tab => ModeTab}}, + proc_lib:init_ack({ok,self(),Config1}), + gen_server:cast(self(), repeated_disk_log_sync), + enter_loop(Config1, State1) + catch + _:Error -> + logger_h_common:error_notify({open_disk_log,Name,Error}), + proc_lib:init_ack(Error) + end; Error -> logger_h_common:error_notify({open_disk_log,Name,Error}), proc_lib:init_ack(Error) @@ -477,8 +497,8 @@ start(Name, Config, HandlerState) -> type => worker, modules => [?MODULE]}, case supervisor:start_child(logger_sup, LoggerDLH) of - {ok,_} -> - ok; + {ok,_Pid,Config1} -> + {ok,Config1}; Error -> Error end. @@ -486,16 +506,16 @@ start(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% Stop and remove the handler. stop(Name) -> - case whereis(Name) of + case whereis(?name_to_reg_name(?MODULE,Name)) of undefined -> ok; - _ -> + Pid -> %% We don't want to do supervisor:terminate_child here %% since we need to distinguish this explicit stop from a %% system termination in order to avoid circular attempts %% at removing the handler (implying deadlocks and %% timeouts). - _ = gen_server:call(Name,stop), + _ = gen_server:call(Pid, stop), _ = supervisor:delete_child(logger_sup, Name), ok end. @@ -530,7 +550,7 @@ do_log(Bin, CallOrCast, State = #{id:=Name, mode := _Mode0}) -> %% this function is called by do_log/3 after an overload check %% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> +flush(_Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> %% flush messages in the mailbox (a limited number in %% order to not cause long delays) _NewFlushed = logger_h_common:flush_log_requests(?FLUSH_MAX_N), @@ -539,20 +559,21 @@ flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> %% handler will be scheduled out often and the mailbox could %% grow very large, so we'd better check the queue again here {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), + ?observe(_Name,{max_qlen,_QLen1}), %% Add 1 for the current log request - ?observe(Name,{flushed,_NewFlushed+1}), + ?observe(_Name,{flushed,_NewFlushed+1}), State1 = ?update_max_time(?diff_time(T1,_T0),State), {dropped,?update_other(flushed,FLUSHED,_NewFlushed, - State1#{mode => ?set_mode(Name,async), + State1#{mode => ?set_mode(ModeTab,async), last_qlen => 0, last_log_ts => T1})}. %% this function is called to write to disk_log write(Name, Mode, T1, Bin, _CallOrCast, - State = #{dl_sync := DLSync, + State = #{mode_tab := ModeTab, + dl_sync := DLSync, dl_sync_int := DLSyncInt, last_qlen := LastQLen, last_log_ts := T0}) -> @@ -589,7 +610,7 @@ write(Name, Mode, T1, Bin, _CallOrCast, {Mode1,BurstMsgCount1,State2} = if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso (Time > ?IDLE_DETECT_TIME_USEC) -> - {?change_mode(Name,Mode,async), 0, disk_log_sync(Name,State1)}; + {?change_mode(ModeTab,Mode,async), 0, disk_log_sync(Name,State1)}; true -> {Mode, BurstMsgCount,State1} end, diff --git a/lib/kernel/src/logger_h_common.erl b/lib/kernel/src/logger_h_common.erl index 336398cd4a..73a5b27ea1 100644 --- a/lib/kernel/src/logger_h_common.erl +++ b/lib/kernel/src/logger_h_common.erl @@ -24,7 +24,7 @@ -export([log_to_binary/2, check_common_config/1, - call_cast_or_drop/2, + call_cast_or_drop/4, check_load/1, limit_burst/1, kill_if_choked/4, @@ -84,6 +84,10 @@ try_format(Log,Formatter,FormatterConfig) -> %%%----------------------------------------------------------------- %%% Check that the configuration term is valid +check_common_config({mode_tab,_Tid}) -> + valid; +check_common_config({handler_pid,Pid}) when is_pid(Pid) -> + valid; check_common_config({toggle_sync_qlen,N}) when is_integer(N) -> valid; check_common_config({drop_new_reqs_qlen,N}) when is_integer(N) -> @@ -116,16 +120,16 @@ check_common_config(_) -> %%%----------------------------------------------------------------- %%% Overload Protection -call_cast_or_drop(Name, Bin) -> +call_cast_or_drop(_Name, HandlerPid, ModeTab, Bin) -> %% If the handler process is getting overloaded, the log request %% will be synchronous instead of asynchronous (slows down the %% logging tempo of a process doing lots of logging. If the %% handler is choked, drop mode is set and no request will be sent. - try ?get_mode(Name) of + try ?get_mode(ModeTab) of async -> - gen_server:cast(Name, {log,Bin}); + gen_server:cast(HandlerPid, {log,Bin}); sync -> - try gen_server:call(Name, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of + try gen_server:call(HandlerPid, {log,Bin}, ?DEFAULT_CALL_TIMEOUT) of %% if return value from call == dropped, the %% message has been flushed by handler and should %% therefore not be counted as dropped in stats @@ -133,28 +137,28 @@ call_cast_or_drop(Name, Bin) -> dropped -> ok catch _:{timeout,_} -> - ?observe(Name,{dropped,1}) + ?observe(_Name,{dropped,1}) end; drop -> - ?observe(Name,{dropped,1}) + ?observe(_Name,{dropped,1}) catch %% if the ETS table doesn't exist (maybe because of a %% handler restart), we can only drop the request - _:_ -> ?observe(Name,{dropped,1}) + _:_ -> ?observe(_Name,{dropped,1}) end, ok. handler_exit(_Name, Reason) -> exit(Reason). -check_load(State = #{id:=Name, mode := Mode, +check_load(State = #{id:=_Name, mode_tab := ModeTab, mode := Mode, toggle_sync_qlen := ToggleSyncQLen, drop_new_reqs_qlen := DropNewQLen, flush_reqs_qlen := FlushQLen}) -> {_,Mem} = process_info(self(), memory), - ?observe(Name,{max_mem,Mem}), + ?observe(_Name,{max_mem,Mem}), {_,QLen} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,QLen}), + ?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 @@ -171,11 +175,11 @@ check_load(State = #{id:=Name, mode := Mode, %% be dropped on the client side (never sent get to %% the handler). IncDrops = if Mode == drop -> 0; true -> 1 end, - {?change_mode(Name, Mode, drop), IncDrops,0}; + {?change_mode(ModeTab, Mode, drop), IncDrops,0}; QLen >= ToggleSyncQLen -> - {?change_mode(Name, Mode, sync), 0,0}; + {?change_mode(ModeTab, Mode, sync), 0,0}; true -> - {?change_mode(Name, Mode, async), 0,0} + {?change_mode(ModeTab, Mode, async), 0,0} end, State1 = ?update_other(drops,DROPS,_NewDrops,State), {Mode1, QLen, Mem, diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index ed365ce6eb..e4d3431468 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -77,29 +77,30 @@ -define(DISK_LOG_MAX_NO_BYTES, 1048576). %%%----------------------------------------------------------------- +%%% Utility macros + +-define(name_to_reg_name(MODULE,Name), + list_to_atom(lists:concat([MODULE,"_",Name]))). + +%%%----------------------------------------------------------------- %%% Overload protection macros -define(timestamp(), erlang:monotonic_time(microsecond)). --define(get_mode(HandlerName), - case ets:lookup(HandlerName, mode) of - [{mode,sync}] -> - case whereis(HandlerName)==self() of - true -> async; - _ -> sync - end; +-define(get_mode(Tid), + case ets:lookup(Tid, mode) of [{mode,M}] -> M; _ -> async end). --define(set_mode(HandlerName, M), - begin ets:insert(HandlerName, {mode,M}), M end). +-define(set_mode(Tid, M), + begin ets:insert(Tid, {mode,M}), M end). --define(change_mode(HandlerName, M0, M1), +-define(change_mode(Tid, M0, M1), if M0 == M1 -> M0; true -> - ets:insert(HandlerName, {mode,M1}), + ets:insert(Tid, {mode,M1}), M1 end). @@ -124,7 +125,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/src/logger_std_h.erl b/lib/kernel/src/logger_std_h.erl index 323f4f02e7..5ec9eced12 100644 --- a/lib/kernel/src/logger_std_h.erl +++ b/lib/kernel/src/logger_std_h.erl @@ -64,7 +64,8 @@ start_link(Name, Config, HandlerState) -> sync(Name) when is_atom(Name) -> try - gen_server:call(Name, filesync, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + filesync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -80,7 +81,8 @@ sync(Name) -> info(Name) when is_atom(Name) -> try - gen_server:call(Name, info, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + info, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -95,7 +97,8 @@ info(Name) -> reset(Name) when is_atom(Name) -> try - gen_server:call(Name, reset, ?DEFAULT_CALL_TIMEOUT) + gen_server:call(?name_to_reg_name(?MODULE,Name), + reset, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; @@ -118,10 +121,10 @@ adding_handler(#{id:=Name}=Config) -> case logger_h_common:overload_levels_ok(HState) of true -> case start(Name, Config1, HState) of - ok -> + {ok,Config2} -> %% Make sure wait_for_buffer is not stored, so we %% won't hang and wait for buffer on a restart - {ok, maps:remove(wait_for_buffer,Config1)}; + {ok, maps:remove(wait_for_buffer,Config2)}; Error -> Error end; @@ -137,13 +140,16 @@ adding_handler(#{id:=Name}=Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, ?MODULE:=#{type:=Type}}, +changing_config(OldConfig=#{id:=Name, ?MODULE:=HConfig}, NewConfig=#{id:=Name}) -> + #{type:=Type, handler_pid:=HPid, mode_tab:=ModeTab} = HConfig, MyConfig = maps:get(?MODULE, NewConfig, #{}), case maps:get(type, MyConfig, Type) of Type -> - MyConfig1 = MyConfig#{type=>Type}, - changing_config1(Name, OldConfig, + MyConfig1 = MyConfig#{type=>Type, + handler_pid=>HPid, + mode_tab=>ModeTab}, + changing_config1(HPid, OldConfig, NewConfig#{?MODULE=>MyConfig1}); _ -> {error,{illegal_config_change,OldConfig,NewConfig}} @@ -151,10 +157,10 @@ changing_config(OldConfig=#{id:=Name, ?MODULE:=#{type:=Type}}, changing_config(OldConfig, NewConfig) -> {error,{illegal_config_change,OldConfig,NewConfig}}. -changing_config1(Name, OldConfig, NewConfig) -> +changing_config1(HPid, OldConfig, NewConfig) -> case check_config(changing, NewConfig) of Result = {ok,NewConfig1} -> - try gen_server:call(Name, {change_config,OldConfig,NewConfig1}, + try gen_server:call(HPid, {change_config,OldConfig,NewConfig1}, ?DEFAULT_CALL_TIMEOUT) of ok -> Result; HError -> HError @@ -209,12 +215,12 @@ removing_handler(#{id:=Name}) -> %%%----------------------------------------------------------------- %%% Get buffer when swapping from simple handler -swap_buffer(Name,Buffer) -> - case whereis(Name) of +swap_buffer(Name, Buffer) -> + case whereis(?name_to_reg_name(?MODULE,Name)) of undefined -> ok; - _ -> - Name ! {buffer,Buffer} + Pid -> + Pid ! {buffer,Buffer} end. %%%----------------------------------------------------------------- @@ -223,20 +229,22 @@ swap_buffer(Name,Buffer) -> LogEvent :: logger:log_event(), Config :: logger:config(). -log(LogEvent,Config=#{id:=Name}) -> +log(LogEvent, Config = #{id := Name, + ?MODULE := #{handler_pid := HPid, + mode_tab := ModeTab}}) -> %% if the handler has crashed, we must drop this request %% and hope the handler restarts so we can try again - true = is_pid(whereis(Name)), - Bin = logger_h_common:log_to_binary(LogEvent,Config), - logger_h_common:call_cast_or_drop(Name, Bin). + true = is_process_alive(HPid), + Bin = logger_h_common:log_to_binary(LogEvent, Config), + logger_h_common:call_cast_or_drop(Name, HPid, ModeTab, Bin). %%%=================================================================== %%% gen_server callbacks %%%=================================================================== -init([Name, Config, - State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> - register(Name, self()), +init([Name, Config = #{?MODULE := HConfig}, + State0 = #{type := Type, file_ctrl_sync_int := FileCtrlSyncInt}]) -> + register(?name_to_reg_name(?MODULE,Name), self()), process_flag(trap_exit, true), process_flag(message_queue_data, off_heap), @@ -245,21 +253,32 @@ init([Name, Config, case do_init(Name, Type) of {ok,InitState} -> - catch ets:new(Name, [public, named_table]), - ?set_mode(Name, async), - State = maps:merge(State0, InitState), - T0 = ?timestamp(), - State1 = - ?merge_with_stats(State#{mode => async, - file_ctrl_sync => FileCtrlSyncInt, - last_qlen => 0, - last_log_ts => T0, - last_op => sync, - burst_win_ts => T0, - burst_msg_count => 0}), - proc_lib:init_ack({ok,self()}), - gen_server:cast(self(), repeated_filesync), - enter_loop(Config, State1); + try ets:new(Name, [public]) of + ModeTab -> + ?set_mode(ModeTab, async), + State = maps:merge(State0, InitState), + T0 = ?timestamp(), + State1 = + ?merge_with_stats(State#{ + mode_tab => ModeTab, + mode => async, + file_ctrl_sync => FileCtrlSyncInt, + last_qlen => 0, + last_log_ts => T0, + last_op => sync, + burst_win_ts => T0, + burst_msg_count => 0}), + Config1 = + Config#{?MODULE => HConfig#{handler_pid => self(), + mode_tab => ModeTab}}, + proc_lib:init_ack({ok,self(),Config1}), + gen_server:cast(self(), repeated_filesync), + enter_loop(Config1, State1) + catch + _:Error -> + logger_h_common:error_notify({init_handler,Name,Error}), + proc_lib:init_ack(Error) + end; Error -> logger_h_common:error_notify({init_handler,Name,Error}), proc_lib:init_ack(Error) @@ -466,8 +485,8 @@ start(Name, Config, HandlerState) -> type => worker, modules => [?MODULE]}, case supervisor:start_child(logger_sup, LoggerStdH) of - {ok,_Pid} -> - ok; + {ok,_Pid,Config1} -> + {ok,Config1}; Error -> Error end. @@ -475,16 +494,16 @@ start(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% Stop and remove the handler. stop(Name) -> - case whereis(Name) of + case whereis(?name_to_reg_name(?MODULE,Name)) of undefined -> ok; - _ -> + Pid -> %% We don't want to do supervisor:terminate_child here %% since we need to distinguish this explicit stop from a %% system termination in order to avoid circular attempts %% at removing the handler (implying deadlocks and %% timeouts). - _ = gen_server:call(Name,stop), + _ = gen_server:call(Pid, stop), _ = supervisor:delete_child(logger_sup, Name), ok end. @@ -519,7 +538,7 @@ do_log(Bin, CallOrCast, State = #{id:=Name}) -> %% this clause is called by do_log/3 after an overload check %% has been performed, where QLen > FlushQLen -flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> +flush(_Name, _QLen0, T1, State=#{last_log_ts := _T0, mode_tab := ModeTab}) -> %% flush messages in the mailbox (a limited number in %% order to not cause long delays) _NewFlushed = logger_h_common:flush_log_requests(?FLUSH_MAX_N), @@ -528,20 +547,21 @@ flush(Name, _QLen0, T1, State=#{last_log_ts := _T0}) -> %% handler will be scheduled out often and the mailbox could %% grow very large, so we'd better check the queue again here {_,_QLen1} = process_info(self(), message_queue_len), - ?observe(Name,{max_qlen,_QLen1}), + ?observe(_Name,{max_qlen,_QLen1}), %% Add 1 for the current log request - ?observe(Name,{flushed,_NewFlushed+1}), + ?observe(_Name,{flushed,_NewFlushed+1}), State1 = ?update_max_time(?diff_time(T1,_T0),State), {dropped,?update_other(flushed,FLUSHED,_NewFlushed, - State1#{mode => ?set_mode(Name,async), + State1#{mode => ?set_mode(ModeTab,async), last_qlen => 0, last_log_ts => T1})}. %% this clause is called to write to file -write(Name, Mode, T1, Bin, _CallOrCast, - State = #{file_ctrl_pid := FileCtrlPid, +write(_Name, Mode, T1, Bin, _CallOrCast, + State = #{mode_tab := ModeTab, + file_ctrl_pid := FileCtrlPid, file_ctrl_sync := FileCtrlSync, last_qlen := LastQLen, last_log_ts := T0, @@ -555,15 +575,15 @@ write(Name, Mode, T1, Bin, _CallOrCast, %% file writes so it can keep up with incoming messages {Result,LastQLen1} = if DoWrite, FileCtrlSync == 0 -> - ?observe(Name,{_CallOrCast,1}), + ?observe(_Name,{_CallOrCast,1}), file_write_sync(FileCtrlPid, Bin, false), {ok,element(2, process_info(self(), message_queue_len))}; DoWrite -> - ?observe(Name,{_CallOrCast,1}), + ?observe(_Name,{_CallOrCast,1}), file_write_async(FileCtrlPid, Bin), {ok,LastQLen}; not DoWrite -> - ?observe(Name,{flushed,1}), + ?observe(_Name,{flushed,1}), {dropped,LastQLen} end, @@ -585,7 +605,7 @@ write(Name, Mode, T1, Bin, _CallOrCast, _File -> file_ctrl_filesync_async(FileCtrlPid) end, - {?change_mode(Name, Mode, async),0}; + {?change_mode(ModeTab, Mode, async),0}; true -> {Mode,BurstMsgCount} end, diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 2b5bbe6aed..e1b1f16414 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -107,10 +107,10 @@ start_stop_handler(_Config) -> ok = logger:add_handler(?MODULE, logger_disk_log_h, #{}), {error,{already_exist,?MODULE}} = logger:add_handler(?MODULE, logger_disk_log_h, #{}), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok = logger:remove_handler(?MODULE), timer:sleep(500), - undefined = whereis(?MODULE). + undefined = whereis(h_proc_name()). start_stop_handler(cleanup, _Config) -> logger:remove_handler(?MODULE). @@ -326,7 +326,7 @@ formatter_fail(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}, %% no formatter! logger:add_handler(Name, logger_disk_log_h, HConfig), - Pid = whereis(Name), + Pid = whereis(h_proc_name(Name)), true = is_pid(Pid), #{handlers:=HC1} = logger:i(), H = [Id || {Id,_,_} <- HC1], @@ -357,7 +357,7 @@ formatter_fail(Config) -> 5000), %% Check that handler is still alive and was never dead - Pid = whereis(Name), + Pid = whereis(h_proc_name(Name)), #{handlers:=HC2} = logger:i(), H = [Id || {Id,_,_} <- HC2], ok. @@ -598,7 +598,7 @@ disk_log_wrap(Config) -> Pid end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,MaxBytes)], @@ -652,7 +652,7 @@ disk_log_full(Config) -> Pid end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), NoOfChars = 5, @@ -701,10 +701,10 @@ disk_log_events(Config) -> Pid end, {ok,_} = dbg:tracer(process, {TraceFun, Tester}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:tp(logger_disk_log_h, handle_info, 2, []), - [whereis(?MODULE) ! E || E <- Events], + [whereis(h_proc_name()) ! E || E <- Events], %% wait for trace messages timer:sleep(2000), dbg:stop_clear(), @@ -889,7 +889,7 @@ op_switch_to_drop(Config) -> [send_burst({n,NumOfReqs}, {spawn,Procs,0}, {chars,79}, info) || _ <- lists:seq(1, Bursts)], Logged = count_lines(Log), - ok= stop_handler(?MODULE), + ok = stop_handler(?MODULE), _ = file:delete(Log), ct:pal("Number of messages dropped = ~w (~w)", [Procs*NumOfReqs*Bursts-Logged,Procs*NumOfReqs*Bursts]), @@ -1033,14 +1033,14 @@ kill_disabled(Config) -> Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), ok = file:delete(Log), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok. kill_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). qlen_kill_new(Config) -> {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = @@ -1064,7 +1064,7 @@ qlen_kill_new(Config) -> ct:pal("Slow shutdown, handler process was killed!", []) end, timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok after 5000 -> @@ -1077,7 +1077,7 @@ qlen_kill_new(cleanup, _Config) -> mem_kill_new(Config) -> {_Log,HConfig,DLHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = @@ -1101,7 +1101,7 @@ mem_kill_new(Config) -> ct:pal("Slow shutdown, handler process was killed!", []) end, timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok after 5000 -> @@ -1119,13 +1119,13 @@ restart_after(Config) -> handler_overloaded_qlen=>10, handler_restart_after=>never}}, ok = logger:set_handler_config(?MODULE, NewHConfig1), - MRef1 = erlang:monitor(process, whereis(?MODULE)), + MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler send_burst({n,100}, {spawn,2,0}, {chars,79}, info), receive {'DOWN', MRef1, _, _, _Info1} -> timer:sleep(?HANDLER_RESTART_AFTER + 1000), - undefined = whereis(?MODULE), + undefined = whereis(h_proc_name()), ok after 5000 -> @@ -1139,14 +1139,14 @@ restart_after(Config) -> handler_overloaded_qlen=>10, handler_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig2), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler send_burst({n,100}, {spawn,2,0}, {chars,79}, info), receive {'DOWN', MRef2, _, _, _Info2} -> timer:sleep(RestartAfter + 2000), - Pid1 = whereis(?MODULE), + Pid1 = whereis(h_proc_name()), true = is_pid(Pid1), false = (Pid1 == Pid0), ok @@ -1225,14 +1225,15 @@ start_handler(Name, FuncName, Config) -> max_no_bytes => 100000000}, filter_default=>log, filters=>?DEFAULT_HANDLER_FILTERS([Name]), - formatter=>{?MODULE,op}}), + formatter=>{?MODULE,op}, + level => info}), {ok,{_,HConfig = #{logger_disk_log_h := DLHConfig}}} = logger:get_handler_config(Name), {lists:concat([File,".1"]),HConfig,DLHConfig}. stop_handler(Name) -> - ok = logger:remove_handler(Name), - ct:pal("Handler ~p stopped!", [Name]). + ct:pal("Stopping handler ~p!", [Name]), + logger:remove_handler(Name). send_burst(NorT, Type, {chars,Sz}, Class) -> Text = [34 + rand:uniform(126-34) || _ <- lists:seq(1,Sz)], @@ -1331,7 +1332,7 @@ start_and_add(Name, Config, LogOpts) -> [Name,Config#{disk_log_opts=>LogOpts}]), ok = logger:add_handler(Name, logger_disk_log_h, Config#{disk_log_opts=>LogOpts}), - Pid = whereis(Name), + Pid = whereis(h_proc_name(Name)), true = is_pid(Pid), Name = proplists:get_value(name, disk_log:info(Name)), ok. @@ -1339,7 +1340,7 @@ start_and_add(Name, Config, LogOpts) -> remove_and_stop(Handler) -> ok = logger:remove_handler(Handler), timer:sleep(500), - undefined = whereis(Handler), + undefined = whereis(h_proc_name(Handler)), ok. try_read_file(FileName, Expected, Time) -> @@ -1442,7 +1443,7 @@ repeat_until_ok(Fun, C, Stop, FirstReason) -> start_tracer(Trace,Expected) -> Pid = self(), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), - dbg:p(whereis(?MODULE),[c]), + dbg:p(h_proc_name(),[c]), tpl(Trace), ok. @@ -1498,3 +1499,8 @@ escape([H|T]) -> [H|escape(T)]; escape([]) -> []. + +h_proc_name() -> + h_proc_name(?MODULE). +h_proc_name(Name) -> + list_to_atom(lists:concat([logger_disk_log_h,"_",Name])). diff --git a/lib/kernel/test/logger_std_h_SUITE.erl b/lib/kernel/test/logger_std_h_SUITE.erl index c6391e55fc..fa90be0fc8 100644 --- a/lib/kernel/test/logger_std_h_SUITE.erl +++ b/lib/kernel/test/logger_std_h_SUITE.erl @@ -170,7 +170,7 @@ add_remove_instance_file(Log, Type) -> filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), true = is_pid(Pid), logger:info(M1=?msg,?domain), ?check(M1), @@ -178,7 +178,7 @@ add_remove_instance_file(Log, Type) -> try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), ok = logger:remove_handler(?MODULE), timer:sleep(500), - undefined = whereis(?MODULE), + undefined = whereis(h_proc_name()), logger:info(?msg,?domain), ?check_no_log, try_read_file(Log, {ok,B1}, ?FILESYNC_REP_INT), @@ -240,7 +240,7 @@ formatter_fail(Config) -> #{logger_std_h => #{type => {file,Log}}, filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE])}), - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), true = is_pid(Pid), #{handlers:=HC1} = logger:i(), H = [Id || {Id,_,_} <- HC1], @@ -271,7 +271,7 @@ formatter_fail(Config) -> 5000), %% Check that handler is still alive and was never dead - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), #{handlers:=HC2} = logger:i(), H = [Id || {Id,_,_} <- HC2], @@ -354,7 +354,12 @@ crash_std_h(Config,Func,Var,Type,Log) -> ct:pal("Starting ~p with ~tp", [Name,Args]), %% Start a node which prints kernel logs to the destination specified by Type {ok,Node} = test_server:start_node(Name, peer, [{args, Args}]), - Pid = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + HProcName = + case Type of + file -> ?name_to_reg_name(logger_std_h,?STANDARD_HANDLER); + disk_log -> ?name_to_reg_name(logger_disk_log_h,?STANDARD_HANDLER) + end, + Pid = rpc:call(Node,erlang,whereis,[HProcName]), ok = rpc:call(Node,logger,set_handler_config,[?STANDARD_HANDLER,formatter, {?MODULE,self()}]), ok = log_on_remote_node(Node,"dummy1"), @@ -367,7 +372,7 @@ crash_std_h(Config,Func,Var,Type,Log) -> %% Wait a bit, then check that it is gone timer:sleep(2000), - undefined = rpc:call(Node,erlang,whereis,[?STANDARD_HANDLER]), + undefined = rpc:call(Node,erlang,whereis,[HProcName]), %% Check that file is not empty {ok,Bin2} = sync_and_read(Node,Type,Log), @@ -940,14 +945,14 @@ kill_disabled(Config) -> Logged = count_lines(Log), ct:pal("Number of messages logged = ~w", [Logged]), ok = file:delete(Log), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok. kill_disabled(cleanup, _Config) -> ok = stop_handler(?MODULE). qlen_kill_new(Config) -> {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = @@ -970,7 +975,7 @@ qlen_kill_new(Config) -> ct:pal("Slow shutdown, handler process was killed!", []) end, timer:sleep(RestartAfter + 2000), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok after 5000 -> @@ -998,7 +1003,7 @@ qlen_kill_std(_Config) -> mem_kill_new(Config) -> {_Log,HConfig,StdHConfig} = start_handler(?MODULE, ?FUNCTION_NAME, Config), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), {_,Mem0} = process_info(Pid0, memory), RestartAfter = ?HANDLER_RESTART_AFTER, NewHConfig = @@ -1021,7 +1026,7 @@ mem_kill_new(Config) -> ct:pal("Slow shutdown, handler process was killed!", []) end, timer:sleep(RestartAfter * 3), - true = is_pid(whereis(?MODULE)), + true = is_pid(whereis(h_proc_name())), ok after 5000 -> @@ -1044,13 +1049,13 @@ restart_after(Config) -> handler_overloaded_qlen=>10, handler_restart_after=>never}}, ok = logger:set_handler_config(?MODULE, NewHConfig1), - MRef1 = erlang:monitor(process, whereis(?MODULE)), + MRef1 = erlang:monitor(process, whereis(h_proc_name())), %% kill handler send_burst({n,100}, {spawn,2,0}, {chars,79}, info), receive {'DOWN', MRef1, _, _, _Info1} -> timer:sleep(?HANDLER_RESTART_AFTER + 1000), - undefined = whereis(?MODULE), + undefined = whereis(h_proc_name()), ok after 5000 -> @@ -1064,14 +1069,14 @@ restart_after(Config) -> handler_overloaded_qlen=>10, handler_restart_after=>RestartAfter}}, ok = logger:set_handler_config(?MODULE, NewHConfig2), - Pid0 = whereis(?MODULE), + Pid0 = whereis(h_proc_name()), MRef2 = erlang:monitor(process, Pid0), %% kill handler send_burst({n,100}, {spawn,2,0}, {chars,79}, info), receive {'DOWN', MRef2, _, _, _Info2} -> timer:sleep(RestartAfter + 2000), - Pid1 = whereis(?MODULE), + Pid1 = whereis(h_proc_name()), true = is_pid(Pid1), false = (Pid1 == Pid0), ok @@ -1286,7 +1291,7 @@ add_remove_instance_nofile(Type) -> filter_default=>stop, filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,self()}}), - Pid = whereis(?MODULE), + Pid = whereis(h_proc_name()), true = is_pid(Pid), group_leader(group_leader(),Pid), % to get printouts in test log logger:info(M1=?msg,?domain), @@ -1295,7 +1300,7 @@ add_remove_instance_nofile(Type) -> ok = logger_std_h:sync(?MODULE), ok = logger:remove_handler(?MODULE), timer:sleep(500), - undefined = whereis(?MODULE), + undefined = whereis(h_proc_name()), logger:info(?msg,?domain), ?check_no_log, ok. @@ -1379,7 +1384,7 @@ start_op_trace() -> TRecvPid = spawn_link(fun() -> trace_receiver(5000) end), {ok,_} = dbg:tracer(process, {TraceFun, TRecvPid}), - {ok,_} = dbg:p(whereis(?MODULE), [c]), + {ok,_} = dbg:p(whereis(h_proc_name()), [c]), {ok,_} = dbg:p(self(), [c]), MS1 = dbg:fun2ms(fun([_]) -> return_trace() end), @@ -1459,7 +1464,7 @@ start_tracer(Trace,Expected) -> Pid = self(), FileCtrlPid = maps:get(file_ctrl_pid, logger_std_h:info(?MODULE)), dbg:tracer(process,{fun tracer/2,{Pid,Expected}}), - dbg:p(whereis(?MODULE),[c]), + dbg:p(whereis(h_proc_name()),[c]), dbg:p(FileCtrlPid,[c]), tpl(Trace), ok. @@ -1525,3 +1530,8 @@ escape([H|T]) -> [H|escape(T)]; escape([]) -> []. + +h_proc_name() -> + h_proc_name(?MODULE). +h_proc_name(Name) -> + ?name_to_reg_name(logger_std_h,Name). |