Disclaimer: this is by no means an issue and it doesn’t block anything nor causes problems to our code. It is up only for discussion. Only waste your free time here
I’ve been doing some reviews on several projects in Elixir and one of my routines is to run mix test --trace just to get the outline of the test suite.
This has the added benefit of showing the times each test needed to run. What I’ve noticed is that the first test time seems to have some warm-up added to it. Most suites here have every test under 10ms but the first one always passes the 100ms mark and its source does not have anything that would cause this. I’ve run the suites several times and the order changes but it is always the first test that is reported at above the 100ms mark. I couldn’t find anything in ExUnit’s source code that would cause this (no differences from how it runs the “first” test).
Discussion
Could any one just shine some light here and make us all more knowledgeable about the inner workings of the BEAM and/or OTP? I’d truly appreciate that
This is most likely related to loading of the modules. The VM can run in two modes: interactive that loads modules on first use and embedded that requires loading all the modules explicitly. The first is used by things like mix and iex and the later by releases. The slowness of the first test you see is most likely related to this lazy loading of the modules.
By modules he means your actual application and its dependencies, not the test modules. The code you’re testing in lib isn’t actually loaded until it’s called, so the first test to touch some code pays the time penalty to load it.
But then again (sorry for being persistent), when we calculate that time aren’t our modules already loaded? I mean, this is the time of a single test and not the time for the whole command to run, right?
defmodule FooTest do
use ExUnit.Case
# The Foo module is not loaded yet
test "foo" do
Foo().bar # the Foo module is loaded exactly now
# because it's being called for the first time now.
end
end
The module isn’t loaded until during the middle of the test case, so the time required to load it falls within the test case time.
The VM has two modes of operating: interpreted and embedded;
Mix runs interpreted, releases run embedded;
When the test runs modules that are not a script are already compiled but not loaded. This happens lazily on the first call;
The test module is a script so its loaded only before being run.
The thing I’m thinking now is: the application is already started when running the test, right? I mean, I don’t start my top level application to run tests and all configurations are loaded already (with test overrides). When starting the application it loads all of its modules dependencies, right?
What I do have is the “support” folder which contains code that is not a script (fixtures and whatnot…) and is an “extra” for test env only. Those I know for sure are only loaded when first called.
Yes, the application usually is started before running the tests, but does your application call into Foo during its start? Does it’s force the load of the module?
And on top of that, there is the whole Elixir standard library and the modules in your libraries, that will only be loaded when use the first time, and most likely are not loaded when your app boots.
This is precisely why you can do mix test --trace --preload-modules, as the loading does skew test measurement times.
