Add each_long_verification_threshold, closes #14336

Author: josevalim

lib/elixir/lib/kernel/parallel_compiler.ex

@@ -270,7 +270,7 @@ defmodule Kernel.ParallelCompiler do
         max(:erlang.system_info(:schedulers_online), 2)
       end)
 
-    {:ok, cache} = Module.ParallelChecker.start_link(schedulers)
+    {:ok, cache} = Module.ParallelChecker.start_link(options)
 
     {status, modules_or_errors, info} =
       try do
@@ -341,16 +341,12 @@ defmodule Kernel.ParallelCompiler do
     File.mkdir_p!(path)
     Code.prepend_path(path)
 
-    Enum.flat_map(result, fn
-      {{:module, module}, {binary, _}} when is_binary(binary) ->
-        full_path = Path.join(path, Atom.to_string(module) <> ".beam")
-        File.write!(full_path, binary)
-        if timestamp, do: File.touch!(full_path, timestamp)
-        [module]
-
-      _ ->
-        []
-    end)
+    for {{:module, module}, {binary, _}} when is_binary(binary) <- result do
+      full_path = Path.join(path, Atom.to_string(module) <> ".beam")
+      File.write!(full_path, binary)
+      if timestamp, do: File.touch!(full_path, timestamp)
+      module
+    end
   end
 
   defp write_module_binaries(result, _output, _timestamp) do
@@ -362,16 +358,12 @@ defmodule Kernel.ParallelCompiler do
   defp verify_modules(result, compile_warnings, dependent_modules, state) do
     modules = write_module_binaries(result, state.output, state.beam_timestamp)
     _ = state.after_compile.()
-    runtime_warnings = maybe_check_modules(result, dependent_modules, state)
+    runtime_warnings = maybe_check_modules(modules, dependent_modules, state)
     info = %{compile_warnings: Enum.reverse(compile_warnings), runtime_warnings: runtime_warnings}
     {{:ok, modules, info}, state}
   end
 
