Improve logging - add timestamp to logs

src/leveled_log.erl

@@ -309,10 +309,12 @@
 
 
 log(LogReference, Subs) ->
-    {ok, {LogLevel, LogText}} = dict:find(LogReference, ?LOGBASE),
+    {LogLevel, LogText} = dict:fetch(LogReference, ?LOGBASE),
     case lists:member(LogLevel, ?LOG_LEVEL) of
         true ->
-            io:format(LogReference ++ " ~w " ++ LogText ++ "~n",
+            io:format(format_time()
+                        ++ " " ++ LogReference ++ " ~w "
+                        ++ LogText ++ "~n",
                         [self()|Subs]);
         false ->
             ok
@@ -320,7 +322,7 @@ log(LogReference, Subs) ->
 
 
 log_timer(LogReference, Subs, StartTime) ->
-    {ok, {LogLevel, LogText}} = dict:find(LogReference, ?LOGBASE),
+    {LogLevel, LogText} = dict:fetch(LogReference, ?LOGBASE),
     case lists:member(LogLevel, ?LOG_LEVEL) of
         true ->
             MicroS = timer:now_diff(os:timestamp(), StartTime),
@@ -330,7 +332,9 @@ log_timer(LogReference, Subs, StartTime) ->
                                 MicroS ->
                                     {"ms", MicroS div 1000}
                             end,
-            io:format(LogReference ++ " ~w " ++ LogText
+            io:format(format_time()
+                            ++ LogReference ++ " ~w "
+                            ++ LogText
                             ++ " with time taken ~w " ++ Unit ++ "~n",
                         [self()|Subs] ++ [Time]);
         false ->
@@ -510,6 +514,17 @@ gen_timing_int({N, TimerD}, T0, TimerType, _KeyListFun, _LogPoint, _LogRef) ->
                     TimerD)}.
 
 
+format_time() ->
+    format_time(localtime_ms()).
+
+localtime_ms() ->
+    {_, _, Micro} = Now = os:timestamp(),
+    {Date, {Hours, Minutes, Seconds}} = calendar:now_to_local_time(Now),
+    {Date, {Hours, Minutes, Seconds, Micro div 1000 rem 1000}}.
+
+format_time({{Y, M, D}, {H, Mi, S, Ms}}) ->
+    io_lib:format("~b-~2..0b-~2..0b", [Y, M, D]) ++ "T" ++
+        io_lib:format("~2..0b:~2..0b:~2..0b.~3..0b", [H, Mi, S, Ms]).
 
 
 %%%============================================================================

src/leveled_tree.erl

@@ -524,7 +524,7 @@ search_test_by_type(Type) ->
     T = from_orderedlist(KL, Type),
     
     StartKeyFun = fun(V) -> V end,
-    SW = os:timestamp(),
+    statistics(runtime),
     ?assertMatch([], search_range(0, 1, T, StartKeyFun)),
     ?assertMatch([], search_range(201, 202, T, StartKeyFun)),
     ?assertMatch([{4, 2}], search_range(2, 4, T, StartKeyFun)),
@@ -535,8 +535,9 @@ search_test_by_type(Type) ->
     ?assertMatch(49, length(search_range(2, 197, T, StartKeyFun))),
     ?assertMatch(49, length(search_range(4, 197, T, StartKeyFun))),
     ?assertMatch(48, length(search_range(5, 197, T, StartKeyFun))),
+    {_, T1} = statistics(runtime),
     io:format(user, "10 range tests with type ~w in ~w microseconds~n",
-                [Type, timer:now_diff(os:timestamp(), SW)]).
+                [Type, T1]).
 
 
 tree_oor_test() ->
@@ -591,21 +592,30 @@ tolist_test_by_type(Type) ->
     ?assertMatch(KL, T_Reverse).
     
 tree_timing_test() ->
-    tree_test_by_(16, tree, 4000),
+    log_tree_test_by_(16, tree, 4000),
     tree_test_by_(8, tree, 1000),
     tree_test_by_(4, tree, 256).
 
 idxt_timing_test() ->
-    tree_test_by_(16, idxt, 4000),
+    log_tree_test_by_(16, idxt, 4000),
     tree_test_by_(8, idxt, 1000),
     tree_test_by_(4, idxt, 256).
 
 skpl_timing_test() ->
     tree_test_by_(auto, skpl, 6000),
-    tree_test_by_(auto, skpl, 4000),
+    log_tree_test_by_(auto, skpl, 4000),
     tree_test_by_(auto, skpl, 1000),
     tree_test_by_(auto, skpl, 256).
 
+log_tree_test_by_(Width, Type, N) ->
+    erlang:statistics(runtime),
+    G0 = erlang:statistics(garbage_collection),
+    tree_test_by_(Width, Type, N),
+    {_, T1} = erlang:statistics(runtime),
+    G1 = erlang:statistics(garbage_collection),
+    io:format(user, "Test took ~w ms and GC transitioned from ~w to ~w~n",
+                [T1, G0, G1]).
+
 tree_test_by_(Width, Type, N) ->
     io:format(user, "~nTree test for type and width: ~w ~w~n", [Type, Width]),
     KL = lists:ukeysort(1, generate_randomkeys(1, N, 1, N div 5)),