From 8aa64c90ddd20ec0ca8cc5fe92a6124324c51da5 Mon Sep 17 00:00:00 2001 From: Siri Hansen Date: Wed, 16 May 2018 16:10:30 +0200 Subject: Use system_time instead of monotonic_time as timestamp in logger --- lib/kernel/doc/src/logger.xml | 6 +++--- lib/kernel/src/code_server.erl | 4 ++-- lib/kernel/src/logger.erl | 2 +- lib/kernel/src/logger_formatter.erl | 11 +++++------ lib/kernel/src/logger_simple.erl | 7 +++---- lib/kernel/test/logger_SUITE.erl | 4 ++-- lib/kernel/test/logger_formatter_SUITE.erl | 5 ++--- 7 files changed, 18 insertions(+), 21 deletions(-) (limited to 'lib/kernel') diff --git a/lib/kernel/doc/src/logger.xml b/lib/kernel/doc/src/logger.xml index 183102f240..cac9c39f2a 100644 --- a/lib/kernel/doc/src/logger.xml +++ b/lib/kernel/doc/src/logger.xml @@ -111,7 +111,7 @@ logger:error("error happened because: ~p",[Reason]). %% Without macro pid => self() gl => group_leader() - time => erlang:monotonic_time(microsecond) + time => erlang:system_time(microsecond)

When a log macro is used, Logger also inserts location information:

@@ -184,8 +184,8 @@ logger:error("error happened because: ~p",[Reason]). %% Without macro

A timestamp produced - with - erlang:monotonic_time(microsecond).

