File 1222-erts-Cleanup-trace_call_time_SUITE-bif.patch of Package erlang
From ab4b26d562c6cb7b711cd3e82f551f49899f253e Mon Sep 17 00:00:00 2001
From: Sverker Eriksson <sverker@erlang.org>
Date: Wed, 8 Mar 2023 15:23:59 +0100
Subject: [PATCH 2/2] erts: Cleanup trace_call_time_SUITE:bif
and get some more results printed for trouble shooting.
---
erts/emulator/test/trace_call_time_SUITE.erl | 59 ++++++++++++++------
1 file changed, 42 insertions(+), 17 deletions(-)
diff --git a/erts/emulator/test/trace_call_time_SUITE.erl b/erts/emulator/test/trace_call_time_SUITE.erl
index 124f0e2283..26687129bb 100644
--- a/erts/emulator/test/trace_call_time_SUITE.erl
+++ b/erts/emulator/test/trace_call_time_SUITE.erl
@@ -412,11 +412,21 @@ bif(Config) when is_list(Config) ->
Pid = setup(),
{L, Tot1} = execute(Pid, fun() -> with_bif(M) end),
- {call_time,[{Pid,_,S,Us}]} = erlang:trace_info({?MODULE,with_bif,1}, call_time),
- T1 = Tot1 - (S*1000000 + Us),
-
- ok = check_trace_info({erlang, binary_to_term, 1}, [{Pid, M - 1, 0, 0}], T1/2),
- ok = check_trace_info({erlang, term_to_binary, 1}, [{Pid, M - 1, 0, 0}], T1/2),
+ {call_time,[{Pid,_,S,Us}]}=WB = erlang:trace_info({?MODULE,with_bif,1}, call_time),
+ T1 = Tot1 - (S*1000_000 + Us),
+
+ B2T = erlang:trace_info({erlang, binary_to_term, 1}, call_time),
+ T2B = erlang:trace_info({erlang, term_to_binary, 1}, call_time),
+ io:format("with_bif = ~p\n", [WB]),
+ io:format("binary_to_term = ~p\n", [B2T]),
+ io:format("term_to_binary = ~p\n", [T2B]),
+ Sum = us(WB) + us(B2T) + us(T2B),
+ io:format("Sum = ~p us\n", [Sum]),
+ io:format("Tot1 = ~p us Diff = ~p us\n", [Tot1, Tot1-Sum]),
+ ok = check_trace_info_ret({erlang, binary_to_term, 1}, [{Pid, M-1, 0, 0}],
+ T1/2, B2T),
+ ok = check_trace_info_ret({erlang, term_to_binary, 1}, [{Pid, M-1, 0, 0}],
+ T1/2, T2B),
% disable term2binary
@@ -432,6 +442,9 @@ bif(Config) when is_list(Config) ->
Pid ! quit,
ok.
+us({call_time,[{_,_,S,Us}]}) ->
+ S*1000_000 + Us.
+
%% %%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
%% Tests tracing of nifs
@@ -712,23 +725,35 @@ seq_r(Start, Stop, Succ, R) ->
seq_r(Succ(Start), Stop, Succ, [Start | R]).
% Check call time tracing data and print mismatches
-check_trace_info(Mfa, [{Pid, ExpectedC,_,_}] = Expect, Time) ->
- {call_time,[{Pid,C,S,Us}]} = erlang:trace_info(Mfa, call_time),
+check_trace_info(Mfa, Expect, Time) ->
+ check_trace_info_ret(Mfa, Expect, Time, erlang:trace_info(Mfa, call_time)).
+
+check_trace_info_ret(Mfa, [{Pid, ExpectedC,_,_}] = Expect, Time, TraceInfo) ->
+ {call_time,[{Pid,Cnt,S,Us}]} = TraceInfo,
+
{Mod, Name, Arity} = Mfa,
IsBuiltin = erlang:is_builtin(Mod, Name, Arity),
- if
+ ok = if
%% Call count on BIFs may exceed number of calls as they often trap to
%% themselves.
- IsBuiltin, C >= ExpectedC, S >= 0, Us >= 0,
- abs(1 - Time/(S*1000000 + Us)) < ?R_ERROR;
- abs(Time - S*1000000 - Us) < ?US_ERROR ->
+ IsBuiltin, Cnt >= ExpectedC ->
ok;
- not IsBuiltin, C =:= ExpectedC, S >= 0, Us >= 0,
- abs(1 - Time/(S*1000000 + Us)) < ?R_ERROR;
- abs(Time - S*1000000 - Us) < ?US_ERROR ->
+ not IsBuiltin, Cnt =:= ExpectedC ->
+ ok;
+ true ->
+ io:format("Expected ~p -> {call_time, ~p}~n"
+ " - got call count ~w~p",
+ [Mfa, Expect, Cnt]),
+ count_error
+ end,
+
+ true = (S >= 0),
+ true = (Us >= 0),
+ Sum = S*1000_000 + Us,
+ if
+ abs(1 - Time/Sum) < ?R_ERROR; abs(Time - Sum) < ?US_ERROR ->
ok;
true ->
- Sum = S*1000000 + Us,
io:format("Expected ~p -> {call_time, ~p (Time ~p us)}~n - got ~w "
"s. ~w us. = ~w us. - ~w -> delta ~w (ratio ~.2f, "
"should be 1.0)~n",
@@ -736,8 +761,8 @@ check_trace_info(Mfa, [{Pid, ExpectedC,_,_}] = Expect, Time) ->
S, Us, Sum, Time, Sum - Time, Time/Sum]),
time_error
end;
-check_trace_info(Mfa, Expect, _) ->
- case erlang:trace_info(Mfa, call_time) of
+check_trace_info_ret(Mfa, Expect, _, TraceInfo) ->
+ case TraceInfo of
{call_time, Expect} ->
ok;
Other ->
--
2.35.3