Log times to type check modules when profiling

Author: josevalim

lib/elixir/lib/kernel/parallel_compiler.ex

@@ -197,8 +197,8 @@ defmodule Kernel.ParallelCompiler do
       deprecation warnings, and type checking should run. Defaults to `true`.
       We recommend disabling it only for debugging purposes.
 
-    * `:profile` - if set to `:time` measure the compilation time of each compilation cycle
-       and group pass checker
+    * `:profile` - if set to `:time`, measure the compilation time of each compilation cycle,
+      each module type check, and group pass checker
 
     * `:purge_compiler_modules` - if set to `true`, automatically purge compilation modules
       after compilation (see `Code.purge_compiler_modules/0`)

lib/elixir/lib/module/parallel_checker.ex

@@ -20,6 +20,7 @@ defmodule Module.ParallelChecker do
           {:max_concurrency, pos_integer()}
           | {:long_verification_threshold, pos_integer()}
           | {:each_long_verification, (module() -> term()) | (module(), pid() -> term())}
+          | {:profile, :time}
           | {atom(), term()}
         ]
 
@@ -117,13 +118,13 @@ defmodule Module.ParallelChecker do
             send(checker, {ref, :cached})
 
             receive do
-              {^ref, :check} ->
+              {^ref, :check, profile} ->
                 # Set the compiler info so we can collect warnings
                 :erlang.put(:elixir_compiler_info, {pid, self()})
 
                 {warnings, errors} =
                   if module_tuple do
-                    check_module(module_tuple, {checker, table}, log?)
+                    check_module(module_tuple, {checker, table}, log?, profile)
                   else
                     {[], []}
                   end
@@ -262,7 +263,7 @@ defmodule Module.ParallelChecker do
 
   ## Module checking
 
-  defp check_module(module_tuple, cache, log?) do
+  defp check_module(module_tuple, cache, log?, profile) do
     {module, file, line, definitions, no_warn_undefined, behaviours, impls, attrs, after_verify} =
       module_tuple
 
@@ -276,9 +277,13 @@ defmodule Module.ParallelChecker do
         definitions
       )
 
+    type_warnings =
+      profile(module, profile, fn ->
+        Module.Types.warnings(module, file, attrs, definitions, no_warn_undefined, cache)
+      end)
+
     {warnings, errors} =
-      module
-      |> Module.Types.warnings(file, attrs, definitions, no_warn_undefined, cache)
+      type_warnings
       |> Kernel.++(behaviour_warnings)
       |> group_diagnostics()
       |> emit_diagnostics(file, log?)
@@ -577,6 +582,7 @@ defmodule Module.ParallelChecker do
       schedulers: schedulers,
       threshold: threshold,
       callback: callback,
+      profile: Keyword.get(options, :profile),
       protocols: [],
       table: table
     }
@@ -653,9 +659,24 @@ defmodule Module.ParallelChecker do
   end
 
   defp run_checkers(%{modules: [{module, pid, ref} | modules]} = state) do
-    send(pid, {ref, :check})
+    send(pid, {ref, :check, state.profile})
     timer = :erlang.send_after(state.threshold, self(), {__MODULE__, :timeout, module, pid})
     spawned = Map.put(state.spawned, module, timer)
     run_checkers(%{state | modules: modules, spawned: spawned})
   end
+
+  defp profile(module, :time, fun) do
+    {time, result} = :timer.tc(fun)
+
+    IO.puts(
+      :stderr,
+      "[profile] Type checked #{inspect(module)} in #{div(time, 1000)}ms"
+    )
+
+    result
+  end
+
+  defp profile(_module, _profile, fun) do
+    fun.()
+  end
 end

lib/elixir/test/elixir/kernel/parallel_compiler_test.exs

@@ -57,6 +57,7 @@ defmodule Kernel.ParallelCompilerTest do
                ~r"\[profile\] [\s\d]{6}ms compiling \+      0ms waiting while compiling .*tmp/profile_time/bar.ex"
 
       assert profile =~ ~r"\[profile\] Finished compilation cycle of 1 modules in \d+ms"
+      assert profile =~ ~r"\[profile\] Type checked HelloWorld in \d+ms"
       assert profile =~ ~r"\[profile\] Finished group pass check of 1 modules in \d+ms"
     after
       purge([HelloWorld])