path: root/lib/stdlib/test/timer_SUITE.erl

%%
%% %CopyrightBegin%
%%
%% Copyright Ericsson AB 1996-2010. All Rights Reserved.
%%
%% The contents of this file are subject to the Erlang Public License,
%% Version 1.1, (the "License"); you may not use this file except in
%% compliance with the License. You should have received a copy of the
%% Erlang Public License along with this software. If not, it can be
%% retrieved online at http://www.erlang.org/.
%%
%% Software distributed under the License is distributed on an "AS IS"
%% basis, WITHOUT WARRANTY OF ANY KIND, either express or implied. See
%% the License for the specific language governing rights and limitations
%% under the License.
%%
%% %CopyrightEnd%
%%
-module(timer_SUITE).

-export([all/0, suite/0,groups/0,init_per_suite/1, end_per_suite/1, init_per_group/2,end_per_group/2]).
-export([do_big_test/1]).
-export([big_test/1, collect/3, i_t/3, a_t/2]).
-export([do_nrev/1, internal_watchdog/2]).

-include_lib("test_server/include/test_server.hrl").

%% Test suite for timer module. This is a really nasty test it runs a
%% lot of timeouts and then checks in the end if any of them was
%% trigggered too early or if any late timeouts was much too
%% late. What should be added is more testing of the interface
%% functions I guess. But I don't have time for that now.
%%
%% Expect it to run for at least 5-10 minutes!
%% Except for VxWorks of course, where a couple of hours is more apropriate...


%% The main test case in this module is "do_big_test", which
%% orders a large number of timeouts and measures how
%% exact the timeouts arrives. To simulate a system under load there is
%% also a number of other concurrent processes running "nrev" at the same
%% time. The result is analyzed afterwards by trying to check if the
%% measured values are reasonable. It is hard to determine what is
%% reasonable on different machines therefore the test can sometimes
%% fail, even though the timer module is ok. I have checked against
%% previous versions of the timer module (which contained bugs) and it
%% seems it fails every time when running the buggy timer modules.
%% 
%% The solution is to rewrite the test suite. Possible strategies for a
%% rewrite: smarter math on the measuring data, test cases with varying
%% amount of load. The test suite should also include tests that test the
%% interface of the timer module.

suite() -> [{suite_callbacks,[ts_install_scb]}].

all() -> 
[do_big_test].

groups() -> 
    [].

init_per_suite(Config) ->
    Config.

end_per_suite(_Config) ->
    ok.

init_per_group(_GroupName, Config) ->
	Config.

end_per_group(_GroupName, Config) ->
	Config.


%% ------------------------------------------------------- %%

do_big_test(TConfig) when is_list(TConfig) ->
    Dog = ?t:timetrap(?t:minutes(20)),
    Save = process_flag(trap_exit, true),
    Result = case os:type() of
		 vxworks ->
		     big_test(10);
		 _ ->
		     big_test(200)
	     end,
    process_flag(trap_exit, Save),
    ?t:timetrap_cancel(Dog),
    report_result(Result).

report_result(ok) -> ok;
report_result(Error) -> ?line test_server:fail(Error).

%% ------------------------------------------------------- %%

big_test(N) ->
    C = start_collect(),
    system_time(), system_time(), system_time(),
    A1 = element(2, erlang:now()),
    A2 = A1 * 3,
    A3 = element(3, erlang:now()),
    random:seed(A1, A2, A3),
    random:uniform(100),random:uniform(100),random:uniform(100),

    big_loop(C, N, []),

    %%C ! print_report,
    C ! {self(), get_report},
    Report = receive
		 {report, R} ->
		     R
	     end,
    C ! stop,
    receive
	{'EXIT', C, normal} ->
	    ok
    end,
    print_report(Report),
    Result = analyze_report(Report),
    %%io:format("big_test is done: ~w~n", [Result]),
    Result.
    
big_loop(_C, 0, []) ->
    %%io:format("All processes are done!~n", []),
    ok;
