Switch between gen_event notify/sync_notify based on message queue length #117

Merged
merged 3 commits into from Mar 14, 2013

2 participants

@Vagabond

In normal operation, there's no need for log messages to be synchronous.
Its slower and introduces a global serialization point in the
application.

However, when in an overload condition, synchronous logging is good
because it limits each process to at most 1 log message in flight.

So, this change allows the gen_event at the core of lager to switch
modes depending on the size of the gen_event's mailbox. It should
provide better performance in the case of normal load, but it will also
prevent unbounded mailbox growth if an overload occurs.

The threshold at which the switch between async and sync is done is
configured via the 'async_threshold' app env var.

@Vagabond

Here's some initial results from Vagabond/logbench, in log messages per second, percentages are relative to master:

Master Branch, async off Branch, async 100 Always async, from #113
6511 6355 7311 2645
100% 98% 112% 41%
./bin/bench lager_file simple 10000

Note that I patched logbench to do a gen_event:which_handlers(lager_event) call so that the benchmark waits for the lager gen_event mailbox to drain. I've pushed the changes to logbench master as that check does not seem to appreciably change the benchmark speeds, even for older lager.

@Vagabond Vagabond Switch between gen_event notify/sync_notify based on message queue le…
…ngth

In normal operation, there's no need for log messages to be synchronous.
Its slower and introduces a global serialization point in the
application.

However, when in an overload condition, synchronous logging is good
because it limits each process to at most 1 log message in flight.

So, this change allows the gen_event at the core of lager to switch
modes depending on the size of the gen_event's mailbox. It should
provide better performance in the case of normal load, but it will also
prevent unbounded mailbox growth if an overload occurs.

The threshold at which the switch between async and sync is done is
configured via the 'async_threshold' app env var.
cf89804
@macshonle macshonle commented on an outdated diff Mar 14, 2013
src/lager.erl
@@ -78,8 +78,14 @@ dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
_ ->
Format
end,
- gen_event:sync_notify(Pid, {log, lager_msg:new(Msg, Timestamp,
- Severity, Metadata, Destinations)});
+ case lager_config:get(async, false) of
+ true ->
+ gen_event:notify(Pid, {log, lager_msg:new(Msg, Timestamp,
@macshonle
macshonle added a line comment Mar 14, 2013

Maybe pull out the common lager_msg:new subexpression?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@macshonle macshonle commented on the diff Mar 14, 2013
src/lager_backend_throttle.erl
@@ -0,0 +1,55 @@
+-module(lager_backend_throttle).
+
+-include("lager.hrl").
+
+-behaviour(gen_event).
+
+-export([init/1, handle_call/2, handle_event/2, handle_info/2, terminate/2,
+ code_change/3]).
+
+-record(state, {
+ hwm,
@macshonle
macshonle added a line comment Mar 14, 2013

"high water mark"?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@Vagabond Vagabond merged commit cf40867 into master Mar 14, 2013

1 check passed

Details default The Travis build passed
@Vagabond Vagabond deleted the adt-sync-switch branch Mar 14, 2013
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment