Add --profile time flag to profile compilation steps (#9519)

lib/elixir/lib/kernel/parallel_compiler.ex

@@ -70,6 +70,9 @@ defmodule Kernel.ParallelCompiler do
     * `:long_compilation_threshold` - the timeout (in seconds) after the
       `:each_long_compilation` callback is invoked; defaults to `15`
 
+    * `:profile` - if set to `:time` measure the compilation time of each compilation cycle
+       and group pass checker
+
     * `:dest` - the destination directory for the BEAM files. When using `compile/2`,
       this information is only used to properly annotate the BEAM files before
       they are loaded into memory. If you want a file to actually be written to
@@ -145,8 +148,11 @@ defmodule Kernel.ParallelCompiler do
         each_long_compilation: Keyword.get(options, :each_long_compilation, fn _file -> :ok end),
         each_module: Keyword.get(options, :each_module, fn _file, _module, _binary -> :ok end),
         beam_timestamp: Keyword.get(options, :beam_timestamp),
-        output: output,
         long_compilation_threshold: Keyword.get(options, :long_compilation_threshold, 15),
+        profile: Keyword.get(options, :profile),
+        cycle_start: System.monotonic_time(),
+        module_counter: 0,
+        output: output,
         schedulers: schedulers
       })
 
@@ -243,6 +249,8 @@ defmodule Kernel.ParallelCompiler do
 
   # No more queue, nothing waiting, this cycle is done
   defp spawn_workers([], 0, [], [], result, warnings, state) do
+    state = cycle_timing(result, state)
+
     case each_cycle_return(state.each_cycle.()) do
       {:runtime, dependent_modules} ->
         write_and_verify_modules(result, warnings, dependent_modules, state)
@@ -319,14 +327,37 @@ defmodule Kernel.ParallelCompiler do
     end
   end
 
+  defp cycle_timing(result, %{profile: :time} = state) do
+    %{cycle_start: cycle_start, module_counter: module_counter} = state
+    num_modules = count_modules(result)
+    diff_modules = num_modules - module_counter
+    now = System.monotonic_time()
+    time = System.convert_time_unit(now - cycle_start, :native, :millisecond)
+
+    IO.puts(
+      :stderr,
+      "[profile] Finished compilation cycle of #{diff_modules} modules in #{time}ms"
+    )
+
+    %{state | cycle_start: now, module_counter: num_modules}
+  end
+
+  defp cycle_timing(_result, %{profile: nil} = state) do
+    state
+  end
+
+  defp count_modules(result) do
+    Enum.count(result, &match?({{:module, _}, _}, &1))
+  end
+
   # TODO: Deprecate on v1.12
   defp each_cycle_return(modules) when is_list(modules), do: {:compile, modules}
   defp each_cycle_return(other), do: other
 
   defp write_and_verify_modules(result, warnings, dependent_modules, state) do
-    %{output: output, beam_timestamp: beam_timestamp, schedulers: schedulers} = state
+    %{output: output, beam_timestamp: beam_timestamp} = state
 
-    {binaries, checker_warnings} = maybe_check_modules(result, dependent_modules, schedulers)
+    {binaries, checker_warnings} = maybe_check_modules(result, dependent_modules, state)
     write_module_binaries(output, beam_timestamp, binaries)
     warnings = Enum.reverse(warnings, checker_warnings)
     {:ok, Enum.map(binaries, &elem(&1, 0)), warnings}
@@ -344,14 +375,19 @@ defmodule Kernel.ParallelCompiler do
     :ok
   end
 
-  defp maybe_check_modules(result, runtime_modules, schedulers) do
+  defp maybe_check_modules(result, runtime_modules, state) do
+    %{schedulers: schedulers, profile: profile} = state
+
     if :elixir_config.get(:bootstrap) do
       binaries = for {{:module, module}, {binary, _map}} <- result, do: {module, binary}
       {binaries, []}
     else
       compiled_modules = checker_compiled_modules(result)
       runtime_modules = checker_runtime_modules(runtime_modules)
-      Module.ParallelChecker.verify(compiled_modules, runtime_modules, schedulers)
+
+      profile_checker(profile, compiled_modules, runtime_modules, fn ->
+        Module.ParallelChecker.verify(compiled_modules, runtime_modules, schedulers)
+      end)
     end
   end
 
@@ -369,6 +405,18 @@ defmodule Kernel.ParallelCompiler do
     end
   end
 
+  defp profile_checker(_profile = :time, compiled_modules, runtime_modules, fun) do
+    {time, result} = :timer.tc(fun)
+    time = div(time, 1000)
+    num_modules = length(compiled_modules) + length(runtime_modules)
+    IO.puts(:stderr, "[profile] Finished group pass check of #{num_modules} modules in #{time}ms")
+    result
+  end
+
+  defp profile_checker(_profile = nil, _compiled_modules, _runtime_modules, fun) do
+    fun.()
+  end
+
   # The goal of this function is to find leaves in the dependency graph,
   # i.e. to find code that depends on code that we know is not being defined.
   defp without_definition(waiting, files) do

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

@@ -183,6 +183,7 @@ defmodule Mix.Compilers.Elixir do
       each_module: &each_module(&1, &2, &3, cwd),
       each_long_compilation: &each_long_compilation(&1, cwd, long_compilation_threshold),
       long_compilation_threshold: long_compilation_threshold,
+      profile: opts[:profile],
       beam_timestamp: timestamp
     ]
 

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

@@ -26,6 +26,7 @@ defmodule Mix.Tasks.Compile.Elixir do
       return a non-zero exit code
     * `--long-compilation-threshold N` - sets the "long compilation" threshold
       (in seconds) to `N` (see the docs for `Kernel.ParallelCompiler.compile/2`)
+    * `--profile` - if set to `time`, outputs timing information of compilation steps
     * `--all-warnings` - prints warnings even from files that do not need to be recompiled
     * `--tracer` - adds a compiler tracer in addition to any specified in the `mix.exs` file
 
@@ -49,6 +50,7 @@ defmodule Mix.Tasks.Compile.Elixir do
     debug_info: :boolean,
     verbose: :boolean,
     long_compilation_threshold: :integer,
+    profile: :string,
     all_warnings: :boolean,
     tracer: :keep
   ]
@@ -74,6 +76,7 @@ defmodule Mix.Tasks.Compile.Elixir do
       |> Keyword.merge(opts)
       |> xref_exclude_opts(project)
       |> merge_tracers()
+      |> profile_opts()
 
     Mix.Compilers.Elixir.compile(manifest, srcs, dest, [:ex], force, opts)
   end
@@ -109,4 +112,12 @@ defmodule Mix.Tasks.Compile.Elixir do
         Keyword.update(opts, :tracers, tracers, &(tracers ++ &1))
     end
   end
+
+  defp profile_opts(opts) do
+    case Keyword.fetch(opts, :profile) do
+      {:ok, "time"} -> Keyword.put(opts, :profile, :time)
+      {:ok, _} -> Keyword.delete(opts, :profile)
+      :error -> opts
+    end
+  end
 end