Merge pull request erlang-lager#120 from basho/adt-msg-has-datetime

Improve the performance of the file backend
basho · Mar 22, 2013 · 9719370 · 9719370
2 parents 4c4071a + 79ea55a
commit 9719370
Show file tree

Hide file tree

Showing 9 changed files with 456 additions and 150 deletions.
diff --git a/include/lager.hrl b/include/lager.hrl
@@ -59,7 +59,6 @@
 
 -define(NOTIFY(Level, Pid, Format, Args),
     gen_event:notify(lager_event, {log, lager_msg:new(io_lib:format(Format, Args),
-            lager_util:format_time(),
             Level,
             [{pid,Pid},{line,?LINE},{file,?FILE},{module,?MODULE}],
             [])}

diff --git a/src/lager.app.src b/src/lager.app.src
@@ -16,9 +16,9 @@
             {handlers, [
                 {lager_console_backend, info},
                 {lager_file_backend, [
-                    {"log/error.log", error, 10485760, "$D0", 5},
-                    {"log/console.log", info, 10485760, "$D0", 5}
-                ]}
+                    {file, "log/error.log"}, {level, error}, {size, 10485760}, {date, "$D0"}, {count, 5}]},
+                {lager_file_backend, [
+                    {file, "log/console.log"}, {level, info}, {size, 10485760}, {date, "$D0"}, {count, 5}]}
             ]},
             %% What colors to use with what log levels
             {colored, false},

diff --git a/src/lager.erl b/src/lager.erl
@@ -103,14 +103,13 @@ do_log(Severity, Metadata, Format, Args, Size, SeverityAsInt, LevelThreshold, Tr
     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,
+            LagerMsg = lager_msg:new(Msg,
                 Severity, Metadata, Destinations),
             case lager_config:get(async, false) of
                 true ->

diff --git a/src/lager_app.erl b/src/lager_app.erl
@@ -104,31 +104,35 @@ stop(Handlers) ->
 
 expand_handlers([]) ->
     [];
+expand_handlers([{lager_file_backend, [{Key, _Value}|_]=Config}|T]) when is_atom(Key) ->
+    %% this is definitely a new-style config, no expansion needed
+    [maybe_make_handler_id(lager_file_backend, Config) | expand_handlers(T)];
 expand_handlers([{lager_file_backend, Configs}|T]) ->
+    ?INT_LOG(notice, "Deprecated lager_file_backend config detected, please consider updating it", []),
     [ {lager_file_backend:config_to_id(Config), Config} || Config <- Configs] ++
       expand_handlers(T);
 expand_handlers([{Mod, Config}|T]) when is_atom(Mod) ->
+    [maybe_make_handler_id(Mod, Config) | expand_handlers(T)];
+expand_handlers([H|T]) ->
+    [H | expand_handlers(T)].
+
+maybe_make_handler_id(Mod, Config) ->
     %% Allow the backend to generate a gen_event handler id, if it wants to.
     %% We don't use erlang:function_exported here because that requires the module 
     %% already be loaded, which is unlikely at this phase of startup. Using code:load
     %% caused undesireable side-effects with generating code-coverage reports.
-    Res = try Mod:config_to_id(Config) of
+    try Mod:config_to_id(Config) of
         Id ->
             {Id, Config}
     catch
-        _:_ ->
+        error:undef ->
             {Mod, Config}
-    end,
-    [Res | expand_handlers(T)];
-expand_handlers([H|T]) ->
-    [H | expand_handlers(T)].
-
-
-
+    end.
 
 -ifdef(TEST).
 application_config_mangling_test_() ->
-    [{"Explode the file backend handlers",
+    [
+        {"Explode the file backend handlers",
             ?_assertMatch(
                 [{lager_console_backend, info},
                     {{lager_file_backend,"error.log"},{"error.log",error,10485760, "$D0",5}},
@@ -139,7 +143,21 @@ application_config_mangling_test_() ->
                                 {"error.log", error, 10485760, "$D0", 5},
                                 {"console.log", info, 10485760, "$D0", 5}
                             ]}]
-                ))},
+                ))
+        },
+        {"Explode the short form of backend file handlers",
+            ?_assertMatch(
+                [{lager_console_backend, info},
+                    {{lager_file_backend,"error.log"},{"error.log",error}},
+                    {{lager_file_backend,"console.log"},{"console.log",info}}
+                ],
+                expand_handlers([{lager_console_backend, info},
+                        {lager_file_backend, [
+                                {"error.log", error},
+                                {"console.log", info}
+                            ]}]
+                ))
+        },
         {"Explode with formatter info",
             ?_assertMatch(
                 [{{lager_file_backend,"test.log"},  [{"test.log", debug, 10485760, "$D0", 5},{lager_default_formatter,["[",severity,"] ", message, "\n"]}]},
@@ -150,5 +168,30 @@ application_config_mangling_test_() ->
                             ]
                         }])
             )
