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

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

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