From a1c498df4b4ee20172def79c469e6fd8dd41e841 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 8 Jun 2018 14:17:44 +0200 Subject: [logger] Change names of sync functions in built-in handlers logger_std_h:filesync/1 -----> logger_std_h:sync/1 logger_disk_log_h:disk_log_sync/1 -----> logger_disk_log_h:sync/1 --- lib/kernel/src/logger_disk_log_h.erl | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 773aa75bc6..00643b6a84 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -26,7 +26,7 @@ -include("logger_h_common.hrl"). %%% API --export([start_link/3, info/1, disk_log_sync/1, reset/1]). +-export([start_link/3, info/1, sync/1, reset/1]). %% gen_server callbacks -export([init/1, handle_call/3, handle_cast/2, handle_info/2, @@ -57,18 +57,18 @@ start_link(Name, Config, HandlerState) -> %%%----------------------------------------------------------------- %%% --spec disk_log_sync(Name) -> ok | {error,Reason} when +-spec sync(Name) -> ok | {error,Reason} when Name :: atom(), Reason :: handler_busy | {badarg,term()}. -disk_log_sync(Name) when is_atom(Name) -> +sync(Name) when is_atom(Name) -> try gen_server:call(Name, disk_log_sync, ?DEFAULT_CALL_TIMEOUT) catch _:{timeout,_} -> {error,handler_busy} end; -disk_log_sync(Name) -> - {error,{badarg,{disk_log_sync,[Name]}}}. +sync(Name) -> + {error,{badarg,{sync,[Name]}}}. %%%----------------------------------------------------------------- %%% -- cgit v1.2.3 From e5bbcfd47088162a1c349eeb5aa3c37d8263d274 Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Mon, 4 Jun 2018 14:55:08 +0200 Subject: [logger] Change registered name of built-in handlers and use TID for mode table --- lib/kernel/src/logger_disk_log_h.erl | 121 ++++++++++++++++++++--------------- 1 file changed, 71 insertions(+), 50 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') 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, -- cgit v1.2.3 From 7f6e61ca0d752c780ffadd7aacf29aaab0783c78 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 6 Jun 2018 15:58:12 +0200 Subject: [logger] Change name of handler specific config field from ?MODULE to 'config' And add field 'module' in handler config. --- lib/kernel/src/logger_disk_log_h.erl | 30 +++++++++++++++--------------- 1 file changed, 15 insertions(+), 15 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index ba90fefcd3..d339957ac8 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -115,7 +115,7 @@ adding_handler(#{id:=Name}=Config) -> case check_config(adding, Config) of {ok, Config1} -> %% create initial handler state by merging defaults with config - HConfig = maps:get(?MODULE, Config1, #{}), + HConfig = maps:get(config, Config1, #{}), HState = maps:merge(get_init_state(), HConfig), case logger_h_common:overload_levels_ok(HState) of true -> @@ -139,15 +139,15 @@ adding_handler(#{id:=Name}=Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts, ?MODULE:=HConfig}, +changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts, config:=HConfig}, NewConfig=#{id:=Name, disk_log_opts:=DLOpts}) -> case check_config(changing, NewConfig) of - {ok,NewConfig1 = #{?MODULE:=NewHConfig}} -> + {ok,NewConfig1 = #{config:=NewHConfig}} -> #{handler_pid:=HPid, mode_tab:=ModeTab} = HConfig, NewHConfig1 = NewHConfig#{handler_pid=>HPid, mode_tab=>ModeTab}, - NewConfig2 = NewConfig1#{?MODULE=>NewHConfig1}, + NewConfig2 = NewConfig1#{config=>NewHConfig1}, try gen_server:call(HPid, {change_config,OldConfig,NewConfig2}, ?DEFAULT_CALL_TIMEOUT) of ok -> {ok,NewConfig2}; @@ -167,11 +167,11 @@ check_config(adding, #{id:=Name}=Config) -> LogOpts = merge_default_logopts(Name, LogOpts0), case check_log_opts(maps:to_list(LogOpts)) of ok -> - MyConfig = maps:get(?MODULE, Config, #{}), + MyConfig = maps:get(config, Config, #{}), case check_my_config(maps:to_list(MyConfig)) of ok -> {ok,Config#{disk_log_opts=>LogOpts, - ?MODULE=>MyConfig}}; + config=>MyConfig}}; Error -> Error end; @@ -179,7 +179,7 @@ check_config(adding, #{id:=Name}=Config) -> Error end; check_config(changing, Config) -> - MyConfig = maps:get(?MODULE, Config, #{}), + MyConfig = maps:get(config, Config, #{}), case check_my_config(maps:to_list(MyConfig)) of ok -> {ok,Config}; Error -> Error @@ -248,8 +248,8 @@ swap_buffer(Name, Buffer) -> Config :: logger:config(). log(LogEvent, Config = #{id := Name, - ?MODULE := #{handler_pid := HPid, - mode_tab := ModeTab}}) -> + config := #{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_process_alive(HPid), @@ -260,7 +260,7 @@ log(LogEvent, Config = #{id := Name, %%% gen_server callbacks %%%=================================================================== -init([Name, Config = #{?MODULE := HConfig, disk_log_opts := LogOpts}, +init([Name, Config = #{config := HConfig, disk_log_opts := LogOpts}, State = #{dl_sync_int := DLSyncInt}]) -> register(?name_to_reg_name(?MODULE,Name), self()), process_flag(trap_exit, true), @@ -291,8 +291,8 @@ init([Name, Config = #{?MODULE := HConfig, disk_log_opts := LogOpts}, prev_sync_result => ok, prev_disk_log_info => undefined}), Config1 = - Config#{?MODULE => HConfig#{handler_pid => self(), - mode_tab => ModeTab}}, + Config#{config => 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) @@ -335,7 +335,7 @@ handle_call(disk_log_sync, _From, State = #{id := Name}) -> handle_call({change_config,_OldConfig,NewConfig}, _From, State = #{filesync_repeat_interval := FSyncInt0}) -> - HConfig = maps:get(?MODULE, NewConfig, #{}), + HConfig = maps:get(config, NewConfig, #{}), State1 = #{toggle_sync_qlen := TSQL, drop_new_reqs_qlen := DNRQL, flush_reqs_qlen := FRQL} = maps:merge(State, HConfig), @@ -482,9 +482,9 @@ get_init_state() -> %%% ignored. %%% %%% Handler specific config should be provided with a sub map associated -%%% with a key named the same as this module, e.g: +%%% with a key named 'config', e.g: %%% -%%% Config = #{logger_disk_log_h => #{toggle_sync_qlen => 50} +%%% Config = #{config => #{toggle_sync_qlen => 50} %%% %%% The disk_log handler process is linked to logger_sup, which is %%% part of the kernel application's supervision tree. -- cgit v1.2.3 From b91eceaf71e0009346d119346a33894ed53be7b0 Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Thu, 7 Jun 2018 10:59:04 +0200 Subject: [logger] Implement logging of handler overload status Conflicts: lib/kernel/src/logger_disk_log_h.erl lib/kernel/src/logger_std_h.erl --- lib/kernel/src/logger_disk_log_h.erl | 89 ++++++++++++++++++++++++++---------- 1 file changed, 66 insertions(+), 23 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index d339957ac8..c3d2204630 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -37,6 +37,9 @@ adding_handler/1, removing_handler/1, changing_config/2, swap_buffer/2]). +%% handler internal +-export([log_handler_info/4]). + %%%=================================================================== %%% API %%%=================================================================== @@ -250,7 +253,7 @@ swap_buffer(Name, Buffer) -> log(LogEvent, Config = #{id := Name, config := #{handler_pid := HPid, mode_tab := ModeTab}}) -> - %% if the handler has crashed, we must drop this request + %% if the handler has crashed, we must drop this event %% and hope the handler restarts so we can try again true = is_process_alive(HPid), Bin = logger_h_common:log_to_binary(LogEvent, Config), @@ -295,6 +298,16 @@ init([Name, Config = #{config := HConfig, disk_log_opts := LogOpts}, mode_tab => ModeTab}}, proc_lib:init_ack({ok,self(),Config1}), gen_server:cast(self(), repeated_disk_log_sync), + case logger_h_common:unset_restart_flag(Name, ?MODULE) of + true -> + %% inform about restart + gen_server:cast(self(), {log_handler_info, + "Handler ~p restarted", + [Name]}); + false -> + %% initial start + ok + end, enter_loop(Config1, State1) catch _:Error -> @@ -315,15 +328,13 @@ enter_loop(#{wait_for_buffer:=true}=Config,State) -> Bin = logger_h_common:log_to_binary(Log,Config), {_,S1} = do_log(Bin,cast,S), S1 - end, - State, - Buffer) + end, State, Buffer) end, gen_server:enter_loop(?MODULE,[],State1); enter_loop(_Config,State) -> gen_server:enter_loop(?MODULE,[],State). -%% This is the synchronous log request. +%% This is the synchronous log event. handle_call({log, Bin}, _From, State) -> {Result,State1} = do_log(Bin, call, State), %% Result == ok | dropped @@ -377,15 +388,19 @@ handle_call(stop, _From, State) -> {stop, {shutdown,stopped}, ok, State}. -%% This is the asynchronous log request. +%% This is the asynchronous log event. handle_cast({log, Bin}, State) -> {_,State1} = do_log(Bin, cast, State), {noreply, State1}; +handle_cast({log_handler_info, Format, Args}, State = #{id:=Name}) -> + log_handler_info(Name, Format, Args, State), + {noreply, State}; + %% If FILESYNC_REPEAT_INTERVAL is set to a millisec value, this %% clause gets called repeatedly by the handler. In order to %% guarantee that a filesync *always* happens after the last log -%% request, the repeat operation must be active! +%% event, the repeat operation must be active! handle_cast(repeated_disk_log_sync, State = #{id := Name, filesync_repeat_interval := FSyncInt, @@ -526,21 +541,31 @@ stop(Name) -> if C == 0 -> Interval; true -> C-1 end). -%% check for overload between every request (and set Mode to async, +%% check for overload between every event (and set Mode to async, %% sync or drop accordingly), but never flush the whole mailbox -%% before LogWindowSize requests have been handled -do_log(Bin, CallOrCast, State = #{id:=Name, mode := _Mode0}) -> +%% before LogWindowSize events have been handled +do_log(Bin, CallOrCast, State = #{id:=Name, mode := Mode0}) -> T1 = ?timestamp(), %% check if the handler is getting overloaded, or if it's %% recovering from overload (the check must be done for each - %% request to react quickly to large bursts of requests and + %% event to react quickly to large bursts of events and %% to ensure that the handler can never end up in drop mode %% with an empty mailbox, which would stop operation) {Mode1,QLen,Mem,State1} = logger_h_common:check_load(State), + if (Mode1 == drop) andalso (Mode0 =/= drop) -> + log_handler_info(Name, "Handler ~p switched to drop mode", + [Name], State); + (Mode0 == drop) andalso ((Mode1 == async) orelse (Mode1 == sync)) -> + log_handler_info(Name, "Handler ~p switched to ~w mode", + [Name,Mode1], State); + true -> + ok + end, + %% kill the handler if it can't keep up with the load - logger_h_common:kill_if_choked(Name, QLen, Mem, State), + logger_h_common:kill_if_choked(Name, QLen, Mem, ?MODULE, State), if Mode1 == flush -> flush(Name, QLen, T1, State1); @@ -550,22 +575,26 @@ 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, mode_tab := ModeTab}) -> +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), + NewFlushed = logger_h_common:flush_log_events(?FLUSH_MAX_N), + + %% write info in log about flushed messages + log_handler_info(Name, "Handler ~p flushed ~w log events", + [Name,NewFlushed], State), %% because of the receive loop when flushing messages, the %% 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}), + %% Add 1 for the current log event + ?observe(Name,{flushed,NewFlushed+1}), State1 = ?update_max_time(?diff_time(T1,_T0),State), - {dropped,?update_other(flushed,FLUSHED,_NewFlushed, + {dropped,?update_other(flushed,FLUSHED,NewFlushed, State1#{mode => ?set_mode(ModeTab,async), last_qlen => 0, last_log_ts => T1})}. @@ -578,10 +607,10 @@ write(Name, Mode, T1, Bin, _CallOrCast, last_qlen := LastQLen, last_log_ts := T0}) -> %% check if we need to limit the number of writes - %% during a burst of log requests + %% during a burst of log events {DoWrite,BurstWinT,BurstMsgCount} = logger_h_common:limit_burst(State), - %% only send a synhrounous request to the disk_log process + %% only send a synhrounous event to the disk_log process %% every DLSyncInt time, to give the handler time between %% writes so it can keep up with incoming messages {Status,LastQLen1,State1} = @@ -599,13 +628,13 @@ write(Name, Mode, T1, Bin, _CallOrCast, {dropped, LastQLen, State} end, - %% Check if the time since the previous log request is long enough - + %% Check if the time since the previous log event is long enough - %% and the queue length small enough - to assume the mailbox has %% been emptied, and if so, do filesync operation and 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 requests is fast and no new - %% request comes in after the last one, idle state won't be detected! + %% 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), {Mode1,BurstMsgCount1,State2} = if (LastQLen1 < ?FILESYNC_OK_QLEN) andalso @@ -628,6 +657,20 @@ write(Name, Mode, T1, Bin, _CallOrCast, {Status,State4}. +log_handler_info(Name, Format, Args, State) -> + Config = + case logger:get_handler_config(Name) of + {ok,Conf} -> Conf; + _ -> #{formatter=>{?DEFAULT_FORMATTER,?DEFAULT_FORMAT_CONFIG}} + end, + Meta = #{time=>erlang:system_time(microsecond)}, + Bin = logger_h_common:log_to_binary(#{level => notice, + msg => {Format,Args}, + meta => Meta}, Config), + _ = disk_log_write(Name, Bin, State), + ok. + + open_disk_log(Name, LogOpts) -> #{file := File, max_no_bytes := MaxNoBytes, -- cgit v1.2.3 From d8a16e264fcdbe5b13643b81987e7afe0a633dd8 Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Thu, 7 Jun 2018 23:52:01 +0200 Subject: [logger] Change names of overload config parameters in build-in handlers --- lib/kernel/src/logger_disk_log_h.erl | 44 ++++++++++++++++++------------------ 1 file changed, 22 insertions(+), 22 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index c3d2204630..e4b583c269 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -131,10 +131,10 @@ adding_handler(#{id:=Name}=Config) -> Error end; false -> - #{toggle_sync_qlen := TSQL, - drop_new_reqs_qlen := DNRQL, - flush_reqs_qlen := FRQL} = HState, - {error,{invalid_levels,{TSQL,DNRQL,FRQL}}} + #{sync_mode_qlen := SMQL, + drop_mode_qlen := DMQL, + flush_qlen := FQL} = HState, + {error,{invalid_levels,{SMQL,DMQL,FQL}}} end; Error -> Error @@ -347,9 +347,9 @@ handle_call(disk_log_sync, _From, State = #{id := Name}) -> handle_call({change_config,_OldConfig,NewConfig}, _From, State = #{filesync_repeat_interval := FSyncInt0}) -> HConfig = maps:get(config, NewConfig, #{}), - State1 = #{toggle_sync_qlen := TSQL, - drop_new_reqs_qlen := DNRQL, - flush_reqs_qlen := FRQL} = maps:merge(State, HConfig), + State1 = #{sync_mode_qlen := SMQL, + drop_mode_qlen := DMQL, + flush_qlen := FQL} = maps:merge(State, HConfig), case logger_h_common:overload_levels_ok(State1) of true -> _ = @@ -370,7 +370,7 @@ handle_call({change_config,_OldConfig,NewConfig}, _From, end, {reply, ok, State1}; false -> - {reply, {error,{invalid_levels,{TSQL,DNRQL,FRQL}}}, State} + {reply, {error,{invalid_levels,{SMQL,DMQL,FQL}}}, State} end; handle_call(info, _From, State) -> @@ -464,19 +464,19 @@ code_change(_OldVsn, State, _Extra) -> %%%----------------------------------------------------------------- %%% get_init_state() -> - #{toggle_sync_qlen => ?TOGGLE_SYNC_QLEN, - drop_new_reqs_qlen => ?DROP_NEW_REQS_QLEN, - flush_reqs_qlen => ?FLUSH_REQS_QLEN, - enable_burst_limit => ?ENABLE_BURST_LIMIT, - burst_limit_size => ?BURST_LIMIT_SIZE, - burst_window_time => ?BURST_WINDOW_TIME, - enable_kill_overloaded => ?ENABLE_KILL_OVERLOADED, - handler_overloaded_qlen => ?HANDLER_OVERLOADED_QLEN, - handler_overloaded_mem => ?HANDLER_OVERLOADED_MEM, - handler_restart_after => ?HANDLER_RESTART_AFTER, - dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, - filesync_ok_qlen => ?FILESYNC_OK_QLEN, - filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. + #{sync_mode_qlen => ?SYNC_MODE_QLEN, + drop_mode_qlen => ?DROP_MODE_QLEN, + flush_qlen => ?FLUSH_QLEN, + burst_limit_enable => ?BURST_LIMIT_ENABLE, + burst_limit_max_count => ?BURST_LIMIT_MAX_COUNT, + burst_limit_window_time => ?BURST_LIMIT_WINDOW_TIME, + overload_kill_enable => ?OVERLOAD_KILL_ENABLE, + overload_kill_qlen => ?OVERLOAD_KILL_QLEN, + overload_kill_mem_size => ?OVERLOAD_KILL_MEM_SIZE, + overload_kill_restart_after => ?OVERLOAD_KILL_RESTART_AFTER, + dl_sync_int => ?CONTROLLER_SYNC_INTERVAL, + filesync_ok_qlen => ?FILESYNC_OK_QLEN, + filesync_repeat_interval => ?FILESYNC_REPEAT_INTERVAL}. %%%----------------------------------------------------------------- %%% Add a disk_log handler to the logger. @@ -499,7 +499,7 @@ get_init_state() -> %%% Handler specific config should be provided with a sub map associated %%% with a key named 'config', e.g: %%% -%%% Config = #{config => #{toggle_sync_qlen => 50} +%%% Config = #{config => #{sync_mode_qlen => 50} %%% %%% The disk_log handler process is linked to logger_sup, which is %%% part of the kernel application's supervision tree. -- cgit v1.2.3 From 4d3fe8ee8d5b079df6172232d4f6864286048028 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 8 Jun 2018 17:53:47 +0200 Subject: [logger] Split config() in two: primary_config() and handler_config() --- lib/kernel/src/logger_disk_log_h.erl | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index e4b583c269..2676b50580 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -50,7 +50,7 @@ %%% handler process gets added (as a result of calling add/3). -spec start_link(Name, Config, HandlerState) -> {ok,Pid} | {error,Reason} when Name :: atom(), - Config :: logger:config(), + Config :: logger:handler_config(), HandlerState :: map(), Pid :: pid(), Reason :: term(). @@ -248,7 +248,7 @@ swap_buffer(Name, Buffer) -> %%% Log a string or report -spec log(LogEvent, Config) -> ok | dropped when LogEvent :: logger:log_event(), - Config :: logger:config(). + Config :: logger:handler_config(). log(LogEvent, Config = #{id := Name, config := #{handler_pid := HPid, @@ -484,8 +484,8 @@ get_init_state() -> %%% exist if the handler is registered with logger (and should not %%% exist if the handler is not registered). %%% -%%% Config is the logger:config() map containing a sub map with any of -%%% the following associations: +%%% Config is the logger:handler_config() map containing a sub map +%%% with any of the following associations: %%% %%% Config = #{disk_log_opts => #{file => file:filename(), %%% max_no_bytes => integer(), -- cgit v1.2.3 From e721674309b683f37306e9dd206aa8521fa871cf Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Fri, 8 Jun 2018 18:15:06 +0200 Subject: [logger] Removed unused code in logger_std_h and logger_disk_log_h --- lib/kernel/src/logger_disk_log_h.erl | 35 ++--------------------------------- 1 file changed, 2 insertions(+), 33 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 2676b50580..8a456f72b1 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -33,9 +33,7 @@ terminate/2, code_change/3]). %% logger callbacks --export([log/2, - adding_handler/1, removing_handler/1, - changing_config/2, swap_buffer/2]). +-export([log/2, adding_handler/1, removing_handler/1, changing_config/2]). %% handler internal -export([log_handler_info/4]). @@ -122,14 +120,7 @@ adding_handler(#{id:=Name}=Config) -> HState = maps:merge(get_init_state(), HConfig), case logger_h_common:overload_levels_ok(HState) of true -> - case start(Name, Config1, HState) of - {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,Config2)}; - Error -> - Error - end; + start(Name, Config1, HState); false -> #{sync_mode_qlen := SMQL, drop_mode_qlen := DMQL, @@ -234,16 +225,6 @@ check_my_config([]) -> removing_handler(#{id:=Name}) -> stop(Name). -%%%----------------------------------------------------------------- -%%% Get buffer when swapping from simple handler -swap_buffer(Name, Buffer) -> - case whereis(?name_to_reg_name(?MODULE,Name)) of - undefined -> - ok; - Pid -> - Pid ! {buffer,Buffer} - end. - %%%----------------------------------------------------------------- %%% Log a string or report -spec log(LogEvent, Config) -> ok | dropped when @@ -319,18 +300,6 @@ init([Name, Config = #{config := HConfig, disk_log_opts := LogOpts}, proc_lib:init_ack(Error) end. -enter_loop(#{wait_for_buffer:=true}=Config,State) -> - State1 = - receive - {buffer,Buffer} -> - lists:foldl( - fun(Log,S) -> - Bin = logger_h_common:log_to_binary(Log,Config), - {_,S1} = do_log(Bin,cast,S), - S1 - end, State, Buffer) - end, - gen_server:enter_loop(?MODULE,[],State1); enter_loop(_Config,State) -> gen_server:enter_loop(?MODULE,[],State). -- cgit v1.2.3 From 98371223a4056459957552f1243f499c4003628e Mon Sep 17 00:00:00 2001 From: Peter Andersson Date: Fri, 8 Jun 2018 18:41:16 +0200 Subject: [logger] Move the disk log options to the handler config map Conflicts: lib/kernel/src/logger_disk_log_h.erl --- lib/kernel/src/logger_disk_log_h.erl | 135 +++++++++++++++++------------------ 1 file changed, 67 insertions(+), 68 deletions(-) (limited to 'lib/kernel/src/logger_disk_log_h.erl') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 8a456f72b1..a074d0210e 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -133,12 +133,25 @@ adding_handler(#{id:=Name}=Config) -> %%%----------------------------------------------------------------- %%% Updating handler config -changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts, config:=HConfig}, - NewConfig=#{id:=Name, disk_log_opts:=DLOpts}) -> +changing_config(OldConfig = #{id:=Name, config:=OldHConfig}, + NewConfig = #{id:=Name, config:=NewHConfig}) -> + #{type:=Type, file:=File, max_no_files:=MaxFs, + max_no_bytes:=MaxBytes} = OldHConfig, + case NewHConfig of + #{type:=Type, file:=File, max_no_files:=MaxFs, + max_no_bytes:=MaxBytes} -> + changing_config1(OldConfig, NewConfig); + _ -> + {error,{illegal_config_change,OldConfig,NewConfig}} + end; +changing_config(OldConfig, NewConfig) -> + {error,{illegal_config_change,OldConfig,NewConfig}}. + +changing_config1(OldConfig=#{config:=OldHConfig}, NewConfig) -> case check_config(changing, NewConfig) of {ok,NewConfig1 = #{config:=NewHConfig}} -> #{handler_pid:=HPid, - mode_tab:=ModeTab} = HConfig, + mode_tab:=ModeTab} = OldHConfig, NewHConfig1 = NewHConfig#{handler_pid=>HPid, mode_tab=>ModeTab}, NewConfig2 = NewConfig1#{config=>NewHConfig1}, @@ -151,73 +164,58 @@ changing_config(OldConfig=#{id:=Name, disk_log_opts:=DLOpts, config:=HConfig}, end; Error -> Error - end; -changing_config(OldConfig, NewConfig) -> - {error,{illegal_config_change,OldConfig,NewConfig}}. + end. check_config(adding, #{id:=Name}=Config) -> - %% Merge in defaults on handler level - LogOpts0 = maps:get(disk_log_opts, Config, #{}), - LogOpts = merge_default_logopts(Name, LogOpts0), - case check_log_opts(maps:to_list(LogOpts)) of + %% merge handler specific config data + HConfig = merge_default_logopts(Name, maps:get(config, Config, #{})), + case check_h_config(maps:to_list(HConfig)) of ok -> - MyConfig = maps:get(config, Config, #{}), - case check_my_config(maps:to_list(MyConfig)) of - ok -> - {ok,Config#{disk_log_opts=>LogOpts, - config=>MyConfig}}; - Error -> - Error - end; + {ok,Config#{config=>HConfig}}; Error -> Error end; check_config(changing, Config) -> - MyConfig = maps:get(config, Config, #{}), - case check_my_config(maps:to_list(MyConfig)) of + HConfig = maps:get(config, Config, #{}), + case check_h_config(maps:to_list(HConfig)) of ok -> {ok,Config}; Error -> Error end. -merge_default_logopts(Name, LogOpts) -> - Type = maps:get(type, LogOpts, wrap), +merge_default_logopts(Name, HConfig) -> + Type = maps:get(type, HConfig, wrap), {DefaultNoFiles,DefaultNoBytes} = case Type of halt -> {undefined,infinity}; _wrap -> {10,1048576} end, {ok,Dir} = file:get_cwd(), - Default = #{file => filename:join(Dir,Name), - max_no_files => DefaultNoFiles, - max_no_bytes => DefaultNoBytes, - type => Type}, - maps:merge(Default,LogOpts). - -check_log_opts([{file,File}|Opts]) when is_list(File) -> - check_log_opts(Opts); -check_log_opts([{max_no_files,undefined}|Opts]) -> - check_log_opts(Opts); -check_log_opts([{max_no_files,N}|Opts]) when is_integer(N), N>0 -> - check_log_opts(Opts); -check_log_opts([{max_no_bytes,infinity}|Opts]) -> - check_log_opts(Opts); -check_log_opts([{max_no_bytes,N}|Opts]) when is_integer(N), N>0 -> - check_log_opts(Opts); -check_log_opts([{type,Type}|Opts]) when Type==wrap; Type==halt -> - check_log_opts(Opts); -check_log_opts([Invalid|_]) -> - {error,{invalid_config,disk_log_opt,Invalid}}; -check_log_opts([]) -> - ok. - -check_my_config([Other | Config]) -> + Defaults = #{file => filename:join(Dir,Name), + max_no_files => DefaultNoFiles, + max_no_bytes => DefaultNoBytes, + type => Type}, + maps:merge(Defaults, HConfig). + +check_h_config([{file,File}|Config]) when is_list(File) -> + check_h_config(Config); +check_h_config([{max_no_files,undefined}|Config]) -> + check_h_config(Config); +check_h_config([{max_no_files,N}|Config]) when is_integer(N), N>0 -> + check_h_config(Config); +check_h_config([{max_no_bytes,infinity}|Config]) -> + check_h_config(Config); +check_h_config([{max_no_bytes,N}|Config]) when is_integer(N), N>0 -> + check_h_config(Config); +check_h_config([{type,Type}|Config]) when Type==wrap; Type==halt -> + check_h_config(Config); +check_h_config([Other | Config]) -> case logger_h_common:check_common_config(Other) of valid -> - check_my_config(Config); + check_h_config(Config); invalid -> {error,{invalid_config,?MODULE,Other}} end; -check_my_config([]) -> +check_h_config([]) -> ok. %%%----------------------------------------------------------------- @@ -244,16 +242,22 @@ log(LogEvent, Config = #{id := Name, %%% gen_server callbacks %%%=================================================================== -init([Name, Config = #{config := HConfig, disk_log_opts := LogOpts}, +init([Name, + Config = #{config := HConfig = #{file:=File, + type:=Type, + max_no_bytes:=MNB, + max_no_files:=MNF}}, State = #{dl_sync_int := DLSyncInt}]) -> + register(?name_to_reg_name(?MODULE,Name), self()), process_flag(trap_exit, true), process_flag(message_queue_data, off_heap), ?init_test_hooks(), ?start_observation(Name), - - case open_disk_log(Name, LogOpts) of + + LogOpts = #{file=>File, type=>Type, max_no_bytes=>MNB, max_no_files=>MNF}, + case open_disk_log(Name, File, Type, MNB, MNF) of ok -> try ets:new(Name, [public]) of ModeTab -> @@ -453,22 +457,21 @@ get_init_state() -> %%% exist if the handler is registered with logger (and should not %%% exist if the handler is not registered). %%% -%%% Config is the logger:handler_config() map containing a sub map -%%% with any of the following associations: +%%% Config is the logger:handler_config() map. Handler specific parameters +%%% should be provided with a sub map associated with a key named +%%% 'config', e.g: %%% -%%% Config = #{disk_log_opts => #{file => file:filename(), -%%% max_no_bytes => integer(), -%%% max_no_files => integer(), -%%% type => wrap | halt}}. +%%% Config = #{config => #{sync_mode_qlen => 50} %%% -%%% This map will be merged with the logger configuration data for -%%% the disk_log LogName. If type == halt, then max_no_files is -%%% ignored. +%%% The 'config' sub map will also contain parameters for configuring +%%% the disk_log: %%% -%%% Handler specific config should be provided with a sub map associated -%%% with a key named 'config', e.g: +%%% Config = #{config => #{file => file:filename(), +%%% max_no_bytes => integer(), +%%% max_no_files => integer(), +%%% type => wrap | halt}}. %%% -%%% Config = #{config => #{sync_mode_qlen => 50} +%%% If type == halt, then max_no_files is ignored. %%% %%% The disk_log handler process is linked to logger_sup, which is %%% part of the kernel application's supervision tree. @@ -640,11 +643,7 @@ log_handler_info(Name, Format, Args, State) -> ok. -open_disk_log(Name, LogOpts) -> - #{file := File, - max_no_bytes := MaxNoBytes, - max_no_files := MaxNoFiles, - type := Type} = LogOpts, +open_disk_log(Name, File, Type, MaxNoBytes, MaxNoFiles) -> case filelib:ensure_dir(File) of ok -> Size = -- cgit v1.2.3