-        }].
+        },
+        {"Explode short form with short formatter info",
+            ?_assertMatch(
+                [{{lager_file_backend,"test.log"},  [{"test.log", debug},{lager_default_formatter,["[",severity,"] ", message, "\n"]}]},
+                    {{lager_file_backend,"test2.log"}, [{"test2.log",debug},{lager_default_formatter}]}],
+                expand_handlers([{lager_file_backend, [
+                                [{"test.log", debug},{lager_default_formatter,["[",severity,"] ", message, "\n"]}],
+                                [{"test2.log",debug},{lager_default_formatter}]
+                            ]
+                        }])
+            )
+        },
+        {"New form needs no expansion",
+            ?_assertMatch([
+                    {{lager_file_backend,"test.log"},  [{file, "test.log"}]},
+                    {{lager_file_backend,"test2.log"}, [{file, "test2.log"}, {level, info}, {sync_on, none}]},
+                    {{lager_file_backend,"test3.log"}, [{formatter, lager_default_formatter}, {file, "test3.log"}]}
+                ],
+                expand_handlers([
+                        {lager_file_backend, [{file, "test.log"}]},
+                        {lager_file_backend, [{file, "test2.log"}, {level, info}, {sync_on, none}]},
+                        {lager_file_backend, [{formatter, lager_default_formatter},{file, "test3.log"}]}
+                    ])
+            )
+        }
+    ].
 -endif.
diff --git a/src/lager_default_formatter.erl b/src/lager_default_formatter.erl
@@ -79,10 +79,10 @@ format(Msg, Config) ->
 -spec output(term(),lager_msg:lager_msg()) -> iolist().
 output(message,Msg) -> lager_msg:message(Msg);
 output(date,Msg) ->
-    {D, _T} = lager_msg:timestamp(Msg),
+    {D, _T} = lager_msg:datetime(Msg),
     D;
 output(time,Msg) ->
-    {_D, T} = lager_msg:timestamp(Msg),
+    {_D, T} = lager_msg:datetime(Msg),
     T;
 output(severity,Msg) ->
     atom_to_list(lager_msg:severity(Msg));
@@ -129,11 +129,17 @@ get_metadata(Key, Metadata, Default) ->
     end.
 
 -ifdef(TEST).
+date_time_now() ->
+    Now = os:timestamp(),
+    {Date, Time} = lager_util:format_time(lager_util:maybe_utc(lager_util:localtime_ms(Now))),
+    {Date, Time, Now}.
+
 basic_test_() ->
+    {Date, Time, Now} = date_time_now(),
     [{"Default formatting test",
-            ?_assertEqual(iolist_to_binary([<<"Day Time [error] ">>, pid_to_list(self()), <<" Message\n">>]),
+            ?_assertEqual(iolist_to_binary([Date, " ", Time,  " [error] ", pid_to_list(self()), " Message\n"]),
                 iolist_to_binary(format(lager_msg:new("Message",
-                            {"Day", "Time"},
+                            Now,
                             error,
                             [{pid, self()}],
                             []),
@@ -142,36 +148,36 @@ basic_test_() ->
         {"Basic Formatting",
             ?_assertEqual(<<"Simplist Format">>,
                 iolist_to_binary(format(lager_msg:new("Message",
-                            {"Day", "Time"},
+                            Now,
                             error,
                             [{pid, self()}],
                             []),
                         ["Simplist Format"])))
         },
         {"Default equivalent formatting test",
-            ?_assertEqual(iolist_to_binary([<<"Day Time [error] ">>, pid_to_list(self()), <<" Message\n">>]),
+            ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] ", pid_to_list(self()), " Message\n"]),
                 iolist_to_binary(format(lager_msg:new("Message",
-                            {"Day", "Time"},
+                            Now,
                             error,
                             [{pid, self()}],
                             []),
                         [date, " ", time," [",severity,"] ",pid, " ", message, "\n"]
                     )))
         },
         {"Non existant metadata can default to string",
-            ?_assertEqual(iolist_to_binary([<<"Day Time [error] Fallback Message\n">>]),
+            ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] Fallback Message\n"]),
                 iolist_to_binary(format(lager_msg:new("Message",
-                            {"Day", "Time"},
+                            Now,
                             error,
                             [{pid, self()}],
                             []),
                         [date, " ", time," [",severity,"] ",{does_not_exist,"Fallback"}, " ", message, "\n"]
                     )))
         },
         {"Non existant metadata can default to other metadata",
-            ?_assertEqual(iolist_to_binary([<<"Day Time [error] Fallback Message\n">>]),
+            ?_assertEqual(iolist_to_binary([Date, " ", Time, " [error] Fallback Message\n"]),
                 iolist_to_binary(format(lager_msg:new("Message",
-                            {"Day", "Time"},
+                            Now,
                             error,
                             [{pid, "Fallback"}],
                             []),