big_loop(C, 0, Pids) ->
    %%ok = io:format("Loop done, ~w processes remaining~n", [length(Pids)]),
    %% wait for remaining processes
    receive
	{'EXIT', Pid, done} ->
	    big_loop(C, 0, lists:delete(Pid, Pids));
	{'EXIT', Pid, Error} ->
	    ?line ok = io:format("XXX Pid ~w died with reason ~p~n",
				 [Pid, Error]),
	    big_loop(C, 0, lists:delete(Pid, Pids))
    end;
big_loop(C, N, Pids) ->
    %% First reap any processes that are done.
    receive
	{'EXIT', Pid, done} ->
	    big_loop(C, N, lists:delete(Pid, Pids));
	{'EXIT', Pid, Error} ->
	    ?line ok =io:format("XXX Internal error: Pid ~w died, reason ~p~n",
				 [Pid, Error]),
	    big_loop(C, N, lists:delete(Pid, Pids))
    after 0 ->

	    %% maybe start an interval timer test
	    Pids1 = maybe_start_i_test(Pids, C, random:uniform(4)),
	    
	    %% start 1-4 "after" tests
	    Pids2 = start_after_test(Pids1, C, random:uniform(4)),
	    %%Pids2=Pids1,

	    %% wait a little while
	    timer:sleep(random:uniform(200)*10),

	    %% spawn zero, one or two nrev to get some load ;-/
	    Pids3 = start_nrev(Pids2, random:uniform(100)),
	    
	    big_loop(C, N-1, Pids3)
    end.


start_nrev(Pids, N) when N < 25 ->
    Pids;
start_nrev(Pids, N) when N < 75 ->
    [spawn_link(timer_SUITE, do_nrev, [1])|Pids];
start_nrev(Pids, _N) ->
    NrevPid1 = spawn_link(timer_SUITE, do_nrev, [random:uniform(1000)*10]),
    NrevPid2 = spawn_link(timer_SUITE, do_nrev, [1]),
    [NrevPid1,NrevPid2|Pids].
    

start_after_test(Pids, C, 1) ->
    TO1 = random:uniform(100)*100,
    [s_a_t(C, TO1)|Pids];
start_after_test(Pids, C, 2) ->
    TO1 = random:uniform(100)*100,
    TO2 = TO1 div random:uniform(3) + 200,
    [s_a_t(C, TO1),s_a_t(C, TO2)|Pids];
start_after_test(Pids, C, N) ->
    TO1 = random:uniform(100)*100,
    start_after_test([s_a_t(C, TO1)|Pids], C, N-1).

s_a_t(C, TimeOut) ->
    spawn_link(timer_SUITE, a_t, [C, TimeOut]).

a_t(C, TimeOut) ->
    start_watchdog(self(), TimeOut),
    Start = system_time(),
    timer:send_after(TimeOut, self(), now),
    receive
	now ->
	    Stop = system_time(),
	    report(C, Start,Stop,TimeOut),
	    exit(done);
	watchdog ->
	    Stop = system_time(),
	    report(C, Start,Stop,TimeOut),
	    ?line ok = io:format("Internal watchdog timeout (a), not good!!~n",
				 []),
	    exit(done)
    end.


maybe_start_i_test(Pids, C, 1) ->
    %% ok do it
    TOI = random:uniform(100)*100,
    CountI = random:uniform(10) + 3,                      % at least 4 times
    [spawn_link(timer_SUITE, i_t, [C, TOI, CountI])|Pids];
maybe_start_i_test(Pids, _C, _) ->
    Pids.

i_t(C, TimeOut, Times) ->
    start_watchdog(self(), TimeOut*Times),
    Start = system_time(),
    {ok, Ref} = timer:send_interval(TimeOut, interval),
    i_wait(Start, Start, 1, TimeOut, Times, Ref, C).

i_wait(Start, Prev, Times, TimeOut, Times, Ref, C) ->
    receive
	interval ->
	    Now = system_time(),
	    report_interval(C, {final,Times}, Start, Prev, Now, TimeOut),
	    timer:cancel(Ref),
	    exit(done);
	watchdog ->
	    Now = system_time(),
	    report_interval(C, {final,Times}, Start, Prev, Now, TimeOut),
	    timer:cancel(Ref),
	    ?line ok = io:format("Internal watchdog timeout (i), not good!!~n",
				 []),
	    exit(done)
    end;
