ExUnit LogCapture Scaling with Parallel Test Cases

[bmteller]

Elixir and Erlang/OTP versions

Erlang/OTP 27 [erts-15.2] [source] [64-bit] [smp:10:10] [ds:10:10:10] [async-threads:1] [jit]

Elixir 1.18.2 (compiled with Erlang/OTP 27)

Operating system

Linux

Current behavior

Let's say I'm using ExUnit.start(capture_log: true). My understanding is this will end up calling ExUnit.CaptureServer.log_capture_on for each test that is running and register a StringIO GenServer. Then each time I call a Logger.<level> method this will iterate over each StringIO GenServer writing the contents of the log message to each GenServer. So if I'm running with max cases = 16 then every time I perform a log this causes a GenServer.call to 16 GenServers. So in the best case the cost of an individual logging call increases linearly with number of ExUnit max cases. However, multiple processes writing to the GenServers becomes a point of contention so the best case (which is far from ideal) is not possible. My suspicion is the cost of an individual log message is somewhere between a linear function of max-cases and a quadratic function of max-cases. I'm running max_cases=16 on a 32 core machine and I'm seeing ~400ms latency between two log messages which should be really happening directly after each other.

Here is a minimal test reproducer:

defmodule SlowLogTests do
  
  Enum.each(1..1024, fn(i) ->
    Module.create(:"Part#{i}Test", quote do
      use ExUnit.Case, async: true
      require Logger

      test "spam" do
        process = inspect(self())
        Enum.each(1..256, fn(_) ->
          Logger.info("AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA: #{process}")
        end)
      end
    end, Macro.Env.location(__ENV__))
  end)
  
end

along with test/test_helper:

ExUnit.start(capture_log: true)

and you can see the tests effective run serially:

Running ExUnit with seed: 981401, max_cases: 1

................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
Finished in 6.0 seconds (6.0s async, 0.00s sync)
1024 tests, 0 failures

Running ExUnit with seed: 764626, max_cases: 20

................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................
Finished in 6.1 seconds (6.1s async, 0.00s sync)
1024 tests, 0 failures

Though, this is not a great reproducer because if you turn off the capture log the tests still run serially because the underlying log implementation is not able to keep up with the log traffic.

Expected behavior

Ideally the cost of a log when running with capture_log would be completely local to the test. However, because of the way erlang/elixir works with processes I don't think this is logically possible because there is no way to group a process to a test that would make sense to everyone. I suspect it should be possible to stop the amplification if all the tests are capturing logs with the same configuration.

[josevalim]

Oh, what a great find. It should be an easy fix.

[josevalim]

Btw, this is a very clear reproducer:

[max_cases] = System.argv()

ExUnit.start(capture_log: true, autorun: false, max_cases: String.to_integer(max_cases))

Enum.each(1..1024, fn i ->
  Module.create(
    :"Part#{i}Test",
    quote do
      use ExUnit.Case, async: true
      require Logger

      test "spam" do
        process = inspect(self())

        Enum.each(1..256, fn _ ->
          Logger.info(
            "AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA: #{process}"
          )
        end)
      end
    end,
    Macro.Env.location(__ENV__)
  )
end)

ExUnit.run()

run it as elixir foo.exs 1 and elixir foo.exs 32. :) The example you provided is a bit muddier because modules are run as they are loaded, so the time to compile the module was getting mixed in.

[josevalim]

With the commit above it takes 0.6s for max_cases=1 and 0.9s for max_cases=32 (before it took 6.6s for max_cases=32). The slow down happens because:

1. I don't have 32 cores on my machine
2. Since this is only logging, the contention becomes the main factor
3. We are doing additional work anyway and StringIO could be optimized

We will take action on 3 as well, either soon or open up a separate issue.