Skip to content
This repository

Add lager:dispatch_log/8 async mode #97

Closed
wants to merge 6 commits into from

2 participants

Aleksandr Vinokurov Andrew Thompson
Aleksandr Vinokurov

Add an option to choose sync or async mode of log event notification.

Each mode has its pros and cons:

sync:

  • degrades caller process performance
  • ensures all log events of one caller process to be handled completely by all lager backends
  • guaranties the order of log events produced by one caller process to be handled by all lager backends in that order

async:

  • let the caller process continue its work not waiting for the lager backends at all
  • does not guaranty complete log events handling by the end of the series of logging calls (actually normal terminating of the lager should wait for its event manager message box exhaust)
  • does not guaranty complete log events handling at all (event manager message box can be overwhelmed on high log load)
  • the order of the handling of log events is not guarantied too due a no-message-order guaranty in Erlang

Results of the benchmark of the differences in this modes can be found here

For more completeness of the solution I've added a flow control macros, they allow to build three versions of the lager module:
1. operating strictly in sync mode
2. operating strictly in async mode
3. operating in start-time configured -- dynamic -- mode (via app env sync_dispatch_log)

Aleksandr Vinokurov aleksandr-vin Change lager:dispatch_log/8 to async style
One extra test fails due to asyncing of the fun.
de380c8
Aleksandr Vinokurov aleksandr-vin Fix "tracing to a dedicated file should work, second try"
* Support new async behavior of the lager:dispatch_log/8. Syncing the
  test by the log file size growth after the event being logged.

* Add test/wait.erl module with the 'wait-for' primitive provided. It
  should be used for syncing tests with some specific-to-backend
  quality changes. Because the logging behaviour is now asynchronous
  and there is no warranty that the event will be logged by a backend
  after the log event provider process returns to its execution.

* Add filesize_checker/1 to lager_file_backend: a handy generator of
  the predicator that can be used in wait:wait/2,3. Those predicators
  checks log file size growth which is the lager_file_backend's
  specific quality, and allow to sync tests.
4542f78
Aleksandr Vinokurov aleksandr-vin Add app env 'sync_dispatch_log' to switch the sync and async modes of…
… lager:dispatch_log/8
7ad002b
Aleksandr Vinokurov aleksandr-vin Add caching of 'sync_dispatch_log' app env value in proc dict
Works better than vanilla app env lookup on each dispatch.
987ee58
Aleksandr Vinokurov aleksandr-vin Add preprocessor defines for choosing 'sync' or 'async' mode of the l…
…ager

For those who need more efficiency on each log call: there are now
LAGER_ASYNC_NOTIFY and LAGER_SYNC_NOTIFY preprocessor definitions. The last one
has higher effective level. If no one is defined, a dynamic mode selection is
used, based on app env 'sync_dispatch_log'.
1ba4003
Aleksandr Vinokurov aleksandr-vin Add new macros description (LAGER_SYNC_NOTIFY and LAGER_ASYNC_NOTIFY) 6196b3a
Aleksandr Vinokurov

The travis build fails because of eunit tests failure that was in such state before the proposed changes...

Andrew Thompson

I'm not ignoring this, I just haven't had time to really think about how best to address it.

Aleksandr Vinokurov

No problems -- I understand :)
I see you are doing well & NY is coming...
Say if I can help with smth.

Andrew Thompson

Is something like #117 acceptable instead?

Andrew Thompson

Closing in favor of #117, which I think is the better solution.

Andrew Thompson Vagabond closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Showing 6 unique commits by 1 author.

Nov 28, 2012
Aleksandr Vinokurov aleksandr-vin Change lager:dispatch_log/8 to async style
One extra test fails due to asyncing of the fun.
de380c8
Nov 29, 2012
Aleksandr Vinokurov aleksandr-vin Fix "tracing to a dedicated file should work, second try"
* Support new async behavior of the lager:dispatch_log/8. Syncing the
  test by the log file size growth after the event being logged.

