timing_cth.erl

%%% Time all the things!
%%%
%%% To use this hook, on the command line:
%%%     ct_run -suite example_SUITE -pa . -ct_hooks timing_cth
%%%
%%% Note `-pa .`: the hook beam file must be in the code path when installing.
-module(timing_cth).

%% Mandatory Callbacks
-export([init/2]).

%% Optional Callbacks
-export([id/1]).

-export([pre_init_per_suite/3]).
-export([post_init_per_suite/4]).
-export([pre_end_per_suite/3]).
-export([post_end_per_suite/4]).

-export([pre_init_per_testcase/4]).
-export([post_init_per_testcase/5]).
-export([pre_end_per_testcase/4]).
-export([post_end_per_testcase/5]).

-export([terminate/1]).

%% A timer record, used for timing the execution of a task.
-record(timer, {
    last_start = 0 :: non_neg_integer(),
    duration = 0 :: non_neg_integer()
}).

new_timer(AtTime) ->
    #timer{last_start = AtTime}.

pause(#timer{last_start = LastStart, duration = Duration} = Timer, AtTime) ->
    Timer#timer{duration = Duration + AtTime - LastStart}.

resume(Timer, AtTime) ->
    Timer#timer{last_start = AtTime}.

%% This hook state is threaded through all the callbacks.
%% It collects time statistics for the test run. The following
%% kinds of tasks are all timed separately:
%% - suite init hook
%% - suite end hook
%% - group init hook
%% - group end hook
%% - test case init hook
%% - test case end hook
%% - test case execution
%%
%% For each kind of task, the time is accumulated in the state.
%% If there are multiple suites, groups or test cases, the time
%% is accumulated for them together in each kind.
%%
%% The state is also used to count the number of suites, groups and test cases.
-record(state, {
    filename :: string(),
    suites = 0 :: non_neg_integer(),
    groups = 0 :: non_neg_integer(),
    cases = 0 :: non_neg_integer(),
    fails = 0 :: non_neg_integer(),
    skips = 0 :: non_neg_integer(),
    suite_init_timer = #timer{} :: #timer{},
    suite_end_timer = #timer{} :: #timer{},
    group_init_timer = #timer{} :: #timer{},
    group_end_timer = #timer{} :: #timer{},
    testcase_init_timer = #timer{} :: #timer{},
    testcase_end_timer = #timer{} :: #timer{},
    testcase_timer = #timer{} :: #timer{}
}).

%% Return the current time in milliseconds.
get_time() ->
    erlang:monotonic_time(millisecond).

%% Return a unique id for this CTH.
%% Using the filename means the hook can be used with different
%% log files to separate timing data within the same test run.
%% See Installing a CTH for more information.
id(Opts) ->
    %% the path is relative to the test run directory
    proplists:get_value(filename, Opts, "timing_cth.log").

%% Always called before any other callback function. Use this to initiate
%% any common state.
init(Id, _Opts) ->
    {ok, #state{filename = Id}}.

pre_init_per_suite(Suite, Config, State) ->
    Now = get_time(),
    Timer = resume(State#state.suite_init_timer, Now),
    NewState = State#state{suite_init_timer = Timer},
    {Config, NewState}.

post_init_per_suite(Suite, Config, Return, State) ->
    Now = get_time(),
    Timer = pause(State#state.suite_init_timer, Now),
    NewState = State#state{suite_init_timer = Timer},
    {Return, NewState}.

pre_end_per_suite(Suite, Config, State) ->
    Now = get_time(),
    Timer = resume(State#state.suite_end_timer, Now),
    NewState = State#state{suite_end_timer = Timer},
    {Config, NewState}.

post_end_per_suite(Suite, Config, Return, State) ->
    Now = get_time(),
    Timer = pause(State#state.suite_end_timer, Now),
    NewState = State#state{
        suite_end_timer = Timer,
        suites = State#state.suites + 1
    },
    {Return, NewState}.

pre_init_per_group(Suite, Group, Config, State) ->
    Now = get_time(),
    Timer = resume(State#state.group_init_timer, Now),
    NewState = State#state{group_init_timer = Timer},
    {Config, NewState}.

post_init_per_group(Suite, Group, Config, Return, State) ->
    Now = get_time(),
    Timer = pause(State#state.group_init_timer, Now),
    NewState = State#state{group_init_timer = Timer},
    {Return, NewState}.

pre_end_per_group(Suite, Group, Config, State) ->
    Now = get_time(),
    Timer = resume(State#state.group_end_timer, Now),
    NewState = State#state{group_end_timer = Timer},
    {Config, NewState}.

post_end_per_group(Suite, Group, Config, Return, State) ->
    Now = get_time(),
    Timer = pause(State#state.group_end_timer, Now),
    NewState = State#state{
        group_end_timer = Timer,
        groups = State#state.groups + 1
    },
    {Return, NewState}.

pre_init_per_testcase(Suite, TC, Config, State) ->
    Now = get_time(),
    Timer = resume(State#state.testcase_init_timer, Now),
    NewState = State#state{testcase_init_timer = Timer},
    {Config, NewState}.

%% Called after each init_per_testcase (immediately before the test case).
post_init_per_testcase(Suite, TC, Config, Return, State) ->
    Now = get_time(),
    InitTimer = pause(State#state.testcase_init_timer, Now),
    TestCaseTimer = resume(State#state.testcase_timer, Now),
    NewState = State#state{
        testcase_init_timer = InitTimer,
        testcase_timer = TestCaseTimer
    },
    {Return, NewState}.

%% Called before each end_per_testcase (immediately after the test case).
pre_end_per_testcase(Suite, TC, Config, State) ->
    Now = get_time(),
    TestCaseTimer = pause(State#state.testcase_timer, Now),
    EndTimer = resume(State#state.testcase_end_timer, Now),
    NewState = State#state{
        testcase_timer = TestCaseTimer,
        testcase_end_timer = EndTimer
    },
    {Config, NewState}.

post_end_per_testcase(Suite, TC, Config, Return, State) ->
    Now = get_time(),
    Timer = pause(State#state.testcase_end_timer, Now),
    NewState = State#state{
        testcase_end_timer = Timer,
        cases = State#state.cases + 1
    },
    {Return, NewState}.

%% Called after post_init_per_suite, post_end_per_suite, post_init_per_group,
%% post_end_per_group and post_end_per_testcase if the suite, group or test case failed.
on_tc_fail(Suite, TC, Reason, State) ->
    State#state{fails = State#state.fails + 1}.

%% Called when a test case is skipped by either user action
%% or due to an init function failing.
on_tc_skip(Suite, TC, Reason, State) ->
    State#state{skips = State#state.skips + 1}.

%% Called when the scope of the CTH is done
terminate(State) ->
    FileName = State#state.filename,
    File = file:open(FileName, [write, append]),
    %% print CSV
    io:format(File, "Suites,Groups,Cases,Fails,Skips,Init,End,Group,Test,Total~n"),
    io:format(File, "~b,~b,~b,~b,~b,~b,~b,~b,~b,~b~n",
              [State#state.suites,
               State#state.groups,
               State#state.cases,
               State#state.fails,
               State#state.skips,
               State#state.suite_init_timer#timer.duration,
               State#state.suite_end_timer#timer.duration,
               State#state.group_init_timer#timer.duration + State#state.group_end_timer#timer.duration,
               State#state.testcase_init_timer#timer.duration + State#state.testcase_end_timer#timer.duration,
               State#state.testcase_timer#timer.duration]
    ),
    file:close(File).