aboutsummaryrefslogtreecommitdiffstats
path: root/lib/kernel
diff options
context:
space:
mode:
authorSiri Hansen <[email protected]>2018-10-17 19:26:08 +0200
committerSiri Hansen <[email protected]>2018-10-19 11:57:46 +0200
commitde968677491c21af9695ba910f4ae4682221ffea (patch)
tree6ebdc049027c366c6c4e74405bd4bf6cb8be15b6 /lib/kernel
parentb68f7bfaa70a8f2f17f3167abbe3e8de6b8441ce (diff)
downloadotp-de968677491c21af9695ba910f4ae4682221ffea.tar.gz
otp-de968677491c21af9695ba910f4ae4682221ffea.tar.bz2
otp-de968677491c21af9695ba910f4ae4682221ffea.zip
[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.
Diffstat (limited to 'lib/kernel')
-rw-r--r--lib/kernel/src/logger_disk_log_h.erl19
-rw-r--r--lib/kernel/src/logger_h_common.hrl14
-rw-r--r--lib/kernel/test/logger_disk_log_h_SUITE.erl49
3 files changed, 44 insertions, 38 deletions
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);