* Add test/wait.erl module with the 'wait-for' primitive provided. It
  should be used for syncing tests with some specific-to-backend
  quality changes. Because the logging behaviour is now asynchronous
  and there is no warranty that the event will be logged by a backend
  after the log event provider process returns to its execution.

* Add filesize_checker/1 to lager_file_backend: a handy generator of
  the predicator that can be used in wait:wait/2,3. Those predicators
  checks log file size growth which is the lager_file_backend's
  specific quality, and allow to sync tests.
4542f78
Nov 30, 2012
Aleksandr Vinokurov aleksandr-vin Add app env 'sync_dispatch_log' to switch the sync and async modes of…
… lager:dispatch_log/8
7ad002b
Aleksandr Vinokurov aleksandr-vin Add caching of 'sync_dispatch_log' app env value in proc dict
Works better than vanilla app env lookup on each dispatch.
987ee58
Dec 01, 2012
Aleksandr Vinokurov aleksandr-vin Add preprocessor defines for choosing 'sync' or 'async' mode of the l…
…ager

For those who need more efficiency on each log call: there are now
LAGER_ASYNC_NOTIFY and LAGER_SYNC_NOTIFY preprocessor definitions. The last one
has higher effective level. If no one is defined, a dynamic mode selection is
used, based on app env 'sync_dispatch_log'.
1ba4003
Aleksandr Vinokurov aleksandr-vin Add new macros description (LAGER_SYNC_NOTIFY and LAGER_ASYNC_NOTIFY) 6196b3a
This page is out of date. Refresh to see the latest.
8 rebar.config
... ... @@ -1,5 +1,11 @@
1 1 {erl_opts, [debug_info]}.
  2 +
  3 +%% Add {d, 'LAGER_SYNC_NOTIFY'} to erl_opts for sync log events
  4 +%% notification or {d, 'LAGER_ASYNC_NOTIFY'} for async log events
  5 +%% notification. Add none of them and you will have a start-time option
  6 +%% via lager app env 'sync_dispatch_log'.
  7 +
2 8 {erl_first_files, ["src/lager_util.erl"]}.
3 9
4 10 {cover_enabled, true}.
5   -{edoc_opts, [{stylesheet_file, "./priv/edoc.css"}]}.
  11 +{edoc_opts, [{stylesheet_file, "./priv/edoc.css"}]}.
35 src/lager.erl
@@ -74,8 +74,8 @@ dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
74 74 A when is_list(A) ->safe_format_chop(Format,Args,Size);
75 75 _ -> Format
76 76 end,
77   - gen_event:sync_notify(Pid, {log, lager_msg:new(Msg, Timestamp,
78   - Severity, Metadata, Destinations)});
  77 + notify_log(Pid, {log, lager_msg:new(Msg, Timestamp,
  78 + Severity, Metadata, Destinations)});
79 79 _ ->
80 80 ok
81 81 end
@@ -265,3 +265,34 @@ safe_format(Fmt, Args, Limit, Options) ->
265 265 %% @private
266 266 safe_format_chop(Fmt, Args, Limit) ->
267 267 safe_format(Fmt, Args, Limit, [{chomp, true}]).
  268 +
  269 +%% private
  270 +-ifdef(LAGER_SYNC_NOTIFY).
  271 +notify_log(Pid, Log) ->
  272 + gen_event:sync_notify(Pid, Log).
  273 +-else.
  274 +-ifdef(LAGER_ASYNC_NOTIFY).
  275 +notify_log(Pid, Log) ->
  276 + gen_event:notify(Pid, Log).
  277 +-else.
  278 +notify_log(Pid, Log) ->
  279 + case is_sync_dispatch_log() of
  280 + true ->
  281 + gen_event:sync_notify(Pid, Log);
  282 + _ ->
  283 + gen_event:notify(Pid, Log)
  284 + end.
  285 +
  286 +is_sync_dispatch_log() ->
  287 + case erlang:get(sync_dispatch_log) of
  288 + undefined ->
  289 + Env = case application:get_env(lager, sync_dispatch_log) of
  290 + {ok, true} -> true;
  291 + _ -> false
  292 + end,
  293 + erlang:put(sync_dispatch_log, Env),
  294 + Env;
  295 + V -> V
  296 + end.
  297 +-endif.
  298 +-endif.