+ with + erlang:system_time(microsecond).

 diff --git a/lib/kernel/src/code_server.erl b/lib/kernel/src/code_server.erl index bbfa2a995d..1a7677295b 100644 --- a/lib/kernel/src/code_server.erl +++ b/lib/kernel/src/code_server.erl @@ -1437,7 +1437,7 @@ error_msg(Format, Args) -> logger ! {log,error,Format,Args, #{pid=>self(), gl=>group_leader(), - time=>erlang:monotonic_time(microsecond), + time=>erlang:system_time(microsecond), error_logger=>#{tag=>error}}}, ok. @@ -1446,7 +1446,7 @@ info_msg(Format, Args) -> logger ! {log,info,Format,Args, #{pid=>self(), gl=>group_leader(), - time=>erlang:monotonic_time(microsecond), + time=>erlang:system_time(microsecond), error_logger=>#{tag=>info_msg}}}, ok. diff --git a/lib/kernel/src/logger.erl b/lib/kernel/src/logger.erl index a839f97e62..281521ae6e 100644 --- a/lib/kernel/src/logger.erl +++ b/lib/kernel/src/logger.erl @@ -833,7 +833,7 @@ proc_meta() -> default(pid) -> self(); default(gl) -> group_leader(); -default(time) -> erlang:monotonic_time(microsecond). +default(time) -> erlang:system_time(microsecond). %% Remove everything upto and including this module from the stacktrace filter_stacktrace(Module,[{Module,_,_,_}|_]) -> diff --git a/lib/kernel/src/logger_formatter.erl b/lib/kernel/src/logger_formatter.erl index 602c666cc7..a19e7bbc73 100644 --- a/lib/kernel/src/logger_formatter.erl +++ b/lib/kernel/src/logger_formatter.erl @@ -197,16 +197,15 @@ truncate(String,Size) -> String end. -format_time(Timestamp,#{time_offset:=Offset,time_designator:=Des}) - when is_integer(Timestamp) -> - SysTime = Timestamp + erlang:time_offset(microsecond), +%% SysTime is the system time in microseconds +format_time(SysTime,#{time_offset:=Offset,time_designator:=Des}) + when is_integer(SysTime) -> calendar:system_time_to_rfc3339(SysTime,[{unit,microsecond}, {offset,Offset}, {time_designator,Des}]). -%% Assuming this is monotonic time in microseconds -timestamp_to_datetimemicro(Timestamp,Config) when is_integer(Timestamp) -> - SysTime = Timestamp + erlang:time_offset(microsecond), +%% SysTime is the system time in microseconds +timestamp_to_datetimemicro(SysTime,Config) when is_integer(SysTime) -> Micro = SysTime rem 1000000, Sec = SysTime div 1000000, UniversalTime = erlang:posixtime_to_universaltime(Sec), diff --git a/lib/kernel/src/logger_simple.erl b/lib/kernel/src/logger_simple.erl index 5272455a2d..c8cdf25887 100644 --- a/lib/kernel/src/logger_simple.erl +++ b/lib/kernel/src/logger_simple.erl @@ -70,7 +70,7 @@ log(#{msg:=_,meta:=#{time:=_}}=Log,_Config) -> do_log( #{level=>error, msg=>{report,{error,simple_handler_process_dead}}, - meta=>#{time=>erlang:monotonic_time(microsecond)}}), + meta=>#{time=>erlang:system_time(microsecond)}}), do_log(Log); _ -> ?MODULE ! {log,Log} @@ -126,7 +126,7 @@ drop_msg(0) -> drop_msg(N) -> [#{level=>info, msg=>{"Simple handler buffer full, dropped ~w messages",[N]}, - meta=>#{time=>erlang:monotonic_time(microsecond)}}]. + meta=>#{time=>erlang:system_time(microsecond)}}]. %%%----------------------------------------------------------------- %%% Internal @@ -141,8 +141,7 @@ do_log(#{msg:=Msg,meta:=#{time:=T}}) -> display_date(T), display(Msg). -display_date(Timestamp0) when is_integer(Timestamp0) -> - Timestamp = Timestamp0 + erlang:time_offset(microsecond), +display_date(Timestamp) when is_integer(Timestamp) -> Micro = Timestamp rem 1000000, Sec = Timestamp div 1000000, {{Y,Mo,D},{H,Mi,S}} = erlang:universaltime_to_localtime( diff --git a/lib/kernel/test/logger_SUITE.erl b/lib/kernel/test/logger_SUITE.erl index e602fa2576..1d3410e356 100644 --- a/lib/kernel/test/logger_SUITE.erl +++ b/lib/kernel/test/logger_SUITE.erl @@ -769,14 +769,14 @@ process_metadata(_Config) -> undefined = logger:get_process_metadata(), {error,badarg} = ?TRY(logger:set_process_metadata(bad)), ok = logger:add_handler(h1,?MODULE,#{level=>info,filter_default=>log}), - Time = erlang:monotonic_time(microsecond), + Time = erlang:system_time(microsecond), ProcMeta = #{time=>Time,line=>0,custom=>proc}, ok = logger:set_process_metadata(ProcMeta), S1 = ?str, ?LOG_INFO(S1,#{custom=>macro}), check_logged(info,S1,#{time=>Time,line=>0,custom=>macro}), - Time2 = erlang:monotonic_time(microsecond), + Time2 = erlang:system_time(microsecond), S2 = ?str, ?LOG_INFO(S2,#{time=>Time2,line=>1,custom=>macro}), check_logged(info,S2,#{time=>Time2,line=>1,custom=>macro}), diff --git a/lib/kernel/test/logger_formatter_SUITE.erl b/lib/kernel/test/logger_formatter_SUITE.erl index 9baadfd65a..c171165944 100644 --- a/lib/kernel/test/logger_formatter_SUITE.erl +++ b/lib/kernel/test/logger_formatter_SUITE.erl @@ -546,8 +546,7 @@ default_time_format(Timestamp) -> default_time_format(Timestamp,Utc) -> default_time_format(Timestamp,Utc,$T). -default_time_format(Timestamp0,Utc,Sep) -> - Timestamp=Timestamp0+erlang:time_offset(microsecond), +default_time_format(Timestamp,Utc,Sep) -> Offset = if Utc -> "Z"; true -> "" end, @@ -569,7 +568,7 @@ my_try(Fun) -> try Fun() catch C:R:S -> {C,R,hd(S)} end. timestamp() -> - erlang:monotonic_time(microsecond). + erlang:system_time(microsecond). %% necessary? add_time(#{time:=_}=Meta) -> -- cgit v1.2.3