From de968677491c21af9695ba910f4ae4682221ffea Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 17 Oct 2018 19:26:08 +0200 Subject: [logger] Write asynchronously to disk log This commit updates logger_disk_log_h to write most log events asynchronlously (disk_log:balog/2), but synchronously (disk_log:blog/2) on every 20th event in the same way as logger_std_h does. This is for efficiency reasons. --- lib/kernel/src/logger_disk_log_h.erl | 19 ++++++----- lib/kernel/src/logger_h_common.hrl | 14 ++++----- lib/kernel/test/logger_disk_log_h_SUITE.erl | 49 ++++++++++++++++------------- 3 files changed, 44 insertions(+), 38 deletions(-) (limited to 'lib/kernel') diff --git a/lib/kernel/src/logger_disk_log_h.erl b/lib/kernel/src/logger_disk_log_h.erl index 1e48e5b0a8..41e0d51a9d 100644 --- a/lib/kernel/src/logger_disk_log_h.erl +++ b/lib/kernel/src/logger_disk_log_h.erl @@ -184,10 +184,12 @@ merge_default_logopts(Name, HConfig) -> maps:merge(Defaults, HConfig). filesync(Name,_Mode,State) -> - disk_log_sync(Name,State). + Result = ?disk_log_sync(Name), + maybe_notify_error(Name, filesync, Result, prev_sync_result, State). -write(Name, _Mode, Bin, State) -> - disk_log_write(Name, Bin, State). +write(Name, Mode, Bin, State) -> + Result = ?disk_log_write(Name, Mode, Bin), + maybe_notify_error(Name, log, Result, prev_log_result, State). reset_state(_Name, State) -> State#{prev_log_result => ok, @@ -244,13 +246,10 @@ close_disk_log(Name, _) -> _ = disk_log:lclose(Name), ok. -disk_log_write(Name, Bin, State) -> - Result = ?disk_log_blog(Name, Bin), - maybe_notify_error(Name, log, Result, prev_log_result, State). - -disk_log_sync(Name, State) -> - Result = ?disk_log_sync(Name), - maybe_notify_error(Name, filesync, Result, prev_sync_result, State). +disk_log_write(Name, sync, Bin) -> + disk_log:blog(Name, Bin); +disk_log_write(Name, async, Bin) -> + disk_log:balog(Name, Bin). %%%----------------------------------------------------------------- %%% Print error messages, but don't repeat the same message diff --git a/lib/kernel/src/logger_h_common.hrl b/lib/kernel/src/logger_h_common.hrl index 1a0b2c700d..261b0a6246 100644 --- a/lib/kernel/src/logger_h_common.hrl +++ b/lib/kernel/src/logger_h_common.hrl @@ -137,7 +137,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(set_internal_log(MOD_FUNC), @@ -150,7 +150,7 @@ ets:insert(?TEST_HOOKS_TAB, {internal_log,{logger,internal_log}}), ets:insert(?TEST_HOOKS_TAB, {file_write,ok}), ets:insert(?TEST_HOOKS_TAB, {file_datasync,ok}), - ets:insert(?TEST_HOOKS_TAB, {disk_log_blog,ok}), + ets:insert(?TEST_HOOKS_TAB, {disk_log_write,ok}), ets:insert(?TEST_HOOKS_TAB, {disk_log_sync,ok})). -define(internal_log(TYPE, TERM), @@ -171,11 +171,11 @@ [{_,ERROR}] -> ERROR catch _:_ -> file:datasync(DEVICE) end). - -define(disk_log_blog(LOG, DATA), - try ets:lookup(?TEST_HOOKS_TAB, disk_log_blog) of - [{_,ok}] -> disk_log:blog(LOG, DATA); + -define(disk_log_write(LOG, MODE, DATA), + try ets:lookup(?TEST_HOOKS_TAB, disk_log_write) of + [{_,ok}] -> disk_log_write(LOG, MODE, DATA); [{_,ERROR}] -> ERROR - catch _:_ -> disk_log:blog(LOG, DATA) end). + catch _:_ -> disk_log_write(LOG, MODE, DATA) end). -define(disk_log_sync(LOG), try ets:lookup(?TEST_HOOKS_TAB, disk_log_sync) of @@ -194,7 +194,7 @@ -define(internal_log(TYPE, TERM), logger:internal_log(TYPE, TERM)). -define(file_write(DEVICE, DATA), file:write(DEVICE, DATA)). -define(file_datasync(DEVICE), file:datasync(DEVICE)). - -define(disk_log_blog(LOG, DATA), disk_log:blog(LOG, DATA)). + -define(disk_log_write(LOG, MODE, DATA), disk_log_write(LOG, MODE, DATA)). -define(disk_log_sync(LOG), disk_log:sync(LOG)). -define(DEFAULT_CALL_TIMEOUT, 10000). -endif. diff --git a/lib/kernel/test/logger_disk_log_h_SUITE.erl b/lib/kernel/test/logger_disk_log_h_SUITE.erl index 2bd49432b2..87b8250781 100644 --- a/lib/kernel/test/logger_disk_log_h_SUITE.erl +++ b/lib/kernel/test/logger_disk_log_h_SUITE.erl @@ -636,10 +636,10 @@ sync(Config) -> filters=>?DEFAULT_HANDLER_FILTERS([?MODULE]), formatter=>{?MODULE,nl}}), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"first\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"first\n">>}, + {disk_log,sync}]), logger:notice("first", ?domain), %% wait for automatic disk_log_sync @@ -658,12 +658,12 @@ sync(Config) -> %% triggered by the idle timeout between "fourth" and "fifth". timer:sleep(?IDLE_DETECT_TIME_MSEC*2), - start_tracer([{disk_log,blog,2}, - {logger_disk_log_h,disk_log_sync,2}], - [{disk_log,blog,<<"second\n">>}, - {logger_disk_log_h,disk_log_sync}, - {disk_log,blog,<<"third\n">>}, - {logger_disk_log_h,disk_log_sync}]), + start_tracer([{logger_disk_log_h,disk_log_write,3}, + {disk_log,sync,1}], + [{logger_disk_log_h,disk_log_write,<<"second\n">>}, + {disk_log,sync}, + {logger_disk_log_h,disk_log_write,<<"third\n">>}, + {disk_log,sync}]), logger:notice("second", ?domain), timer:sleep(?IDLE_DETECT_TIME_MSEC*2), @@ -792,8 +792,12 @@ disk_log_full(Config) -> [] end, test_server:messages_get()), ct:pal("Trace =~n~p", [Received]), - [{trace,full}, - {trace,{error_status,{error,{full,_}}}}] = Received, + + %% The tail here could be an error_status notification, if the + %% last write was synchronous, but in most cases it will not be + [{trace,full}|_] = Received, + %% [{trace,full}, + %% {trace,{error_status,{error,{full,_}}}}] = Received, ok. disk_log_full(cleanup, _Config) -> dbg:stop_clear(), @@ -855,14 +859,15 @@ write_failure(Config) -> false = (undefined == rpc:call(Node, ets, whereis, [?TEST_HOOKS_TAB])), rpc:call(Node, ets, insert, [?TEST_HOOKS_TAB,{tester,self()}]), rpc:call(Node, ?MODULE, set_internal_log, [?MODULE,internal_log]), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), HState = rpc:call(Node, logger_disk_log_h, info, [?STANDARD_HANDLER]), ct:pal("LogOpts = ~p", [LogOpts = maps:get(log_opts, maps:get(handler_state,HState))]), + %% ?check and ?check_no_log in this test only check for internal log events ok = log_on_remote_node(Node, "Logged1"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok SyncRepInt = case (fun() -> is_atom(?FILESYNC_REPEAT_INTERVAL) end)() of true -> 5500; @@ -871,24 +876,26 @@ write_failure(Config) -> try_read_file(Log, {ok,<<"Logged1\n">>}, SyncRepInt), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,{error,no_such_log}]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,{error,no_such_log}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this should have caused an internal log ?check({error,{?STANDARD_HANDLER,log,LogOpts,{error,no_such_log}}}), - + ok = log_on_remote_node(Node, "No second error printout"), - ?check_no_log, + ?check_no_log, % but don't log same error twice - rpc:call(Node, ?MODULE, set_result, [disk_log_blog, + rpc:call(Node, ?MODULE, set_result, [disk_log_write, {error,{full,?STANDARD_HANDLER}}]), ok = log_on_remote_node(Node, "Cause simple error printout"), + %% this was a different error, so it should be logged ?check({error,{?STANDARD_HANDLER,log,LogOpts, {error,{full,?STANDARD_HANDLER}}}}), - rpc:call(Node, ?MODULE, set_result, [disk_log_blog,ok]), + rpc:call(Node, ?MODULE, set_result, [disk_log_write,ok]), ok = log_on_remote_node(Node, "Logged2"), rpc:call(Node, logger_disk_log_h, filesync, [?STANDARD_HANDLER]), - ?check_no_log, + ?check_no_log, % no internal log when write ok try_read_file(Log, {ok,<<"Logged1\nLogged2\n">>}, SyncRepInt), ok. write_failure(cleanup, _Config) -> @@ -1616,7 +1623,7 @@ tpl([]) -> tracer({trace,_,call,{logger_h_common,handle_cast,[Op|_]},Caller}, {Pid,[{Mod,Func,Op}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Op},Caller); -tracer({trace,_,call,{Mod=disk_log,Func=blog,[_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> +tracer({trace,_,call,{Mod=logger_disk_log_h,Func=disk_log_write,[_,_,Data]},Caller}, {Pid,[{Mod,Func,Data}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func,Data},Caller); tracer({trace,_,call,{Mod,Func,_},Caller}, {Pid,[{Mod,Func}|Expected]}) -> maybe_tracer_done(Pid,Expected,{Mod,Func},Caller); -- cgit v1.2.3