i_wait(Start, Prev, Count, TimeOut, Times, Ref, C) ->
    receive
	interval ->
	    Now = system_time(),
	    report_interval(C, Count, Start, Prev, Now, TimeOut),
	    i_wait(Start, Now, Count+1, TimeOut, Times, Ref, C);
	watchdog ->
	    Now = system_time(),
	    report_interval(C, {final,Count}, Start, Prev, Now, TimeOut),
	    ?line ok = io:format("Internal watchdog timeout (j), not good!!~n",
				 []),
	    exit(done)
    end.

report(C, Start, Stop, Time) ->
    C ! {a_sample, Start, Stop, Time}.
report_interval(C, Count, Start, Prev, Now, TimeOut) ->
    C ! {i_sample, Count, Start, Prev, Now, TimeOut}.

%% ------------------------------------------------------- %%

%% internal watchdog
start_watchdog(Pid, TimeOut) ->
    spawn_link(timer_SUITE, internal_watchdog, [Pid, 3*TimeOut+1000]).

internal_watchdog(Pid, TimeOut) ->
    receive
    after TimeOut ->
	    Pid ! watchdog,
	    exit(normal)
    end.

%% ------------------------------------------------------- %%

-record(stat, {n=0,max=0,min=min,avg=0}).

start_collect() ->
    spawn_link(timer_SUITE, collect, [0,{0,new_update(),new_update()},[]]).

collect(N, {E,A,B}, I) ->
    receive
	{a_sample, Start, Stop, Time} when Stop - Start > Time ->
	    collect(N+1, {E,update(Stop-Start-Time,A),B}, I);
	{a_sample, Start, Stop, Time} when Stop - Start < Time ->
	    collect(N+1, {E,A,update(Time-Stop+Start,B)}, I);
	{a_sample, _Start, _Stop, _Time} ->
	    collect(N+1, {E+1,A,B}, I);
	{i_sample, {final,Count}, Start, Prev, Now, TimeOut} ->
	    IntervDiff = Now - Prev - TimeOut,
	    Drift = Now - (Count*TimeOut) - Start,
	    collect(N, {E,A,B}, [{{final,Count},IntervDiff,Drift}|I]);
	{i_sample, Count, Start, Prev, Now, TimeOut} ->
	    IntervDiff = Now - Prev - TimeOut,
	    Drift = Now - (Count*TimeOut) - Start,
	    collect(N, {E,A,B}, [{Count,IntervDiff,Drift}|I]);
	print_report ->
	    print_report({E,A,B,I}),
	    collect(N,{E,A,B}, I);
	{Pid, get_report} when is_pid(Pid) ->
	    Pid ! {report, {E, A, B, I}},
	    collect(N,{E,A,B}, I);
	reset ->
	    collect(0, {0,new_update(),new_update()}, []);
	stop ->
	    exit(normal);
	_Other ->
	    collect(N, {E,A,B}, I)
    end.

new_update() -> #stat{}.
update(New, Stat) when New > Stat#stat.max ->
    Stat#stat{n=Stat#stat.n + 1, max=New, avg=(New+Stat#stat.avg) div 2};
update(New, Stat) when New < Stat#stat.min ->
    Stat#stat{n=Stat#stat.n + 1, min=New, avg=(New+Stat#stat.avg) div 2};
update(New, Stat) ->
    Stat#stat{n=Stat#stat.n + 1, avg=(New+Stat#stat.avg) div 2}.

%update(New, {N,Max,Min,Avg}) when New>Max ->
%    {N+1,New,Min,(New+Avg) div 2};
%update(New, {N,Max,Min,Avg}) when New<Min ->
%    {N+1,Max,New,(New+Avg) div 2};
%update(New, {N,Max,Min,Avg}) ->
%    {N+1,Max,Min,(New+Avg) div 2}.

