Add slowest_modules option to mix test (#13409)

Author: gpopides

lib/ex_unit/lib/ex_unit.ex

@@ -321,6 +321,10 @@ defmodule ExUnit do
       ExUnit with slow test reporting automatically runs in `trace` mode. It
       is disabled by default;
 
+    * `:slowest_modules` - prints timing information for the N slowest test modules. Running
+      ExUnit with slow test reporting automatically runs in `trace` mode. It
+      is disabled by default;
+
     * `:stacktrace_depth` - configures the stacktrace depth to be used
       on formatting and reporters, defaults to `20`;
 
@@ -532,7 +536,7 @@ defmodule ExUnit do
   end
 
   defp put_slowest(opts) do
-    if opts[:slowest] > 0 do
+    if opts[:slowest] > 0 or opts[:slowest_modules] > 0 do
       Keyword.put(opts, :trace, true)
     else
       opts

lib/ex_unit/lib/ex_unit/cli_formatter.ex

@@ -16,6 +16,7 @@ defmodule ExUnit.CLIFormatter do
       colors: colors(opts),
       width: get_terminal_width(),
       slowest: opts[:slowest],
+      slowest_modules: opts[:slowest_modules],
       test_counter: %{},
       test_timings: [],
       failure_counter: 0,
@@ -45,6 +46,10 @@ defmodule ExUnit.CLIFormatter do
       IO.puts(format_slowest_tests(config, times_us.run))
     end
 
+    if config.slowest_modules > 0 do
+      IO.puts(format_slowest_modules(config, times_us.run))
+    end
+
     print_summary(config, false)
     {:noreply, config}
   end
@@ -266,13 +271,49 @@ defmodule ExUnit.CLIFormatter do
     ]
   end
 
+  defp format_slowest_modules(%{slowest_modules: slowest, test_timings: timings}, run_us) do
+    slowest_tests =
+      timings
+      |> Enum.group_by(
+        fn %{module: module, tags: tags} ->
+          {module, tags.file}
+        end,
+        fn %{time: time} -> time end
+      )
+      |> Enum.into([], fn {{module, trace_test_file_line}, timings} ->
+        {module, trace_test_file_line, Enum.sum(timings)}
+      end)
+      |> Enum.sort_by(fn {_module, _, sum_timings} -> sum_timings end, :desc)
+      |> Enum.take(slowest)
+
+    slowest_us =
+      Enum.reduce(slowest_tests, 0, fn {_module, _, sum_timings}, acc ->
+        acc + sum_timings
+      end)
+
+    slowest_time = slowest_us |> normalize_us() |> format_us()
+    percentage = Float.round(slowest_us / run_us * 100, 1)
+
+    [
+      "\nTop #{slowest} slowest (#{slowest_time}s), #{percentage}% of total time:\n\n"
+      | Enum.map(slowest_tests, &format_slow_module/1)
+    ]
+  end
+
   defp format_slow_test(%ExUnit.Test{time: time, module: module} = test) do
     "#{trace_test_started(test)} (#{inspect(module)}) (#{format_us(time)}ms) " <>
       "[#{trace_test_file_line(test)}]\n"
   end
 
-  defp update_test_timings(%{slowest: slowest} = config, %ExUnit.Test{} = test) do
-    if slowest > 0 do
+  defp format_slow_module({module, test_file_path, timings}) do
+    "#{inspect(module)} (#{format_us(timings)}ms)\n [#{Path.relative_to_cwd(test_file_path)}]\n"
+  end
+
+  defp update_test_timings(
+         %{slowest: slowest, slowest_modules: slowest_modules} = config,
+         %ExUnit.Test{} = test
+       ) do
+    if slowest > 0 or slowest_modules > 0 do
       # Do not store logs, as they are not used for timings and consume memory.
       update_in(config.test_timings, &[%{test | logs: ""} | &1])
     else

lib/ex_unit/mix.exs

@@ -30,6 +30,7 @@ defmodule ExUnit.MixProject do
         rand_algorithm: :exsss,
         refute_receive_timeout: 100,
         slowest: 0,
+        slowest_modules: 0,
         stacktrace_depth: 20,
         timeout: 60000,
         trace: false,

lib/ex_unit/test/ex_unit_test.exs

@@ -239,6 +239,41 @@ defmodule ExUnitTest do
     assert output =~ ~r"\* test delayed \(.+ms\)"
   end
 
+  test "reports slow test modules" do
+    defmodule SlowTestModule do
+      use ExUnit.Case
+
+      test "slow" do
+        refute false
+      end
+    end
+
+    defmodule SlowerTestModule do
+      use ExUnit.Case
+
+      test "slower" do
+        Process.sleep(5)
+        refute false
+      end
+    end
+
+    defmodule SlowestTestModule do
+      use ExUnit.Case
+
+      test "slowest" do
+        Process.sleep(10)
+        refute false
+      end
+    end
+
+    configure_and_reload_on_exit(slowest_modules: 2)
+
+    output = capture_io(fn -> ExUnit.run() end)
+    assert output =~ ~r"Top 2 slowest \(\d+\.\d+s\), \d+.\d% of total time:"
+    assert output =~ ~r"SlowestTestModule \(.+ms\)"
+    assert output =~ ~r"SlowerTestModule \(.+ms\)"
+  end
+
   test "sets max cases to one with trace enabled" do
     configure_and_reload_on_exit(trace: true, max_cases: 10)
     config = ExUnit.configuration()

lib/mix/lib/mix/tasks/test.ex

@@ -447,6 +447,7 @@ defmodule Mix.Tasks.Test do
     listen_on_stdin: :boolean,
     formatter: :keep,
     slowest: :integer,
+    slowest_modules: :integer,
     partitions: :integer,
     preload_modules: :boolean,
     warnings_as_errors: :boolean,
@@ -681,6 +682,7 @@ defmodule Mix.Tasks.Test do
     :formatters,
     :colors,
     :slowest,
+    :slowest_modules,
     :failures_manifest_file,
     :only_test_ids,
     :test_location_relative_path,