Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

In code generated by the parse_transform skip unloggable messages fast #118

Merged
merged 2 commits into from

2 participants

Andrew Thompson Macneil Shonle
Andrew Thompson
Collaborator

Originally an idea that Dizzy forwarded to me from Tony Rogvall.
Basicially all the work lager does gathering metadata and stuff is
wrapped in a case statement that fails-fast if the message is definitely
not going to be logged; the severity isn't currently being consumed and
there's no traces installed.

In my simple test, logging 1 million debug messages, when the debug
level is not being consumed, goes from taking 2.99 seconds to 1.21
seconds with this change.

Also, lager pre 1.0 actually had something similar to this, but it was
removed during a refactor and never re-added.

Andrew Thompson Vagabond was assigned
Macneil Shonle mshonle was assigned
src/lager_transform.erl
@@ -132,18 +133,55 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, lager},
[Attrs, Format, Args] ->
{concat_lists(Attrs, DefaultAttrs), Format, Args}
end,
- {call, Line, {remote, Line, {atom,Line,lager},{atom,Line,dispatch_log}},
+ %% Generate some unique variable names so we don't accidentaly export from case clauses.
+ %% Note that these are not actual atoms, but the AST treats variable names as atoms.
+ LevelVar = list_to_atom("__Level" ++ atom_to_list(get(module)) ++ integer_to_list(Line)),
Macneil Shonle
mshonle added a note

Abstract the common code into a generate_unique_name("__Prefix", Line) call?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Macneil Shonle

+1

Vagabond added some commits
Andrew Thompson Vagabond In code generated by the parse_transform skip unloggable messages fast
Originally an idea that Dizzy forwarded to me from Tony Rogvall.
Basicially all the work lager does gathering metadata and stuff is
wrapped in a case statement that fails-fast if the message is definitely
not going to be logged; the severity isn't currently being consumed and
there's no traces installed.

In my simple test, logging 1 million debug messages, when the debug
level is not being consumed, goes from taking 2.99 seconds to 1.21
seconds with this change.

Also, lager pre 1.0 actually had something similar to this, but it was
removed during a refactor and never re-added.
a454d1f
Andrew Thompson Vagabond Generate variable names with a function, suggested by @mshonle 0d42da4
Andrew Thompson Vagabond merged commit deab695 into from
Sean Cribbs seancribbs deleted the branch
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Commits on Mar 15, 2013
  1. Andrew Thompson

    In code generated by the parse_transform skip unloggable messages fast

    Vagabond authored
    Originally an idea that Dizzy forwarded to me from Tony Rogvall.
    Basicially all the work lager does gathering metadata and stuff is
    wrapped in a case statement that fails-fast if the message is definitely
    not going to be logged; the severity isn't currently being consumed and
    there's no traces installed.
    
    In my simple test, logging 1 million debug messages, when the debug
    level is not being consumed, goes from taking 2.99 seconds to 1.21
    seconds with this change.
    
    Also, lager pre 1.0 actually had something similar to this, but it was
    removed during a refactor and never re-added.
  2. Andrew Thompson
This page is out of date. Refresh to see the latest.
Showing with 89 additions and 48 deletions.
  1. +37 −37 src/lager.erl
  2. +52 −11 src/lager_transform.erl
74 src/lager.erl
View
@@ -27,7 +27,7 @@
clear_all_traces/0, stop_trace/1, status/0,
get_loglevel/1, set_loglevel/2, set_loglevel/3, get_loglevels/0,
update_loglevel_config/0, posix_error/1,
- safe_format/3, safe_format_chop/3,dispatch_log/5,dispatch_log/9,pr/2]).
+ safe_format/3, safe_format_chop/3, dispatch_log/5, dispatch_log/9, do_log/9, pr/2]).
-type log_level() :: debug | info | notice | warning | error | critical | alert | emergency.
-type log_level_number() :: 0..7.
@@ -53,45 +53,45 @@ start_ok(App, {error, Reason}) ->
-spec dispatch_log(log_level(), list(), string(), list() | none, pos_integer()) -> ok | {error, lager_not_running}.
+%% this is the same check that the parse transform bakes into the module at compile time
dispatch_log(Severity, Metadata, Format, Args, Size) when is_atom(Severity)->
- case whereis(lager_event) of
- undefined ->
- %% lager isn't running
+ SeverityAsInt=lager_util:level_to_num(Severity),
+ case {whereis(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of
+ {undefined, _} ->
{error, lager_not_running};
- Pid ->
- {LevelThreshold,TraceFilters} = lager_config:get(loglevel,{?LOG_NONE,[]}),
- SeverityAsInt=lager_util:level_to_num(Severity),
- case (LevelThreshold band SeverityAsInt) /= 0 orelse TraceFilters /= [] of
- true ->
- Destinations = case TraceFilters of
- [] ->
- [];
- _ ->
- lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[])
- end,
- case (LevelThreshold band SeverityAsInt) /= 0 orelse Destinations /= [] of
- true ->
- Timestamp = lager_util:format_time(),
- Msg = case Args of
- A when is_list(A) ->
- safe_format_chop(Format,Args,Size);
- _ ->
- Format
- end,
- LagerMsg = lager_msg:new(Msg, Timestamp,
- Severity, Metadata, Destinations),
- case lager_config:get(async, false) of
- true ->
- gen_event:notify(Pid, {log, LagerMsg});
- false ->
- gen_event:sync_notify(Pid, {log, LagerMsg})
- end;
- false ->
- ok
- end;
+ {Pid, {Level, Traces}} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] ->
+ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, Level, Traces, Pid);
+ _ ->
+ ok
+ end.
+
+%% @private Should only be called externally from code generated from the parse transform
+do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, TraceFilters, Pid) when is_atom(Severity) ->
+ Destinations = case TraceFilters of
+ [] ->
+ [];
+ _ ->
+ lager_util:check_traces(Metadata,SeverityAsInt,TraceFilters,[])
+ end,
+ case (LevelThreshold band SeverityAsInt) /= 0 orelse Destinations /= [] of
+ true ->
+ Timestamp = lager_util:format_time(),
+ Msg = case Args of
+ A when is_list(A) ->
+ safe_format_chop(Format,Args,Size);
_ ->
- ok
- end
+ Format
+ end,
+ LagerMsg = lager_msg:new(Msg, Timestamp,
+ Severity, Metadata, Destinations),
+ case lager_config:get(async, false) of
+ true ->
+ gen_event:notify(Pid, {log, LagerMsg});
+ false ->
+ gen_event:sync_notify(Pid, {log, LagerMsg})
+ end;
+ false ->
+ ok
end.
%% backwards compatible with beams compiled with lager 1.x
63 src/lager_transform.erl
View
@@ -74,6 +74,7 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, lager},
{atom, _Line3, Severity}}, Arguments0} = Stmt) ->
case lists:member(Severity, ?LEVELS) of
true ->
+ SeverityAsInt=lager_util:level_to_num(Severity),
DefaultAttrs0 = {cons, Line, {tuple, Line, [
{atom, Line, module}, {atom, Line, get(module)}]},
{cons, Line, {tuple, Line, [
@@ -132,18 +133,55 @@ transform_statement({call, Line, {remote, _Line1, {atom, _Line2, lager},
[Attrs, Format, Args] ->
{concat_lists(Attrs, DefaultAttrs), Format, Args}
end,
- {call, Line, {remote, Line, {atom,Line,lager},{atom,Line,dispatch_log}},
+ %% Generate some unique variable names so we don't accidentaly export from case clauses.
+ %% Note that these are not actual atoms, but the AST treats variable names as atoms.
+ LevelVar = make_varname("__Level", Line),
+ TracesVar = make_varname("__Traces", Line),
+ PidVar = make_varname("__Pid", Line),
+ %% Wrap the call to lager_dispatch log in a case that will avoid doing any work if this message is not elegible for logging
+ %% case {whereis(lager_event(lager_event), lager_config:get(loglevel, {?LOG_NONE, []})} of
+ {'case', Line,
+ {tuple, Line,
+ [{call, Line, {atom, Line, whereis}, [{atom, Line, lager_event}]},
+ {call, Line, {remote, Line, {atom, Line, lager_config}, {atom, Line, get}}, [{atom, Line, loglevel}, {tuple, Line, [{integer, Line, 0},{nil, Line}]}]}]},
[
- {atom,Line,Severity},
- Traces,
- Message,
- Arguments,
- {integer, Line, get(truncation_size)}
- ]
- };
- false ->
- Stmt
- end;
+ %% {undefined, _} -> {error, lager_not_running}
+ {clause, Line,
+ [{tuple, Line, [{atom, Line, undefined}, {var, Line, '_'}]}],
+ [],
+ %% trick the linter into avoiding a 'term constructed by not used' error:
+ %% (fun() -> {error, lager_not_running} end)();
+ [{call,9, {'fun',9, {clauses, [{clause,9,[],[], [{tuple,9,[{atom,9,error},{atom,9,lager_not_running}]}]}]}}, []}]},
+ %% If we care about the loglevel, or there's any traces installed, we have do more checking
+ %% {Level, Traces} when (Level band SeverityAsInt) /= 0 orelse Traces /= [] ->
+ {clause, Line,
+ [{tuple, Line, [{var, Line, PidVar}, {tuple, Line, [{var, Line, LevelVar}, {var, Line, TracesVar}]}]}],
+ [[{op, Line, 'orelse',
+ {op, Line, '/=', {op, Line, 'band', {var, Line, LevelVar}, {integer, Line, SeverityAsInt}}, {integer, Line, 0}},
+ {op, Line, '/=', {var, Line, TracesVar}, {nil, Line}}}]],
+ [
+ %% do the call to lager:dispatch_log
+ {call, Line, {remote, Line, {atom, Line, lager}, {atom, Line, do_log}},
+ [
+ {atom,Line,Severity},
+ Traces,
+ Message,
+ Arguments,
+ {integer, Line, get(truncation_size)},
+ {integer, Line, SeverityAsInt},
+ {var, Line, LevelVar},
+ {var, Line, TracesVar},
+ {var, Line, PidVar}
+ ]
+ }
+ ]},
+ %% otherwise, do nothing
+ %% _ -> ok
+ {clause, Line, [{var, Line, '_'}],[],[{atom, Line, ok}]}
+ ]};
+ false ->
+ Stmt
+ end;
transform_statement({call, Line, {remote, Line1, {atom, Line2, boston_lager},
{atom, Line3, Severity}}, Arguments}) ->
NewArgs = case Arguments of
@@ -160,6 +198,9 @@ transform_statement(Stmt) when is_list(Stmt) ->
transform_statement(Stmt) ->
Stmt.
+make_varname(Prefix, Line) ->
+ list_to_atom(Prefix ++ atom_to_list(get(module)) ++ integer_to_list(Line)).
+
%% concat 2 list ASTs by replacing the terminating [] in A with the contents of B
concat_lists({var, Line, _Name}=Var, B) ->
%% concatenating a var with a cons
Something went wrong with that request. Please try again.