print_report({E,LateS,EarlyS,I}) ->
    Early = EarlyS#stat.n, Late = LateS#stat.n,
    Total = E + Early + Late,
    io:format("~nOn total of ~w timeouts, there were ~w exact, ~w "
	      "late and ~w early.~n", [Total, E, Late, Early]),
    io:format("Late stats (N,Max,Min,Avg): ~w~nEarly stats: ~w~n",
	      [LateS, EarlyS]),
    IntervS = collect_interval_final_stats(I),
    io:format("Interval stats (Max,Min,Avg): ~w~n", [IntervS]),
    ok.

collect_interval_final_stats(I) ->
    collect_interval_final_stats(I, 0, min, 0).
collect_interval_final_stats([], Max, Min, Avg) ->
    {Max, Min, Avg};
collect_interval_final_stats([{{final,_Count},_,Dev}|T], Max, Min, Avg) ->
    NMax = if Dev>Max -> Dev; true -> Max end,
    NMin = if Dev<Min -> Dev; true -> Min end,
    collect_interval_final_stats(T, NMax, NMin, (Dev+Avg) div 2);
collect_interval_final_stats([_|T], Max, Min, Avg) ->
    collect_interval_final_stats(T, Max, Min, Avg).

analyze_report({E,LateS,EarlyS,I}) ->
    Early = EarlyS#stat.n, Late = LateS#stat.n,
    IntervS = collect_interval_final_stats(I),
    Res1 = min_and_early_check(E, Early, Late, element(2,IntervS)),
    Res2 = abnormal_max_check(LateS#stat.max, element(1,IntervS)),
    res_combine(ok, [Res1, Res2]).

-define(ok_i_min, -100).
-define(ok_max, 8000).
-define(ok_i_max, 4000).

%% ok as long as Early == 0 and IntervMin >= ok_interv_min
min_and_early_check(_Exact, 0, _Late, IntervMin) when IntervMin >= ?ok_i_min ->
    ok;
min_and_early_check(_Exact, Early, _Late, IntervMin) when IntervMin >= ?ok_i_min ->
    {error, {early_timeouts, Early}};
min_and_early_check(_Exact, 0, _Late, _IntervMin) ->
    {error, early_interval_timeout};
min_and_early_check(_Exact, Early, _Late, _IntervMin) ->
    {error, [{early_timeouts, Early},{error, early_interval_timeout}]}.

abnormal_max_check(LateMax, IntMax) when LateMax < ?ok_max,
                                         IntMax < ?ok_i_max ->
    ok;
abnormal_max_check(LateMax, IntMax) when IntMax < ?ok_i_max ->
    {error, {big_late_max, LateMax}};
abnormal_max_check(LateMax, IntMax) when LateMax < ?ok_max ->
    {error, {big_interval_max, IntMax}};
abnormal_max_check(LateMax, IntMax) ->
    {error, [{big_late_max, LateMax},{big_interval_max, IntMax}]}.

res_combine(Res, []) ->
    Res;
res_combine(Res, [ok|T]) ->
    res_combine(Res, T);
res_combine(ok, [{error,What}|T]) ->
    res_combine({error,What}, T);
res_combine({error,Es}, [{error,E}|T]) ->
    res_combine({error,lists:flatten([E,Es])}, T).


system_time() ->
    %%element(1, statistics(wall_clock)).
    {M,S,U} = erlang:now(),
    1000000000 * M + 1000 * S + (U div 1000).

%% ------------------------------------------------------- %%

do_nrev(Sleep) ->
    timer:sleep(Sleep),
    test(1000,"abcdefghijklmnopqrstuvxyz1234"),
    exit(done).

test(0,_) ->
    true;
test(N,L) ->
    nrev(L),
    test(N - 1, L).

nrev([]) ->
    [];
nrev([H|T]) ->
    append(nrev(T), [H]).
    
append([H|T],Z) ->
	[H|append(T,Z)];
append([],X) ->
	X.

%% ------------------------------------------------------- %%