From a454d1f2d1292e1038e9e44e0e1b7d09dc31e2fc Mon Sep 17 00:00:00 2001 From: Andrew Thompson Date: Mon, 11 Mar 2013 20:19:33 -0400 Subject: [PATCH] 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. --- src/lager.erl | 74 ++++++++++++++++++++--------------------- src/lager_transform.erl | 60 +++++++++++++++++++++++++++------ 2 files changed, 86 insertions(+), 48 deletions(-) diff --git a/src/lager.erl b/src/lager.erl index ad47bac..37feb3a 100644 --- a/src/lager.erl +++ b/src/lager.erl @@ -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 diff --git a/src/lager_transform.erl b/src/lager_transform.erl index 1759da1..e7f8f35 100644 --- a/src/lager_transform.erl +++ b/src/lager_transform.erl @@ -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 = list_to_atom("__Level" ++ atom_to_list(get(module)) ++ integer_to_list(Line)), + TracesVar = list_to_atom("__Traces" ++ atom_to_list(get(module)) ++ integer_to_list(Line)), + PidVar = list_to_atom("__Pid" ++ atom_to_list(get(module)) ++ integer_to_list(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