From 2e13e5d8a41aca16c8eca80e4ba2f0208f32bc8d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Eric=20Meadows-J=C3=B6nsson?= Date: Wed, 13 Nov 2019 12:57:49 +0100 Subject: [PATCH] Add --profile time flag to profile compilation steps (#9519) --- lib/elixir/lib/kernel/parallel_compiler.ex | 58 ++++++++++++++++++++-- lib/mix/lib/mix/compilers/elixir.ex | 1 + lib/mix/lib/mix/tasks/compile.elixir.ex | 11 ++++ 3 files changed, 65 insertions(+), 5 deletions(-) diff --git a/lib/elixir/lib/kernel/parallel_compiler.ex b/lib/elixir/lib/kernel/parallel_compiler.ex index 02c6f75cc1..1c1a11bbb4 100644 --- a/lib/elixir/lib/kernel/parallel_compiler.ex +++ b/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 diff --git a/lib/mix/lib/mix/compilers/elixir.ex b/lib/mix/lib/mix/compilers/elixir.ex index bce90e0a19..e974ba71bd 100644 --- a/lib/mix/lib/mix/compilers/elixir.ex +++ b/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 ] diff --git a/lib/mix/lib/mix/tasks/compile.elixir.ex b/lib/mix/lib/mix/tasks/compile.elixir.ex index 852f4ae450..c16c76d975 100644 --- a/lib/mix/lib/mix/tasks/compile.elixir.ex +++ b/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