[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

@@ -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

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.

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);