Starting unit tests takes a lot of time

Ecosystem
1

I am using unit tests a lot and they are a great tool to guarantee a good quality. Up to now everything worked fine with the dune setup

  (inline_tests)
  (preprocess (pps ppx_inline_test))

But recently I have observed some strange behaviour. The start up time of the unit tests has become long (2-3 seconds on my macbook). I am pretty sure that this is not the time to execute the unit test. The pure compilation with dune build is still very fast. However dune runtesttakes the time obviously before executing the tests (because the tests are really simple and should run very fast).

In order to be sure that the execution of the test cases is not the problem, I have deleted all testcases and just put one

let%test _ = true

test case into the file and the behaviour is the same.

What can I do to get some information on what happens. What processes are running under the hood. There has to be some dependency management because when neither the testcases nor the code excersized in the test cases has been changed, the tests are not repeated.

Is there any possibility to activate a trace or some more verbose output to find the source of the delay.

I have tried dune runtest –verbose and I have got the output

Shared cache: enabled-except-user-rules
Shared cache location: /Users/helmut/.cache/dune/db
Workspace root: /Users/helmut/github/alba-lang/compiler
Auto-detected concurrency: 8
Dune context:
 { name = "default"
 ; kind = "default"
 ; profile = Dev
 ; merlin = true
 ; fdo_target_exe = None
 ; build_dir = In_build_dir "default"
 ; instrument_with = []
 }
Running[1]: (cd _build/default && .ppx/bfcab61e6a21ecf6d2f80029fc1ef484/ppx.exe --cookie 'inline_tests="enabled"' --cookie 'library-name="core"' -o src/core/test_elab2.pp.ml --impl src/core/test_elab2.ml -corrected-suffix .ppx-corrected -diff-cmd - -dump-ast)
Running[2]: (cd _build/default && /Users/helmut/.opam/default/bin/ocamldep.opt -modules -impl src/core/test_elab2.pp.ml) > _build/default/src/core/.core.objs/core__Test_elab2.impl.d
Running[3]: (cd _build/default && /Users/helmut/.opam/default/bin/ocamlc.opt -w @1..3@5..28@30..39@43@46..47@49..57@61..62-40 -strict-sequence -strict-formats -short-paths -keep-locs -g -bin-annot -bin-annot-occurrences -I src/core/.core.objs/byte -I /Users/helmut/.opam/default/lib/base -I /Users/helmut/.opam/default/lib/base/base_internalhash_types -I /Users/helmut/.opam/default/lib/base/shadow_stdlib -I /Users/helmut/.opam/default/lib/fmlib_parse -I /Users/helmut/.opam/default/lib/fmlib_pretty -I /Users/helmut/.opam/default/lib/fmlib_std -I /Users/helmut/.opam/default/lib/jane-street-headers -I /Users/helmut/.opam/default/lib/ocaml/unix -I /Users/helmut/.opam/default/lib/ocaml_intrinsics_kernel -I /Users/helmut/.opam/default/lib/ppx_compare/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_enumerate/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_hash/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_inline_test/config -I /Users/helmut/.opam/default/lib/ppx_inline_test/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_sexp_conv/runtime-lib -I /Users/helmut/.opam/default/lib/sexplib0 -I /Users/helmut/.opam/default/lib/time_now -I src/lib/.lib.objs/byte -I src/parse/.alba_parse.objs/byte -I src/std/.std.objs/byte -no-alias-deps -opaque -open Core -o src/core/.core.objs/byte/core__Test_elab2.cmo -c -impl src/core/test_elab2.pp.ml)
Running[4]: (cd _build/default && /Users/helmut/.opam/default/bin/ocamlopt.opt -w @1..3@5..28@30..39@43@46..47@49..57@61..62-40 -strict-sequence -strict-formats -short-paths -keep-locs -g -I src/core/.core.objs/byte -I src/core/.core.objs/native -I /Users/helmut/.opam/default/lib/base -I /Users/helmut/.opam/default/lib/base/base_internalhash_types -I /Users/helmut/.opam/default/lib/base/shadow_stdlib -I /Users/helmut/.opam/default/lib/fmlib_parse -I /Users/helmut/.opam/default/lib/fmlib_pretty -I /Users/helmut/.opam/default/lib/fmlib_std -I /Users/helmut/.opam/default/lib/jane-street-headers -I /Users/helmut/.opam/default/lib/ocaml/unix -I /Users/helmut/.opam/default/lib/ocaml_intrinsics_kernel -I /Users/helmut/.opam/default/lib/ppx_compare/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_enumerate/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_hash/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_inline_test/config -I /Users/helmut/.opam/default/lib/ppx_inline_test/runtime-lib -I /Users/helmut/.opam/default/lib/ppx_sexp_conv/runtime-lib -I /Users/helmut/.opam/default/lib/sexplib0 -I /Users/helmut/.opam/default/lib/time_now -I src/lib/.lib.objs/byte -I src/lib/.lib.objs/native -I src/parse/.alba_parse.objs/byte -I src/parse/.alba_parse.objs/native -I src/std/.std.objs/byte -I src/std/.std.objs/native -intf-suffix .ml -no-alias-deps -opaque -open Core -o src/core/.core.objs/native/core__Test_elab2.cmx -c -impl src/core/test_elab2.pp.ml)
Running[5]: (cd _build/default && /Users/helmut/.opam/default/bin/ocamlopt.opt -w @1..3@5..28@30..39@43@46..47@49..57@61..62-40 -strict-sequence -strict-formats -short-paths -keep-locs -g -a -o src/core/core.cmxa src/core/.core.objs/native/core.cmx src/core/.core.objs/native/core__Info.cmx src/core/.core.objs/native/core__Sign.cmx src/core/.core.objs/native/core__Term.cmx src/core/.core.objs/native/core__Globals.cmx src/core/.core.objs/native/core__Print_term.cmx src/core/.core.objs/native/core__Gamma.cmx src/core/.core.objs/native/core__Generic_elaborator.cmx src/core/.core.objs/native/core__Hole.cmx src/core/.core.objs/native/core__Tracer.cmx src/core/.core.objs/native/core__Base_elab.cmx src/core/.core.objs/native/core__Unify.cmx src/core/.core.objs/native/core__Elab2.cmx src/core/.core.objs/native/core__Test_elab2.cmx src/core/.core.objs/native/core__Elab.cmx src/core/.core.objs/native/core__Il_parser.cmx src/core/.core.objs/native/core__Test_elab.cmx src/core/.core.objs/native/core__Intf.cmx)
Running[6]: (cd _build/default && /Users/helmut/.opam/default/bin/ocamlopt.opt -w @1..3@5..28@30..39@43@46..47@49..57@61..62-40 -strict-sequence -strict-formats -short-paths -keep-locs -w -24 -g -g -o src/core/.core.inline-tests/inline-test-runner.exe /Users/helmut/.opam/default/lib/ppx_inline_test/config/inline_test_config.cmxa /Users/helmut/.opam/default/lib/base/base_internalhash_types/base_internalhash_types.cmxa -I /Users/helmut/.opam/default/lib/base/base_internalhash_types /Users/helmut/.opam/default/lib/sexplib0/sexplib0.cmxa /Users/helmut/.opam/default/lib/base/shadow_stdlib/shadow_stdlib.cmxa /Users/helmut/.opam/default/lib/ocaml_intrinsics_kernel/ocaml_intrinsics_kernel.cmxa -I /Users/helmut/.opam/default/lib/ocaml_intrinsics_kernel /Users/helmut/.opam/default/lib/base/base.cmxa -I /Users/helmut/.opam/default/lib/base /Users/helmut/.opam/default/lib/jane-street-headers/jane_street_headers.cmxa /Users/helmut/.opam/default/lib/ppx_sexp_conv/runtime-lib/ppx_sexp_conv_lib.cmxa /Users/helmut/.opam/default/lib/ppx_compare/runtime-lib/ppx_compare_lib.cmxa /Users/helmut/.opam/default/lib/ppx_enumerate/runtime-lib/ppx_enumerate_lib.cmxa /Users/helmut/.opam/default/lib/ppx_hash/runtime-lib/ppx_hash_lib.cmxa /Users/helmut/.opam/default/lib/time_now/time_now.cmxa -I /Users/helmut/.opam/default/lib/time_now /Users/helmut/.opam/default/lib/ppx_inline_test/runtime-lib/ppx_inline_test_lib.cmxa /Users/helmut/.opam/default/lib/fmlib_std/fmlib_std.cmxa /Users/helmut/.opam/default/lib/fmlib_pretty/fmlib_pretty.cmxa /Users/helmut/.opam/default/lib/fmlib_parse/fmlib_parse.cmxa /Users/helmut/.opam/default/lib/ocaml/unix/unix.cmxa src/lib/lib.cmxa src/std/std.cmxa src/parse/alba_parse.cmxa src/core/core.cmxa /Users/helmut/.opam/default/lib/ppx_inline_test/runner/lib/ppx_inline_test_runner_lib.cmxa -I /Users/helmut/.opam/default/lib/ppx_inline_test/runner/lib src/core/.core.inline-tests/.t.eobjs/native/dune__exe__Main.cmx -linkall)
Running[7]: (cd _build/default/src/core && .core.inline-tests/inline-test-runner.exe inline-test-runner core -list-partitions) > _build/default/src/core/.core.inline-tests/partitions-best
Running[8]: (cd _build/default/src/core && .core.inline-tests/inline-test-runner.exe inline-test-runner core -partition generic_elaborator.ml -source-tree-root ../.. -diff-cmd -)
Running[9]: (cd _build/default/src/core && .core.inline-tests/inline-test-runner.exe inline-test-runner core -partition test_elab.ml -source-tree-root ../.. -diff-cmd -)
Running[10]: (cd _build/default/src/core && .core.inline-tests/inline-test-runner.exe inline-test-runner core -partition test_elab2.ml -source-tree-root ../.. -diff-cmd -)
Command [10] exited with code 2:     
$ (cd _build/default/src/core && .core.inline-tests/inline-test-runner.exe inline-test-runner core -partition test_elab2.ml -source-tree-root ../.. -diff-cmd -)
File "src/core/test_elab2.ml", line 49, characters 0-41: <<check_success true "Any">> threw "Assert_failure src/core/elab2.ml:20:4".
  Raised at Core__Elab2.any in file "src/core/elab2.ml", line 20, characters 4-16
  Called from Alba_parse__Src_parser.Make.step.(fun) in file "src/parse/src_parser.ml", line 54, characters 27-38
  Called from Fmlib_parse__Token_parser.Make.step.(fun) in file "src/parse/token_parser.ml", line 232, characters 35-67
  Called from Fmlib_parse__Generic.Make.step.(fun) in file "src/parse/generic.ml", line 319, characters 24-59
  Called from Fmlib_parse__Generic.Make.Parser.consume_lookaheads in file "src/parse/generic.ml", line 102, characters 35-40
  Called from Fmlib_parse__Parse_with_lexer.Make_basic.check_token in file "src/parse/parse_with_lexer.ml", line 180, characters 20-55
  Called from Fmlib_parse__Parse_with_lexer.Make_basic.put_end in file "src/parse/parse_with_lexer.ml", line 191, characters 12-56
  Called from Fmlib_parse__Run_on.string_at.run in file "src/parse/run_on.ml", line 24, characters 24-35
  Called from Fmlib_parse__Run_on.string in file "src/parse/run_on.ml", line 39, characters 4-44
  Called from Core__Test_elab2.check_success in file "src/core/test_elab2.ml", line 32, characters 12-37

FAILED 1 / 1 tests
2

I would guess you’ve already tried this, but just in case, there’s a difference between

  • dune runs the unit-tests (e.g. via “dune runtest”)
  • you invoke the unit-test directly, e.g. using the log file to show how to do it

Are both of these slow? that is to say, you’ve exonerated dune ?

3

Thanks for the hint. No, I have been not aware that I can start unit tests directly from the commandline. I have tried it.

There seem to be 3 unit tests in this library. Executing the 2nd (Running[9]) one takes the time.

One question: Does dune execute all unit tests even if nothing concerning the specific test has changed? It seems to be yes. I was under the impression that they are not executed. It seems that they are executed and their results are compared with the previous results. Does anybody know the strategy?

4

I thought about this some more, and I think it’s pretty clear that dune -must- execute tests indiscriminately. Here’s why:

(1) dune cannot discern whether a test uses “fixtures” that have changed, even when the test’s -code- hasn’t changed

(2) dune cannot know if a test is nondeterministic

(3) AFAIK dune doesn’t keep track of whether a test succeeded or failed in some persistent place

So how could it know whether to rerun a test or not?

2 Likes
5

During debugging I sometimes add to the tests some printouts to the console. If the a test succeeds the first time, I see the printouts, the next time the printouts are no longer done. Therefore I concluded that dune does not execute success cases repeatedly.

1 Like
7

That is true. In Dune you can think of a test as a build target. When a target has been built successfully, there is no need to rerun the test, because the target (a succeeding test) has been already achieved and the test had no dependencies change so there was no need to rebuild and rerun the test.

dune runtest --force might be of interest to you.

1 Like
8

How can dune know this? There are

  • test-fixtures – test-inputs that aren’t reflected in the build-dependencies
  • flapping (nondeterministic) tests

how can dune know that a rerun test won’t behave differently?

1 Like
9

It only knows about the things that it can know. That is:

  1. Source files that the test executable depends on for building
  2. Declared dependencies

This means that you need to declare dependencies on your fixtures (but given your tests are run in a sandbox location you need to declare them anyway or the test will fail as the fixture files aren’t in the right location).

As for flaky tests, yes, this can be annoying, but you can use the --forceflag while you debug a flaky test. Generally flaky tests are something we want to avoid, so assuming tests are reproducible seems like an ok compromise for which you can get faster test suite runs.

1 Like
10

If your test is non deterministic or its dependencies are too hard to specify, you can specify (universe) as its dependency. Dune will then consider that the test depends on everything under the sun and retrigger the test/rule/whatever every time it is run.

Cheers,
Nicolas

2 Likes
11

Nice. Thank you all for the explanations!