-  defp maybe_check_modules(result, runtime_modules, state) do
-    compiled_modules =
-      for {{:module, module}, {binary, _}} when is_binary(binary) <- result,
-          do: module
-
+  defp maybe_check_modules(compiled_modules, runtime_modules, state) do
     profile(
       state,
       fn ->

lib/elixir/lib/module/parallel_checker.ex

@@ -14,8 +14,8 @@ defmodule Module.ParallelChecker do
   @doc """
   Initializes the parallel checker process.
   """
-  def start_link(schedulers \\ nil) do
-    :proc_lib.start_link(__MODULE__, :init, [schedulers])
+  def start_link(opts \\ []) do
+    :proc_lib.start_link(__MODULE__, :init, [opts])
   end
 
   @doc """
@@ -114,15 +114,15 @@ defmodule Module.ParallelChecker do
                   end
 
                 send(pid, {__MODULE__, module, warnings})
-                send(checker, {__MODULE__, :done})
+                send(checker, {__MODULE__, :done, module})
             end
 
           {:DOWN, ^mon_ref, _, _, _} ->
             :ok
         end
       end)
 
-    register(checker, spawned, ref)
+    register(checker, module, spawned, ref)
     :ok
   end
 
@@ -515,13 +515,13 @@ defmodule Module.ParallelChecker do
     :gen_server.call(server, {:unlock, module, mode}, :infinity)
   end
 
-  defp register(server, pid, ref) do
-    :gen_server.cast(server, {:register, pid, ref})
+  defp register(server, module, pid, ref) do
+    :gen_server.cast(server, {:register, module, pid, ref})
   end
 
   ## Server callbacks
 
-  def init(schedulers) do
+  def init(options) do
     table = :ets.new(__MODULE__, [:set, :public, {:read_concurrency, true}])
     :proc_lib.init_ack({:ok, {self(), table}})
 
@@ -544,11 +544,26 @@ defmodule Module.ParallelChecker do
         end
     end
 
+    schedulers =
+      Keyword.get_lazy(options, :max_concurrency, fn ->
+        max(:erlang.system_info(:schedulers_online), 2)
+      end)
+
+    threshold = Keyword.get(options, :long_verification_threshold, 10) * 1000
+
+    callback =
+      case Keyword.get(options, :each_long_verification, fn _module, _pid -> :ok end) do
+        fun when is_function(fun, 1) -> fn module, _pid -> fun.(module) end
+        fun when is_function(fun, 2) -> fun
+      end
+
     state = %{
       waiting: %{},
       modules: [],
-      spawned: 0,
-      schedulers: schedulers || max(:erlang.system_info(:schedulers_online), 2),
+      spawned: %{},
+      schedulers: schedulers,
+      threshold: threshold,
+      callback: callback,
       protocols: [],
       table: table
     }
@@ -559,11 +574,11 @@ defmodule Module.ParallelChecker do
   def handle_call(:start, _from, %{modules: modules, protocols: protocols, table: table} = state) do
     :ets.insert(table, Enum.map(protocols, &{&1, :uncached}))
 
-    for {pid, ref} <- modules do
+    for {_module, pid, ref} <- modules do
       send(pid, {ref, :cache})
     end
 
-    for {_pid, ref} <- modules do
+    for {_module, _pid, ref} <- modules do
       receive do
         {^ref, :cached} -> :ok
       end
@@ -594,30 +609,38 @@ defmodule Module.ParallelChecker do
     {:reply, :ok, %{state | waiting: waiting, protocols: protocols}}
   end
 
-  def handle_info({__MODULE__, :done}, state) do
-    state = %{state | spawned: state.spawned - 1}
-    {:noreply, run_checkers(state)}
+  def handle_info({__MODULE__, :timeout, module, pid}, state) do
+    state.callback.(module, pid)
+    {:noreply, state}
+  end
+
+  def handle_info({__MODULE__, :done, module}, state) do
+    {timer, spawned} = Map.pop!(state.spawned, module)
+    Process.cancel_timer(timer)
+    {:noreply, run_checkers(%{state | spawned: spawned})}
   end
 
   def handle_info({__MODULE__, :stop}, state) do
     {:stop, :normal, state}
   end
 
-  def handle_cast({:register, pid, ref}, %{modules: modules} = state) do
-    {:noreply, %{state | modules: [{pid, ref} | modules]}}
+  def handle_cast({:register, module, pid, ref}, %{modules: modules} = state) do
+    {:noreply, %{state | modules: [{module, pid, ref} | modules]}}
   end
 
   defp run_checkers(%{modules: []} = state) do
     state
   end
 
   defp run_checkers(%{spawned: spawned, schedulers: schedulers} = state)
-       when spawned >= schedulers do
+       when map_size(spawned) >= schedulers do
     state
   end
 
-  defp run_checkers(%{modules: [{pid, ref} | modules]} = state) do
+  defp run_checkers(%{modules: [{module, pid, ref} | modules]} = state) do
     send(pid, {ref, :check})
-    run_checkers(%{state | modules: modules, spawned: state.spawned + 1})
+    timer = Process.send_after(self(), {__MODULE__, :timeout, module, pid}, state.threshold)
+    spawned = Map.put(state.spawned, module, timer)
+    run_checkers(%{state | modules: modules, spawned: spawned})
   end
 end

lib/mix/lib/mix/compilers/elixir.ex

@@ -1001,7 +1001,8 @@ defmodule Mix.Compilers.Elixir do
   defp compiler_loop(stale, stale_modules, dest, timestamp, opts, state) do
     ref = make_ref()
     parent = self()
-    threshold = opts[:long_compilation_threshold] || 10
+    compilation_threshold = opts[:long_compilation_threshold] || 10
+    verification_threshold = opts[:long_verification_threshold] || 10
     profile = opts[:profile]
     verbose = opts[:verbose] || false
 
@@ -1022,11 +1023,18 @@ defmodule Mix.Compilers.Elixir do
           end,
           each_long_compilation: fn file, pid ->
             Mix.shell().info(
-              "Compiling #{Path.relative_to(file, File.cwd!())} (it's taking more than #{threshold}s)" <>
-                "\n#{debug_stacktrace(pid)}"
+              "Compiling #{Path.relative_to(file, File.cwd!())} " <>
+                "(it's taking more than #{compilation_threshold}s)#{debug_stacktrace(pid)}"
             )
           end,
-          long_compilation_threshold: threshold,
+          each_long_verification: fn module, pid ->
+            Mix.shell().info(
+              "Verifying #{inspect(module)} " <>
+                "(it's taking more than #{verification_threshold}s)#{debug_stacktrace(pid)}"
+            )
+          end,
+          long_compilation_threshold: compilation_threshold,
+          long_verification_threshold: verification_threshold,
           profile: profile,
           beam_timestamp: timestamp,
           return_diagnostics: true
@@ -1286,7 +1294,7 @@ defmodule Mix.Compilers.Elixir do
   defp debug_stacktrace(pid) do
     with true <- Mix.debug?(),
          {:current_stacktrace, stacktrace} <- Process.info(pid, :current_stacktrace) do
-      Exception.format_stacktrace(stacktrace)
+      [?\n, Exception.format_stacktrace(stacktrace)]
     else
       _ -> ""
     end

lib/mix/lib/mix/tasks/compile.elixir.ex

@@ -68,6 +68,8 @@ defmodule Mix.Tasks.Compile.Elixir do
     * `--ignore-module-conflict` - does not emit warnings if a module was previously defined
     * `--long-compilation-threshold N` - sets the "long compilation" threshold
       (in seconds) to `N` (see the docs for `Kernel.ParallelCompiler.compile/2`)
+    * `--long-verification-threshold N` - sets the "long verification" threshold
+      (in seconds) to `N` (see the docs for `Kernel.ParallelCompiler.compile/2`)
     * `--purge-consolidation-path-if-stale PATH` - deletes and purges modules in the
       given protocol consolidation path if compilation is required
     * `--profile` - if set to `time`, outputs timing information of compilation steps
@@ -100,6 +102,7 @@ defmodule Mix.Tasks.Compile.Elixir do
     debug_info: :boolean,
     verbose: :boolean,
     long_compilation_threshold: :integer,
+    long_verification_threshold: :integer,
     purge_consolidation_path_if_stale: :string,
     profile: :string,
     all_warnings: :boolean,