From 7fabd25ae91e28180f674885c9ac1b505c725de6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 13 Aug 2021 10:52:34 +0200 Subject: [PATCH 1/2] Add monotonic_time to span measurements --- README.md | 4 ++-- src/telemetry.erl | 25 +++++++++++++++++++------ test/telemetry_SUITE.erl | 8 ++++---- 3 files changed, 25 insertions(+), 12 deletions(-) diff --git a/README.md b/README.md index c6caab8..ff51c54 100644 --- a/README.md +++ b/README.md @@ -108,8 +108,8 @@ will be re-raised. The measurements for the `EventPrefix ++ [start]` event will contain a key called `system_time` which is derived by calling `erlang:system_time()`. For `EventPrefix ++ [stop]` and `EventPrefix ++ [exception]` events, the measurements will contain a key called `duration`, whose value is derived by calling -`erlang:monotonic_time() - StartMonotonicTime`. Both `system_time` and `duration` represent time as -native units. +`erlang:monotonic_time() - StartMonotonicTime`. ALl events include a `monotonic_time` measurements too. +All of them represent time as native units. To convert the duration from native units you can use: diff --git a/src/telemetry.erl b/src/telemetry.erl index 8eaa702..6b0031a 100644 --- a/src/telemetry.erl +++ b/src/telemetry.erl @@ -198,7 +198,8 @@ execute(EventName, Measurements, Metadata) when is_map(Measurements) and is_map( %% #{ %% % The current system time in native units from %% % calling: erlang:system_time() -%% system_time => integer() +%% system_time => integer(), +%% monotonic_time => integer(), %% } %% ''' %% @@ -230,7 +231,8 @@ execute(EventName, Measurements, Metadata) when is_map(Measurements) and is_map( %% #{ %% % The current monotonic time minus the start monotonic time in native units %% % by calling: erlang:monotonic_time() - start_monotonic_time -%% duration => integer() +%% duration => integer(), +%% monotonic_time => integer() %% } %% ''' %% @@ -265,7 +267,8 @@ execute(EventName, Measurements, Metadata) when is_map(Measurements) and is_map( %% #{ %% % The current monotonic time minus the start monotonic time in native units %% % derived by calling: erlang:monotonic_time() - start_monotonic_time -%% duration => integer() +%% duration => integer(), +%% monotonic_time => integer() %% } %% ''' %% @@ -288,17 +291,27 @@ execute(EventName, Measurements, Metadata) when is_map(Measurements) and is_map( span(EventPrefix, StartMetadata, SpanFunction) -> StartTime = erlang:monotonic_time(), DefaultCtx = erlang:make_ref(), - execute(EventPrefix ++ [start], #{system_time => erlang:system_time()}, merge_ctx(StartMetadata, DefaultCtx)), + execute( + EventPrefix ++ [start], + #{monotonic_time => StartTime, system_time => erlang:system_time()}, + merge_ctx(StartMetadata, DefaultCtx) + ), try {_, #{}} = SpanFunction() of {Result, StopMetadata} -> - execute(EventPrefix ++ [stop], #{duration => erlang:monotonic_time() - StartTime}, merge_ctx(StopMetadata, DefaultCtx)), + StopTime = erlang:monotonic_time(), + execute( + EventPrefix ++ [stop], + #{duration => StopTime - StartTime, monotonic_time => StopTime}, + merge_ctx(StopMetadata, DefaultCtx) + ), Result catch ?WITH_STACKTRACE(Class, Reason, Stacktrace) + StopTime = erlang:monotonic_time(), execute( EventPrefix ++ [exception], - #{duration => erlang:monotonic_time() - StartTime}, + #{duration => StopTime - StartTime, monotonic_time => StopTime}, merge_ctx(StartMetadata#{kind => Class, reason => Reason, stacktrace => Stacktrace}, DefaultCtx) ), erlang:raise(Class, Reason, Stacktrace) diff --git a/test/telemetry_SUITE.erl b/test/telemetry_SUITE.erl index 58df646..97dde8e 100644 --- a/test/telemetry_SUITE.erl +++ b/test/telemetry_SUITE.erl @@ -313,14 +313,14 @@ invoke_successful_span_handlers(Config) -> receive {event, StartEvent, StartMeasurements, StartMetadata, HandlerConfig} -> - ?assertEqual([system_time], maps:keys(StartMeasurements)) + ?assertEqual([monotonic_time, system_time], maps:keys(StartMeasurements)) after 1000 -> ct:fail(timeout_receive_echo) end, receive {event, StopEvent, StopMeasurements, StopMetadata, HandlerConfig} -> - ?assertEqual([duration], maps:keys(StopMeasurements)) + ?assertEqual([duration, monotonic_time], maps:keys(StopMeasurements)) after 1000 -> ct:fail(timeout_receive_echo) end. @@ -349,14 +349,14 @@ invoke_exception_span_handlers(Config) -> receive {event, StartEvent, StartMeasurements, StartMetadata, HandlerConfig} -> - ?assertEqual([system_time], maps:keys(StartMeasurements)) + ?assertEqual([monotonic_time, system_time], maps:keys(StartMeasurements)) after 1000 -> ct:fail(timeout_receive_echo) end, receive {event, ExceptionEvent, StopMeasurements, ExceptionMetadata, HandlerConfig} -> - ?assertEqual([duration], maps:keys(StopMeasurements)), + ?assertEqual([duration, monotonic_time], maps:keys(StopMeasurements)), ?assertEqual([kind, reason, some, stacktrace, telemetry_span_context], lists:sort(maps:keys(ExceptionMetadata))) after 1000 -> ct:fail(timeout_receive_echo) From b59b0c0c65570c952e894caee2b53986ca445974 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Jos=C3=A9=20Valim?= Date: Fri, 13 Aug 2021 20:44:23 +0200 Subject: [PATCH 2/2] Update README.md Co-authored-by: Arek Gil --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index ff51c54..dfe81c7 100644 --- a/README.md +++ b/README.md @@ -108,7 +108,7 @@ will be re-raised. The measurements for the `EventPrefix ++ [start]` event will contain a key called `system_time` which is derived by calling `erlang:system_time()`. For `EventPrefix ++ [stop]` and `EventPrefix ++ [exception]` events, the measurements will contain a key called `duration`, whose value is derived by calling -`erlang:monotonic_time() - StartMonotonicTime`. ALl events include a `monotonic_time` measurements too. +`erlang:monotonic_time() - StartMonotonicTime`. All events include a `monotonic_time` measurements too. All of them represent time as native units. To convert the duration from native units you can use: