#+TITLE: Snabbkaffe
[[https://travis-ci.org/klarna/snabbkaffe.svg?branch=master]]
* Introduction
This library provides functions for simple trace-based testing.
It works like this:
1) Programmer manually instruments the code with trace points
2) Testcases are split in two parts:
- *Run stage* where the program runs and emits event trace
- *Check stage* where trace is collected and validated against the
spec(s)
3) Trace points become ordinary log messages in the release build
This approach can be used in a component test involving an ensemble of
interacting processes. It has a few nice properties:
+ Checks can be separated from the program execution
+ Checks are independent from each other and fully composable
+ Trace contains complete history of the process execution, thus
making certain types of concurrency bugs, like livelocks, easier to
detect
* Usage
** Instrumenting the code
Code instrumentation is done manually by inserting =tp= macros at the
points of interest:
#+BEGIN_SRC erlang
?tp(my_server_state_change, #{old_state => foo, next_state => bar})
#+END_SRC
The above line of code, when compiled in test mode, emits an event of
/kind/ =my_server_state_change=, with some additional data specified
in the second argument. Any event has a /kind/, which is an atom
identifying type of the event. The second argument must be a map, and
it can contain any data.
In the release build this macro will become a [[https://github.com/tolbrino/hut/][hut]] log message with
=debug= level. One can as well tune trace point log level:
#+BEGIN_SRC erlang
?tp(notice, my_server_state_change, #{old_state => foo, next_state => bar})
#+END_SRC
** Collecting trace
Trace collector process must be started before running the test. Full
workflow looks like this:
#+BEGIN_SRC erlang
ok = snabbkaffe:start_trace(),
Return = RunYourCode(),
Trace = snabbkaffe:collect_trace(Timeout),
snabbkaffe:stop(),
RunCheck1(Return, Trace),
RunCheck2(Return, Trace),
...
RunCheckN(Return, Trace).
#+END_SRC
Note that =collect_trace= function is destructive: it cleans event
buffer of the collector process. Its argument =Timeout= specifies how
long the call will wait after the last event is received. Setting this
parameter to a non-zero value is useful when /run stage/ starts some
asynchronous tasks. By default =Timeout= is 0.
** Checking traces
Trace is just a list of maps. Any standard function can work with
it. Nonetheless, /Snabbkaffe/ comes with a few useful macros for trace
analysis.
Select events of certain kind:
#+BEGIN_SRC erlang
?of_kind(foo, Trace)
#+END_SRC
Extract values of a certain event field(s) to a list:
#+BEGIN_SRC erlang
[1, 2] = ?projection(foo, [#{foo => 1, quux => 1}, #{foo => 2}]),
[{1, 1}, {2, 2}] = ?projection([foo, bar], [#{foo => 1, bar => 1}, #{foo => 2, bar => 2}])
#+END_SRC
Check that events occur in certain order, and throw an exception
otherwise:
#+BEGIN_SRC erlang
?causality( #{kind := foo, foo := _A}
, #{kind := bar, foo := _A}
, Trace
)
#+END_SRC
First argument of =?causality= macro matches an event that is called
the /cause/, and the second one matches so called /effect/. The above
example checks events of kind =bar= occur only after corresponding
events of kind =foo=.
This macro can be extended with a guard as well. Here guard checks
that two events actually make up a pair:
#+BEGIN_SRC erlang
?causality( #{kind := foo, foo := _A}
, #{kind := bar, foo := _B}
, _A + 1 =:= _B
, Trace
)
#+END_SRC
There is a version of the above macro that checks that all cause have
an effect:
#+BEGIN_SRC erlang
?strict_causality( #{kind := foo, foo := _A}
, #{kind := bar, foo := _A}
, Trace
)
#+END_SRC
Otherwise it works just like =?causality=.
Both =?causality= and =?strict_causality= are actually based on a more
powerful =?find_pairs= macro that is invoked like this:
#+BEGIN_SRC erlang
?find_pairs( Strict
, MatchCause
, MatchEffect
[, Guard]
, Trace
)
#+END_SRC
where =Strict= is a boolean that determines whever events that matched
as =Effect= may preceed their cause.
It returns a list of tuples of type =snabbkaffe:maybe_pair/0= that is
defined like that:
#+BEGIN_SRC erlang
-type maybe_pair() :: {pair, event(), event()}
| {singleton, event()}.
#+END_SRC
** Gathering it all together
=?check_trace= is a convenience wrapper that starts the trace
collector process, executes /run stage/, collects traces and then
executes /check stage/:
#+BEGIN_SRC erlang
?check_trace(begin
RunStage
end,
fun(ReturnValue, Trace) ->
CheckStage
end).
#+END_SRC
There is an extended version of this macro that takes additional
configuration as the first argument:
#+BEGIN_SRC erlang
?check_trace(#{timeout => Timeout, bucket => Bucket},
begin
RunStage
end,
fun(ReturnValue, Trace) ->
CheckStage
end).
#+END_SRC
or:
#+BEGIN_SRC erlang
?check_trace(Bucket,
begin
RunStage
end,
fun(ReturnValue, Trace) ->
CheckStage
end).
#+END_SRC
=Bucket= is a parameter used for benchmarking, more on that later.
** Blocking execution of testcase until certain event is emitted
Even though philosophy of this library lies in separation of run and
verify stages, sometimes the former needs to be somewhat aware of the
events. For example, the testcase may need to wait for asynchronous
initialization of some resource.
In this case =?block_until= macro should be used. It allows the
testcase to peek into the trace. Example usage:
#+BEGIN_SRC erlang
?block_until(#{kind := Kind}, Timeout, BackInTime)
#+END_SRC
Note: it's tempting to use this macro to check the result of some
asynchronous action, like this:
#+BEGIN_SRC erlang
{ok, Pid} = foo:async_init(),
{ok, Event} = ?block_until(#{kind := foo_init, pid := Pid}),
do_stuff(Pid)
#+END_SRC
However it's not a good idea, because the event can be emitted before
=?block_until= has a chance to run. Use the following macro to avoid
this race condition:
#+BEGIN_SRC
{{ok, Pid}, {ok, Event}} = ?wait_async_action( foo:async_init()
, #{kind := foo_init, pid := Pid}
),
do_stuff(Pid)
#+END_SRC
** PropER integration
There are two useful macros for running /snabbkaffe/ together with [[https://proper-testing.github.io/][propER]]:
#+BEGIN_SRC erlang
?run_prop(Config, PROP)
#+END_SRC
where =PROP= is a proper spec that looks something like this:
#+BEGIN_SRC erlang
?FORALL({Ret, L}, {term(), list()},
?check_trace(
begin
RunStage
end,
fun(Return, Trace) ->
CheckStage
end))
#+END_SRC
There is another macro for the most common type of proper checks where
property is a simple =?FORALL= clause (like in the above example).
#+BEGIN_SRC erlang
?forall_trace({Ret, L}, {term(), list()},
begin
RunStage
end,
fun(Return, Trace) ->
CheckStage
end)
#+END_SRC
It combines =?FORALL= and =?run_prop=.
* Benchmarking
/Snabbkaffe/ automatically adds timestamps to the events, which makes
it a very unscientific benchmarking library.
There is a family of functions for reporting metric data.
Report a scalar metric called =my_metric1=:
#+BEGIN_SRC erlang
snabbkaffe:push_stat(my_metric1, 42),
snabbkaffe:push_stats(my_metric1, [42, 43, 42]),
%% Or even:
snabbkaffe:push_stats(my_metric1, [{pair, Event1, Event2}, {pair, Event3, Event4}, ...]),
#+END_SRC
Sometimes it is entertaining to see how metric value depends on the
size of the input data:
#+BEGIN_SRC erlang
snabbkaffe:push_stat(my_metric1, SizeOfData, 42),
snabbkaffe:push_stats(my_metric1, SizeOfData, [42, 43, 42])
#+END_SRC
Metrics can be reported by calling =snabbkaffe:analyze_statistics/0=
function that prints statistics for each reported metric, like in the
above example:
#+BEGIN_EXAMPLE
-------------------------------
foo_bar statistics:
[{min,9.999999999999999e-6},
{max,9.999999999999999e-6},
{arithmetic_mean,1.000000000000002e-5},
{geometric_mean,1.0000000000000123e-5},
{harmonic_mean,9.999999999999997e-6},
{median,9.999999999999999e-6},
{variance,4.174340734454146e-40},
{standard_deviation,2.0431203426264804e-20},
{skewness,-0.9850375627355535},
{kurtosis,-2.0199000000000003},
{percentile,[{50,9.999999999999999e-6},
{75,9.999999999999999e-6},
{90,9.999999999999999e-6},
{95,9.999999999999999e-6},
{99,9.999999999999999e-6},
{999,9.999999999999999e-6}]},
{histogram,[{9.999999999999999e-6,100}]},
{n,100}]
Statisitics of test
100.479087 ^ *
| *
| *
| *
|
| *
| *
|
| *
| *
| *
|
| *
| *
0 +--------------------------------------------------------------------->
0 1100
N min max avg
110 1.23984e+0 1.09774e+1 5.97581e+0
209 1.10121e+1 2.08884e+1 1.60011e+1
308 2.13004e+1 3.09071e+1 2.60224e+1
407 3.10212e+1 4.09074e+1 3.59904e+1
506 4.10095e+1 5.09904e+1 4.60456e+1
605 5.11370e+1 6.08557e+1 5.60354e+1
704 6.10493e+1 7.09071e+1 6.59642e+1
803 7.11237e+1 8.07733e+1 7.59588e+1
902 8.10944e+1 9.09766e+1 8.60179e+1
1001 9.10459e+1 9.99404e+1 9.54548e+1
1100 1.00004e+2 1.00939e+2 1.00479e+2
#+END_EXAMPLE
Note: =?run_prop= does this automatically.
