woody_erlang/test/bench_woody_event_handler.erl
Andrew Mayorov 4fab3f64af
Split severity off formatted event message (#152)
It's usually needed earlier than the message itself. And may even be used
to skip formatting altogether, with `msg_fun()` facility in Erlang
logger.

Simplify event handler interface which should make this module more
usable down the line.

Also use monotonic timestamps when measuring time intervals.
2021-06-22 11:01:27 +03:00

136 lines
8.6 KiB
Erlang

-module(bench_woody_event_handler).
%% API
-export([
iolib_formatter/1,
bench_iolib_formatter/2,
thrift_formatter/1,
bench_thrift_formatter/2
]).
-type input() :: {woody_event_handler:event_meta(), woody:rpc_id()}.
-spec input() -> input().
input() ->
Meta = #{
args => {
{mg_stateproc_CallArgs,
{bin,
<<131, 104, 4, 100, 0, 11, 116, 104, 114, 105, 102, 116, 95, 99, 97, 108, 108, 100, 0, 16, 112, 97,
114, 116, 121, 95, 109, 97, 110, 97, 103, 101, 109, 101, 110, 116, 104, 2, 100, 0, 15, 80, 97,
114, 116, 121, 77, 97, 110, 97, 103, 101, 109, 101, 110, 116, 100, 0, 11, 67, 114, 101, 97, 116,
101, 67, 108, 97, 105, 109, 109, 0, 0, 2, 145, 11, 0, 2, 0, 0, 0, 11, 49, 67, 83, 72, 84, 104,
84, 69, 74, 56, 52, 15, 0, 3, 12, 0, 0, 0, 4, 12, 0, 4, 11, 0, 1, 0, 0, 0, 11, 49, 67, 83, 72,
84, 106, 75, 108, 51, 52, 75, 12, 0, 2, 12, 0, 1, 12, 0, 2, 8, 0, 1, 0, 0, 0, 1, 0, 12, 0, 3, 8,
0, 1, 0, 0, 0, 1, 0, 12, 0, 1, 12, 0, 1, 12, 0, 1, 11, 0, 1, 0, 0, 0, 18, 72, 111, 111, 102,
115, 32, 38, 32, 72, 111, 114, 110, 115, 32, 79, 74, 83, 67, 11, 0, 2, 0, 0, 0, 10, 49, 50, 51,
52, 53, 48, 57, 56, 55, 54, 11, 0, 3, 0, 0, 0, 13, 49, 50, 49, 51, 52, 53, 54, 55, 56, 57, 48,
49, 50, 11, 0, 4, 0, 0, 0, 48, 78, 101, 122, 97, 104, 117, 97, 108, 99, 111, 121, 111, 116, 108,
32, 49, 48, 57, 32, 80, 105, 115, 111, 32, 56, 44, 32, 67, 101, 110, 116, 114, 111, 44, 32, 48,
54, 48, 56, 50, 44, 32, 77, 69, 88, 73, 67, 79, 11, 0, 5, 0, 0, 0, 3, 78, 97, 78, 11, 0, 6, 0,
0, 0, 8, 68, 105, 114, 101, 99, 116, 111, 114, 11, 0, 7, 0, 0, 0, 7, 83, 111, 109, 101, 111,
110, 101, 11, 0, 8, 0, 0, 0, 13, 49, 48, 48, 36, 32, 98, 97, 110, 107, 110, 111, 116, 101, 12,
0, 9, 11, 0, 1, 0, 0, 0, 19, 52, 50, 55, 54, 51, 48, 48, 48, 49, 48, 57, 48, 56, 51, 49, 50, 56,
57, 51, 11, 0, 2, 0, 0, 0, 8, 83, 111, 109, 101, 66, 97, 110, 107, 11, 0, 3, 0, 0, 0, 9, 49, 50,
51, 49, 50, 57, 56, 55, 54, 11, 0, 4, 0, 0, 0, 8, 54, 54, 54, 52, 50, 54, 54, 54, 0, 0, 0, 0, 0,
0, 0, 0, 12, 0, 4, 11, 0, 1, 0, 0, 0, 11, 49, 67, 83, 72, 84, 106, 75, 108, 51, 52, 75, 12, 0,
2, 12, 0, 4, 11, 0, 1, 0, 0, 0, 11, 49, 67, 83, 72, 84, 106, 75, 108, 51, 52, 76, 12, 0, 2, 12,
0, 1, 12, 0, 1, 11, 0, 1, 0, 0, 0, 3, 82, 85, 66, 0, 12, 0, 2, 12, 0, 1, 11, 0, 1, 0, 0, 0, 19,
52, 50, 55, 54, 51, 48, 48, 48, 49, 48, 57, 48, 56, 51, 49, 50, 56, 57, 51, 11, 0, 2, 0, 0, 0,
8, 83, 111, 109, 101, 66, 97, 110, 107, 11, 0, 3, 0, 0, 0, 9, 49, 50, 51, 49, 50, 57, 56, 55,
54, 11, 0, 4, 0, 0, 0, 8, 54, 54, 54, 52, 50, 54, 54, 54, 0, 0, 0, 0, 0, 0, 0, 0, 12, 0, 6, 11,
0, 1, 0, 0, 0, 11, 49, 67, 83, 72, 84, 106, 75, 108, 51, 52, 77, 12, 0, 2, 12, 0, 5, 12, 0, 1,
8, 0, 1, 0, 0, 0, 1, 0, 12, 0, 6, 11, 0, 1, 0, 0, 0, 0, 0, 12, 0, 2, 11, 0, 1, 0, 0, 0, 17, 66,
97, 116, 116, 108, 101, 32, 82, 101, 97, 100, 121, 32, 83, 104, 111, 112, 0, 11, 0, 3, 0, 0, 0,
11, 49, 67, 83, 72, 84, 106, 75, 108, 51, 52, 75, 11, 0, 4, 0, 0, 0, 11, 49, 67, 83, 72, 84,
106, 75, 108, 51, 52, 76, 0, 0, 0, 0, 12, 0, 6, 11, 0, 1, 0, 0, 0, 11, 49, 67, 83, 72, 84, 106,
75, 108, 51, 52, 77, 12, 0, 2, 12, 0, 12, 12, 0, 1, 11, 0, 1, 0, 0, 0, 3, 82, 85, 66, 0, 0, 0,
0, 0, 0>>},
{mg_stateproc_Machine, <<"party">>, <<"1CSHThTEJ84">>,
[
{mg_stateproc_Event, 1, <<"2019-08-13T07:52:11.080519Z">>, undefined,
{arr, [
{obj, #{
{str, <<"ct">>} =>
{str, <<"application/x-erlang-binary">>},
{str, <<"vsn">>} => {i, 6}
}},
{bin,
<<131, 104, 2, 100, 0, 13, 112, 97, 114, 116, 121, 95, 99, 104, 97, 110, 103, 101,
115, 108, 0, 0, 0, 2, 104, 2, 100, 0, 13, 112, 97, 114, 116, 121, 95, 99, 114,
101, 97, 116, 101, 100, 104, 4, 100, 0, 20, 112, 97, 121, 112, 114, 111, 99, 95,
80, 97, 114, 116, 121, 67, 114, 101, 97, 116, 101, 100, 109, 0, 0, 0, 11, 49,
67, 83, 72, 84, 104, 84, 69, 74, 56, 52, 104, 2, 100, 0, 23, 100, 111, 109, 97,
105, 110, 95, 80, 97, 114, 116, 121, 67, 111, 110, 116, 97, 99, 116, 73, 110,
102, 111, 109, 0, 0, 0, 12, 104, 103, 95, 99, 116, 95, 104, 101, 108, 112, 101,
114, 109, 0, 0, 0, 27, 50, 48, 49, 57, 45, 48, 56, 45, 49, 51, 84, 48, 55, 58,
53, 50, 58, 49, 49, 46, 48, 55, 50, 56, 51, 53, 90, 104, 2, 100, 0, 16, 114,
101, 118, 105, 115, 105, 111, 110, 95, 99, 104, 97, 110, 103, 101, 100, 104, 3,
100, 0, 28, 112, 97, 121, 112, 114, 111, 99, 95, 80, 97, 114, 116, 121, 82, 101,
118, 105, 115, 105, 111, 110, 67, 104, 97, 110, 103, 101, 100, 109, 0, 0, 0, 27,
50, 48, 49, 57, 45, 48, 56, 45, 49, 51, 84, 48, 55, 58, 53, 50, 58, 49, 49, 46,
48, 55, 50, 56, 51, 53, 90, 97, 0, 106>>}
]}}
],
{mg_stateproc_HistoryRange, undefined, 10, backward},
{mg_stateproc_Content, undefined,
{obj, #{
{str, <<"aux_state">>} =>
{bin,
<<131, 116, 0, 0, 0, 2, 100, 0, 20, 112, 97, 114, 116, 121, 95, 114, 101, 118, 105,
115, 105, 111, 110, 95, 105, 110, 100, 101, 120, 116, 0, 0, 0, 0, 100, 0, 14,
115, 110, 97, 112, 115, 104, 111, 116, 95, 105, 110, 100, 101, 120, 106>>},
{str, <<"ct">>} => {str, <<"application/x-erlang-binary">>}
}}},
undefined,
{obj, #{
{str, <<"aux_state">>} =>
{bin,
<<131, 116, 0, 0, 0, 2, 100, 0, 20, 112, 97, 114, 116, 121, 95, 114, 101, 118, 105, 115,
105, 111, 110, 95, 105, 110, 100, 101, 120, 116, 0, 0, 0, 0, 100, 0, 14, 115, 110,
97, 112, 115, 104, 111, 116, 95, 105, 110, 100, 101, 120, 106>>},
{str, <<"ct">>} =>
{str, <<"application/x-erlang-binary">>}
}}}}
},
deadline => {{{2019, 8, 13}, {7, 52, 41}}, 105},
execution_start_time => 1565682731109,
function => 'ProcessCall',
metadata => #{
<<"user-identity.id">> => <<"1CSHThTEJ84">>,
<<"user-identity.realm">> => <<"external">>
},
role => server,
service => 'Processor',
service_schema => {mg_proto_state_processing_thrift, 'Processor'},
type => call
},
RpcID = #{
span_id => <<"1012689088534282240">>,
trace_id => <<"1012689088739803136">>,
parent_id => <<"1012689108264288256">>
},
{Meta, RpcID}.
-spec iolib_formatter({input, _State}) -> input().
iolib_formatter({input, _}) ->
input().
-spec thrift_formatter({input, _State}) -> input().
thrift_formatter({input, _}) ->
input().
-spec bench_iolib_formatter(input(), _State) -> term().
bench_iolib_formatter({Meta, RpcID}, _) ->
format_msg(format_event_iolib(Meta, RpcID)).
format_event_iolib(#{service := Service, function := Function, args := Args}, _RpcID) ->
{"calling ~0p:~0p(~0tp)", [Service, Function, Args]}.
-spec bench_thrift_formatter(input(), _State) -> term().
bench_thrift_formatter({Meta, RpcID}, _) ->
format_msg(woody_event_handler:format_event('call service', Meta, RpcID)).
format_msg({Format, Params}) ->
io_lib:format(Format, Params).