37 src/lager_file_backend.erl
@@ -383,18 +383,37 @@ filesystem_test_() ->
383 383 ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}]))
384 384 end
385 385 },
386   - {"tracing to a dedicated file should work",
387   - fun() ->
388   - file:delete("foo.log"),
389   - {ok, _} = lager:trace_file("foo.log", [{module, ?MODULE}]),
390   - lager:error("Test message"),
391   - {ok, Bin3} = file:read_file("foo.log"),
392   - ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}]))
393   - end
394   - }
  386 + {"tracing to a dedicated file should work, second try",
  387 + fun() ->
  388 + File = "foo.log",
  389 + file:delete(File),
  390 + {ok, _} = lager:trace_file(File, [{module, ?MODULE}]),
  391 + CheckerFun = filesize_checker(File),
  392 + lager:error("Test message"),
  393 + ok = wait:wait(CheckerFun, 5000, 100),
  394 + {ok, Bin3} = file:read_file(File),
  395 + ?assertMatch([_, _, "[error]", _, "Test message\n"], re:split(Bin3, " ", [{return, list}, {parts, 5}]))
  396 + end
  397 + }
395 398 ]
396 399 }.
397 400
  401 +%% @doc Return a zero arity lambda function which checks File size
  402 +%% growth to the time when this lambda was created.
  403 +-spec filesize_checker(File :: file:name()) -> CheckerFun when
  404 + CheckerFun :: fun(() -> true | false).
  405 +filesize_checker(File) ->
  406 + Fun =
  407 + fun () ->
  408 + {ok, FileInfo} =
  409 + file:read_file_info(File),
  410 + FileInfo#file_info.size
  411 + end,
  412 + CurSize = Fun(),
  413 + fun () ->
  414 + CurSize < Fun()
  415 + end.
  416 +
398 417 formatting_test_() ->
399 418 {foreach,
400 419 fun() ->
45 test/wait.erl
... ... @@ -0,0 +1,45 @@
  1 +%% @doc Provides 'wait-for' primitive. It should be used for syncing
  2 +%% tests with some specific-to-backend quality changes. Because the
  3 +%% logging behaviour is now asynchronous and there is no warranty that
  4 +%% the event will be logged by a backend after the log event provider
  5 +%% process returns to its execution.
  6 +-module(wait).
  7 +
  8 +%% API
  9 +-export([wait/2, wait/3]).
  10 +
  11 +%% private
  12 +-export([waiter/3]).
  13 +
  14 +-type predicate() :: fun(() -> true | false).
  15 +
  16 +-spec wait(Pred :: predicate(),
  17 + Timeout :: timer:time()) -> ok | 'timed-out'.
  18 +wait(Pred, Timeout) ->
  19 + wait(Pred, Timeout, 500).
  20 +
  21 +-spec wait(Pred :: predicate(),
  22 + Timeout :: timer:time(),
  23 + Interval :: integer()) -> ok | 'timed-out'.
  24 +wait(Pred, Timeout, Interval) when is_integer(Timeout) andalso Timeout > 0 ->
  25 + Ref = make_ref(),
  26 + {ok, TRef} = timer:apply_interval(Interval, ?MODULE, waiter, [self(), Ref, Pred]),
  27 + Result =
  28 + receive
  29 + {waiter, Ref} ->
  30 + ok
  31 + after Timeout ->
  32 + 'timed-out'
  33 + end,
  34 + timer:cancel(TRef),
  35 + Result.
  36 +
  37 +-spec waiter(Pid :: pid(), Ref :: reference(), Pred :: predicate()) -> true | false.
  38 +waiter(Pid, Ref, Pred) ->
  39 + case Pred() of
  40 + true ->
  41 + Pid ! {waiter, Ref},
  42 + true;
  43 + false ->
  44 + false
  45 + end.

Tip: You can add notes to lines in a file. Hover to the left of a line to make a note

Something went wrong with that request. Please try again.