Consider load time on ExUnit reports, closes #893

Author: José Valim

lib/ex_unit/lib/ex_unit.ex

@@ -81,6 +81,7 @@ defmodule ExUnit do
     :application.start(:ex_unit)
 
     configure(options)
+    ExUnit.Server.start_load
 
     System.at_exit fn
       0 ->
@@ -118,7 +119,7 @@ defmodule ExUnit do
   Returns the number of failures.
   """
   def run do
-    { async, sync } = ExUnit.Server.cases
-    ExUnit.Runner.run async, sync, ExUnit.Server.options
+    { async, sync, options, load_us } = ExUnit.Server.start_run
+    ExUnit.Runner.run async, sync, options, load_us
   end
 end

lib/ex_unit/lib/ex_unit/cli_formatter.ex

@@ -18,8 +18,8 @@ defmodule ExUnit.CLIFormatter do
     pid
   end
 
-  def suite_finished(id, ms) do
-    :gen_server.call(id, { :suite_finished, ms }, @timeout)
+  def suite_finished(id, run_us, load_us) do
+    :gen_server.call(id, { :suite_finished, run_us, load_us }, @timeout)
   end
 
   def case_started(_id, _test_case) do
@@ -44,8 +44,8 @@ defmodule ExUnit.CLIFormatter do
     { :ok, Config.new }
   end
 
-  def handle_call({ :suite_finished, ms }, _from, config) do
-    print_suite(config.counter, config.test_failures, config.case_failures, ms)
+  def handle_call({ :suite_finished, run_us, load_us }, _from, config) do
+    print_suite(config.counter, config.test_failures, config.case_failures, run_us, load_us)
     { :stop, :normal, length(config.test_failures), config }
   end
 
@@ -82,19 +82,19 @@ defmodule ExUnit.CLIFormatter do
     super
   end
 
-  defp print_suite(counter, [], [], ms) do
+  defp print_suite(counter, [], [], run_us, load_us) do
     IO.write "\n\n"
-    IO.puts "Finished in #{format_ms ms} seconds"
+    print_time(run_us, load_us)
     IO.puts success("#{counter} tests, 0 failures")
   end
 
-  defp print_suite(counter, test_failures, case_failures, ms) do
+  defp print_suite(counter, test_failures, case_failures, run_us, load_us) do
     IO.write "\n\nFailures:\n\n"
     num_fails = Enum.reduce Enum.reverse(test_failures), 1, print_test_failure(&1, &2, File.cwd!)
     Enum.reduce Enum.reverse(case_failures), num_fails, print_case_failure(&1, &2, File.cwd!)
     num_invalids = Enum.count test_failures, fn test -> test.invalid end
 
-    IO.puts "Finished in #{format_ms ms} seconds"
+    print_time(run_us, load_us)
 
     num_fails = num_fails - 1
     message = "#{counter} tests, #{num_fails} failures"
@@ -160,6 +160,18 @@ defmodule ExUnit.CLIFormatter do
     Enum.each stacktrace, fn(s) -> IO.puts stacktrace_info format_entry(s, cwd) end
   end
 
+  defp print_time(run_us, nil) do
+    IO.puts "Finished in #{run_us |> normalize_us |> format_us} seconds"
+  end
+
+  defp print_time(run_us, load_us) do
+    run_us  = run_us |> normalize_us
+    load_us = load_us |> normalize_us
+
+    ms = run_us + load_us
+    IO.puts "Finished in #{format_us ms} seconds (#{format_us load_us}s on load, #{format_us run_us}s on tests)"
+  end
+
   defp pad(binary, max) do
     remaining = max - size(binary)
     if remaining > 0 do
@@ -169,12 +181,16 @@ defmodule ExUnit.CLIFormatter do
     end
   end
 
-  defp format_ms(ms) do
-    if ms < 100000 do
-      "0.0#{div(ms, 10000)}"
+  defp normalize_us(us) do
+    div(us, 10000)
+  end
+
+  defp format_us(us) do
+    if us < 10 do
+      "0.0#{us}"
     else
-      ms = div ms, 100000
-      "#{div(ms, 10)}.#{rem(ms, 10)}"
+      us = div us, 10
+      "#{div(us, 10)}.#{rem(us, 10)}"
     end
   end
 

lib/ex_unit/lib/ex_unit/formatter.ex

@@ -7,16 +7,18 @@ defmodule ExUnit.Formatter do
   use Behaviour
 
   @type id :: term
-  @type test_case :: module
-  @type test :: atom
+  @type test_case :: ExUnit.TestCase.t
+  @type test :: ExUnit.Test.t
   @type result :: { kind :: atom, reason :: term, stacktrace :: list } | nil
+  @type run_us :: pos_integer
+  @type load_us :: pos_integer | nil
 
   defcallback suite_started(opts :: list) :: id
-  defcallback suite_finished(id, miliseconds :: pos_integer) :: non_neg_integer
+  defcallback suite_finished(id, run_us, load_us) :: non_neg_integer
 
   defcallback case_started(id, test_case) :: any
   defcallback case_finished(id, test_case) :: any
 
-  defcallback test_started(id, test :: ExUnit.Test.t) :: any
-  defcallback test_finished(id, test :: ExUnit.Test.t) :: any
+  defcallback test_started(id, test) :: any
+  defcallback test_finished(id, test) :: any
 end

lib/ex_unit/lib/ex_unit/runner.ex

@@ -4,17 +4,17 @@ defmodule ExUnit.Runner do
   defrecord Config, formatter: ExUnit.CLIFormatter, formatter_id: nil,
                     max_cases: 4, taken_cases: 0, async_cases: [], sync_cases: []
 
-  def run(async, sync, opts) do
+  def run(async, sync, opts, load_us) do
     config = Config[max_cases: :erlang.system_info(:schedulers_online)]
     config = config.update(opts)
 
-    { ms, config } =
+    { run_us, config } =
       :timer.tc fn ->
         loop config.async_cases(async).sync_cases(sync).
                formatter_id(config.formatter.suite_started(opts))
       end
 
-    config.formatter.suite_finished(config.formatter_id, ms)
+    config.formatter.suite_finished(config.formatter_id, run_us, load_us)
   end
 
   defp loop(Config[] = config) do

lib/ex_unit/lib/ex_unit/server.ex

@@ -4,14 +4,19 @@ defmodule ExUnit.Server do
   @timeout 30_000
   use GenServer.Behaviour
 
-  defrecord Config, options: [], async_cases: [], sync_cases: []
+  defrecord Config, options: [], async_cases: [], sync_cases: [],
+                    start_load: nil
 
   def start_link(options) do
     :gen_server.start_link({ :local, __MODULE__ }, __MODULE__, options, [])
   end
 
   ## Before run API
 
+  def start_load() do
+    :gen_server.cast(__MODULE__, :start_load)
+  end
+
   def add_async_case(name) do
     :gen_server.cast(__MODULE__, { :add_async_case, name })
   end
@@ -26,12 +31,8 @@ defmodule ExUnit.Server do
 
   ## After run API
 
-  def options do
-    :gen_server.call(__MODULE__, :options, @timeout)
-  end
-
-  def cases do
-    :gen_server.call(__MODULE__, :cases, @timeout)
+  def start_run() do
+    :gen_server.call(__MODULE__, :start_run, @timeout)
   end
 
   ## Callbacks
@@ -40,20 +41,25 @@ defmodule ExUnit.Server do
     { :ok, Config[options: options] }
   end
 
-  def handle_call(:options, _from, config) do
-    { :reply, config.options, config }
-  end
+  def handle_call(:start_run, _from, config) do
+    load_us =
+      if start_load = config.start_load do
+        :timer.now_diff(:os.timestamp, start_load)
+      end
 
-  def handle_call(:cases, _from, config) do
     { :reply,
-      { config.async_cases, config.sync_cases },
-      config.async_cases([]).sync_cases([]) }
+      { config.async_cases, config.sync_cases, config.options, load_us },
+      config.async_cases([]).sync_cases([]).start_load(nil) }
   end
 
   def handle_call(request, from, config) do
     super(request, from, config)
   end
 
+  def handle_cast(:start_load, config) do
+    { :noreply, config.start_load(:os.timestamp) }
+  end
+
   def handle_cast({:add_async_case, name}, config) do
     { :noreply, config.update_async_cases [name|&1] }
   end

lib/ex_unit/test/ex_unit_test.exs

@@ -7,7 +7,7 @@ defmodule ExUnit.NilFormatter do
     :ok
   end
 
-  def suite_finished(:ok, _ms) do
+  def suite_finished(:ok, _run_us, _load_us) do
     1
   end