telemetry.erl (15287B)
1 %%%------------------------------------------------------------------- 2 %% @doc `telemetry' allows you to invoke certain functions whenever a 3 %% particular event is emitted. 4 %% 5 %% For more information see the documentation for {@link attach/4}, {@link attach_many/4} 6 %% and {@link execute/2}. 7 %% @end 8 %%%------------------------------------------------------------------- 9 -module(telemetry). 10 11 -export([attach/4, 12 attach_many/4, 13 detach/1, 14 list_handlers/1, 15 execute/2, 16 execute/3, 17 span/3]). 18 19 -export([report_cb/1]). 20 21 -include("telemetry.hrl"). 22 23 -type handler_id() :: term(). 24 -type event_name() :: [atom(), ...]. 25 -type event_measurements() :: map(). 26 -type event_metadata() :: map(). 27 -type event_value() :: number(). 28 -type event_prefix() :: [atom()]. 29 -type handler_config() :: term(). 30 -type handler_function() :: fun((event_name(), event_measurements(), event_metadata(), handler_config()) -> any()). 31 -type span_result() :: term(). 32 -type span_function() :: fun(() -> {span_result(), event_metadata()}). 33 -type handler() :: #{id := handler_id(), 34 event_name := event_name(), 35 function := handler_function(), 36 config := handler_config()}. 37 38 -export_type([handler_id/0, 39 event_name/0, 40 event_measurements/0, 41 event_metadata/0, 42 event_value/0, 43 event_prefix/0, 44 handler_config/0, 45 handler_function/0, 46 handler/0, 47 span_result/0, 48 span_function/0]). 49 50 -import_lib("kernel/import/logger.hrl"). 51 52 %% @doc Attaches the handler to the event. 53 %% 54 %% `handler_id' must be unique, if another handler with the same ID already exists the 55 %% `{error, already_exists}' tuple is returned. 56 %% 57 %% See {@link execute/3} to learn how the handlers are invoked. 58 %% 59 %% <b>Note:</b> due to how anonymous functions are implemented in the Erlang VM, it is best to use 60 %% function captures (i.e. `fun mod:fun/4' in Erlang or `&Mod.fun/4' in Elixir) as event handlers 61 %% to achieve maximum performance. In other words, avoid using literal anonymous functions 62 %% (`fun(...) -> ... end' or `fn ... -> ... end') or local function captures (`fun handle_event/4' 63 %% or `&handle_event/4' ) as event handlers. 64 %% 65 %% All the handlers are executed by the process dispatching event. If the function fails (raises, 66 %% exits or throws) then the handler is removed and a failure event is emitted. 67 %% 68 %% Handler failure events `[telemetry, handler, failure]' should only be used for monitoring 69 %% and diagnostic purposes. Re-attaching a failed handler will likely result in the handler 70 %% failing again. 71 %% 72 %% Note that you should not rely on the order in which handlers are invoked. 73 -spec attach(HandlerId, EventName, Function, Config) -> ok | {error, already_exists} when 74 HandlerId :: handler_id(), 75 EventName :: event_name(), 76 Function :: handler_function(), 77 Config :: handler_config(). 78 attach(HandlerId, EventName, Function, Config) -> 79 attach_many(HandlerId, [EventName], Function, Config). 80 81 %% @doc Attaches the handler to many events. 82 %% 83 %% The handler will be invoked whenever any of the events in the `event_names' list is emitted. Note 84 %% that failure of the handler on any of these invocations will detach it from all the events in 85 %% `event_name' (the same applies to manual detaching using {@link detach/1}). 86 %% 87 %% <b>Note:</b> due to how anonymous functions are implemented in the Erlang VM, it is best to use 88 %% function captures (i.e. `fun mod:fun/4' in Erlang or `&Mod.fun/4' in Elixir) as event handlers 89 %% to achieve maximum performance. In other words, avoid using literal anonymous functions 90 %% (`fun(...) -> ... end' or `fn ... -> ... end') or local function captures (`fun handle_event/4' 91 %% or `&handle_event/4' ) as event handlers. 92 %% 93 %% All the handlers are executed by the process dispatching event. If the function fails (raises, 94 %% exits or throws) a handler failure event is emitted and then the handler is removed. 95 %% 96 %% Handler failure events `[telemetry, handler, failure]' should only be used for monitoring 97 %% and diagnostic purposes. Re-attaching a failed handler will likely result in the handler 98 %% failing again. 99 %% 100 %% Note that you should not rely on the order in which handlers are invoked. 101 -spec attach_many(HandlerId, [EventName], Function, Config) -> ok | {error, already_exists} when 102 HandlerId :: handler_id(), 103 EventName :: event_name(), 104 Function :: handler_function(), 105 Config :: handler_config(). 106 attach_many(HandlerId, EventNames, Function, Config) when is_function(Function, 4) -> 107 assert_event_names(EventNames), 108 case erlang:fun_info(Function, type) of 109 {type, external} -> 110 ok; 111 {type, local} -> 112 ?LOG_INFO(#{handler_id => HandlerId, 113 event_names => EventNames, 114 function => Function, 115 config => Config, 116 type => local}, 117 #{report_cb => fun ?MODULE:report_cb/1}) 118 end, 119 telemetry_handler_table:insert(HandlerId, EventNames, Function, Config). 120 121 %% @doc Removes the existing handler. 122 %% 123 %% If the handler with given ID doesn't exist, `{error, not_found}' is returned. 124 -spec detach(handler_id()) -> ok | {error, not_found}. 125 detach(HandlerId) -> 126 telemetry_handler_table:delete(HandlerId). 127 128 %% @doc Emits the event, invoking handlers attached to it. 129 %% 130 %% When the event is emitted, the handler function provided to {@link attach/4} is called with four 131 %% arguments: 132 %% <ul> 133 %% <li>the event name</li> 134 %% <li>the map of measurements</li> 135 %% <li>the map of event metadata</li> 136 %% <li>the handler configuration given to {@link attach/4}</li> 137 %% </ul> 138 %% 139 %% <h4>Best practices and conventions:</h4> 140 %% 141 %% <p> 142 %% While you are able to emit messages of any `event_name' structure, it is recommended that you follow the 143 %% the guidelines laid out in {@link span/3} if you are capturing start/stop events. 144 %% </p> 145 -spec execute(EventName, Measurements, Metadata) -> ok when 146 EventName :: event_name(), 147 Measurements :: event_measurements() | event_value(), 148 Metadata :: event_metadata(). 149 execute(EventName, Value, Metadata) when is_number(Value) -> 150 ?LOG_WARNING("Using execute/3 with a single event value is deprecated. " 151 "Use a measurement map instead.", []), 152 execute(EventName, #{value => Value}, Metadata); 153 execute([_ | _] = EventName, Measurements, Metadata) when is_map(Measurements) and is_map(Metadata) -> 154 Handlers = telemetry_handler_table:list_for_event(EventName), 155 ApplyFun = 156 fun(#handler{id=HandlerId, 157 function=HandlerFunction, 158 config=Config}) -> 159 try 160 HandlerFunction(EventName, Measurements, Metadata, Config) 161 catch 162 ?WITH_STACKTRACE(Class, Reason, Stacktrace) 163 detach(HandlerId), 164 FailureMetadata = #{event_name => EventName, 165 handler_id => HandlerId, 166 handler_config => Config, 167 kind => Class, 168 reason => Reason, 169 stacktrace => Stacktrace}, 170 FailureMeasurements = #{monotonic_time => erlang:monotonic_time(), system_time => erlang:system_time()}, 171 execute([telemetry, handler, failure], FailureMeasurements, FailureMetadata), 172 ?LOG_ERROR("Handler ~p has failed and has been detached. " 173 "Class=~p~nReason=~p~nStacktrace=~p~n", 174 [HandlerId, Class, Reason, Stacktrace]) 175 end 176 end, 177 lists:foreach(ApplyFun, Handlers). 178 179 %% @doc Runs the provided `SpanFunction', emitting start and stop/exception events, invoking the handlers attached to each. 180 %% 181 %% The `SpanFunction' must return a `{result, stop_metadata}' tuple. 182 %% 183 %% When this function is called, 2 events will be emitted via {@link execute/3}. Those events will be one of the following 184 %% pairs: 185 %% <ul> 186 %% <li>`EventPrefix ++ [start]' and `EventPrefix ++ [stop]'</li> 187 %% <li>`EventPrefix ++ [start]' and `EventPrefix ++ [exception]'</li> 188 %% </ul> 189 %% 190 %% However, note that in case the current process crashes due to an exit signal 191 %% of another process, then none or only part of those events would be emitted. 192 %% Below is a breakdown of the measurements and metadata associated with each individual event. 193 %% 194 %% When providing `StartMetadata' and `StopMetadata', these values will be sent independently to `start' and 195 %% `stop' events. If an exception occurs, exception metadata will be merged onto the `StartMetadata'. In general, 196 %% `StopMetadata' should only provide values that are additive to `StartMetadata' so that handlers, such as those 197 %% used for metrics, can rely entirely on the `stop' event. 198 %% 199 %% A default span context is added to event metadata under the `telemetry_span_context' key if none is provided by 200 %% the user in the `StartMetadata'. This context is useful for tracing libraries to identify unique 201 %% executions of span events within a process to match start, stop, and exception events. Users 202 %% should ensure this value is unique within the context of a process at a minimum if overriding this key and 203 %% that the same value is provided to both `StartMetadata' and `StopMetadata'. 204 %% 205 %% For `telemetry' events denoting the <strong>start</strong> of a larger event, the following data is provided: 206 %% 207 %% <p> 208 %% <ul> 209 %% <li> 210 %% Event: 211 %% ``` 212 %% EventPrefix ++ [start] 213 %% ''' 214 %% </li> 215 %% <li> 216 %% Measurements: 217 %% ``` 218 %% #{ 219 %% % The current system time in native units from 220 %% % calling: erlang:system_time() 221 %% system_time => integer(), 222 %% monotonic_time => integer(), 223 %% } 224 %% ''' 225 %% </li> 226 %% <li> 227 %% Metadata: 228 %% ``` 229 %% #{ 230 %% telemetry_span_context => term(), 231 %% % User defined metadata as provided in StartMetadata 232 %% ... 233 %% } 234 %% ''' 235 %% </li> 236 %% </ul> 237 %% </p> 238 %% 239 %% For `telemetry' events denoting the <strong>stop</strong> of a larger event, the following data is provided: 240 %% <p> 241 %% <ul> 242 %% <li> 243 %% Event: 244 %% ``` 245 %% EventPrefix ++ [stop] 246 %% ''' 247 %% </li> 248 %% <li> 249 %% Measurements: 250 %% ``` 251 %% #{ 252 %% % The current monotonic time minus the start monotonic time in native units 253 %% % by calling: erlang:monotonic_time() - start_monotonic_time 254 %% duration => integer(), 255 %% monotonic_time => integer() 256 %% } 257 %% ''' 258 %% </li> 259 %% <li> 260 %% Metadata: 261 %% ``` 262 %% #{ 263 %% % An optional error field if the stop event is the result of an error 264 %% % but not necessarily an exception. 265 %% error => term(), 266 %% telemetry_span_context => term(), 267 %% % User defined metadata as provided in StopMetadata 268 %% ... 269 %% } 270 %% ''' 271 %% </li> 272 %% </ul> 273 %% </p> 274 %% 275 %% For `telemetry' events denoting an <strong>exception</strong> of a larger event, the following data is provided: 276 %% <p> 277 %% <ul> 278 %% <li> 279 %% Event: 280 %% ``` 281 %% EventPrefix ++ [exception] 282 %% ''' 283 %% </li> 284 %% <li> 285 %% Measurements: 286 %% ``` 287 %% #{ 288 %% % The current monotonic time minus the start monotonic time in native units 289 %% % derived by calling: erlang:monotonic_time() - start_monotonic_time 290 %% duration => integer(), 291 %% monotonic_time => integer() 292 %% } 293 %% ''' 294 %% </li> 295 %% <li> 296 %% Metadata: 297 %% ``` 298 %% #{ 299 %% kind => throw | error | exit, 300 %% reason => term(), 301 %% stacktrace => list(), 302 %% telemetry_span_context => term(), 303 %% % User defined metadata as provided in StartMetadata 304 %% ... 305 %% } 306 %% ''' 307 %% </li> 308 %% </ul> 309 %% </p> 310 -spec span(event_prefix(), event_metadata(), span_function()) -> span_result(). 311 span(EventPrefix, StartMetadata, SpanFunction) -> 312 StartTime = erlang:monotonic_time(), 313 DefaultCtx = erlang:make_ref(), 314 execute( 315 EventPrefix ++ [start], 316 #{monotonic_time => StartTime, system_time => erlang:system_time()}, 317 merge_ctx(StartMetadata, DefaultCtx) 318 ), 319 320 try {_, #{}} = SpanFunction() of 321 {Result, StopMetadata} -> 322 StopTime = erlang:monotonic_time(), 323 execute( 324 EventPrefix ++ [stop], 325 #{duration => StopTime - StartTime, monotonic_time => StopTime}, 326 merge_ctx(StopMetadata, DefaultCtx) 327 ), 328 Result 329 catch 330 ?WITH_STACKTRACE(Class, Reason, Stacktrace) 331 StopTime = erlang:monotonic_time(), 332 execute( 333 EventPrefix ++ [exception], 334 #{duration => StopTime - StartTime, monotonic_time => StopTime}, 335 merge_ctx(StartMetadata#{kind => Class, reason => Reason, stacktrace => Stacktrace}, DefaultCtx) 336 ), 337 erlang:raise(Class, Reason, Stacktrace) 338 end. 339 340 %% @equiv execute(EventName, Measurements, #{}) 341 -spec execute(EventName, Measurements) -> ok when 342 EventName :: event_name(), 343 Measurements :: event_measurements() | event_value(). 344 execute(EventName, Measurements) -> 345 execute(EventName, Measurements, #{}). 346 347 %% @doc Returns all handlers attached to events with given prefix. 348 %% 349 %% Handlers attached to many events at once using {@link attach_many/4} will be listed once for each 350 %% event they're attached to. 351 %% Note that you can list all handlers by feeding this function an empty list. 352 -spec list_handlers(event_prefix()) -> [handler()]. 353 list_handlers(EventPrefix) -> 354 assert_event_prefix(EventPrefix), 355 [#{id => HandlerId, 356 event_name => EventName, 357 function => Function, 358 config => Config} || #handler{id=HandlerId, 359 event_name=EventName, 360 function=Function, 361 config=Config} <- telemetry_handler_table:list_by_prefix(EventPrefix)]. 362 363 %% 364 365 -spec assert_event_names(term()) -> [ok]. 366 assert_event_names(List) when is_list(List) -> 367 [assert_event_name(E) || E <- List]; 368 assert_event_names(Term) -> 369 erlang:error(badarg, Term). 370 371 -spec assert_event_prefix(term()) -> ok. 372 assert_event_prefix(List) when is_list(List) -> 373 case lists:all(fun erlang:is_atom/1, List) of 374 true -> 375 ok; 376 false -> 377 erlang:error(badarg, List) 378 end; 379 assert_event_prefix(List) -> 380 erlang:error(badarg, List). 381 382 -spec assert_event_name(term()) -> ok. 383 assert_event_name([_ | _] = List) -> 384 case lists:all(fun erlang:is_atom/1, List) of 385 true -> 386 ok; 387 false -> 388 erlang:error(badarg, List) 389 end; 390 assert_event_name(Term) -> 391 erlang:error(badarg, Term). 392 393 -spec merge_ctx(event_metadata(), any()) -> event_metadata(). 394 merge_ctx(#{telemetry_span_context := _} = Metadata, _Ctx) -> Metadata; 395 merge_ctx(Metadata, Ctx) -> Metadata#{telemetry_span_context => Ctx}. 396 397 %% @private 398 report_cb(#{handler_id := Id}) -> 399 {"The function passed as a handler with ID ~w is a local function.\n" 400 "This means that it is either an anonymous function or a capture of a function " 401 "without a module specified. That may cause a performance penalty when calling " 402 "that handler. For more details see the note in `telemetry:attach/4` " 403 "documentation.\n\n" 404 "https://hexdocs.pm/telemetry/telemetry.html#attach/4", [Id]}.