From 83b01a8536724a51a889336f6faa45e9a6f0138a Mon Sep 17 00:00:00 2001 From: sabiwara Date: Sun, 26 May 2024 16:28:52 +0900 Subject: [PATCH 1/7] Copy eprof as tprof --- lib/mix/lib/mix/tasks/profile.tprof.ex | 333 ++++++++++++++++++ lib/mix/test/mix/tasks/profile.tprof_test.exs | 123 +++++++ 2 files changed, 456 insertions(+) create mode 100644 lib/mix/lib/mix/tasks/profile.tprof.ex create mode 100644 lib/mix/test/mix/tasks/profile.tprof_test.exs diff --git a/lib/mix/lib/mix/tasks/profile.tprof.ex b/lib/mix/lib/mix/tasks/profile.tprof.ex new file mode 100644 index 00000000000..0cf3913cca4 --- /dev/null +++ b/lib/mix/lib/mix/tasks/profile.tprof.ex @@ -0,0 +1,333 @@ +defmodule Mix.Tasks.Profile.Tprof do + use Mix.Task + + @shortdoc "Profiles the given file or expression with tprof" + + @moduledoc """ + Profiles the given file or expression using Erlang's `tprof` tool. + + [`:tprof`](`:tprof`) provides time information of each function call and can be useful + when you want to discover the bottlenecks related to this. + + Before running the code, it invokes the `app.start` task which compiles + and loads your project. After that, the target expression is profiled together + with all matching function calls using the Erlang trace BIFs. The tracing of + the function calls for that is enabled when the profiling is begun, and + disabled when profiling is stopped. + + To profile the code, you can use syntax similar to the `mix run` task: + + $ mix profile.tprof -e Hello.world + $ mix profile.tprof -e "[1, 2, 3] |> Enum.reverse |> Enum.map(&Integer.to_string/1)" + $ mix profile.tprof my_script.exs arg1 arg2 arg3 + + This task is automatically re-enabled, so you can profile multiple times + in the same Mix invocation. + + ## Command line options + + * `--matching` - only profile calls matching the given `Module.function/arity` pattern + * `--calls` - filters out any results with a call count lower than this + * `--time` - filters out any results that took lower than specified (in µs) + * `--sort` - sorts the results by `time` or `calls` (default: `time`) + * `--eval`, `-e` - evaluates the given code + * `--require`, `-r` - requires pattern before running the command + * `--parallel`, `-p` - makes all requires parallel + * `--no-warmup` - skips the warmup step before profiling + * `--no-compile` - does not compile even if files require compilation + * `--no-deps-check` - does not check dependencies + * `--no-archives-check` - does not check archives + * `--no-halt` - does not halt the system after running the command + * `--no-start` - does not start applications after compilation + * `--no-elixir-version-check` - does not check the Elixir version from mix.exs + + ## Profile output + + Example output: + + # CALLS % TIME µS/CALL + Total 24 100.0 26 1.08 + Enum.reduce_range_inc/4 5 3.85 1 0.20 + :erlang.make_fun/3 1 7.69 2 2.00 + Enum.each/2 1 7.69 2 2.00 + anonymous fn/0 in :elixir_compiler_0.__FILE__/1 1 7.69 2 2.00 + :erlang.integer_to_binary/1 5 15.39 4 0.80 + :erlang.apply/2 1 15.39 4 4.00 + anonymous fn/3 in Enum.each/2 5 19.23 5 1.00 + String.Chars.Integer.to_string/1 5 23.08 6 1.20 + + Profile done over 8 matching functions + + The default output contains data gathered from all matching functions. The first + row after the header contains the sums of the partial results and the average time + for all the function calls listed. The following rows contain the function call, + followed by the number of times that the function was called, then by the percentage + of time that the call uses, then the total time for that function in microseconds, + and, finally, the average time per call in microseconds. + + When `--matching` option is specified, call count tracing will be started only for + the functions matching the given pattern: + + # CALLS % TIME µS/CALL + Total 5 100.0 6 1.20 + String.Chars.Integer.to_string/1 5 100.0 6 1.20 + + Profile done over 1 matching functions + + The pattern can be a module name, such as `String` to count all calls to that module, + a call without arity, such as `String.split`, to count all calls to that function + regardless of arity, or a call with arity, such as `String.split/3`, to count all + calls to that exact module, function and arity. + + ## Caveats + + You should be aware that the code being profiled is running in an anonymous + function which is invoked by [`:tprof` module](https://www.erlang.org/doc/man/tprof.html). + Thus, you'll see some additional entries in your profile output. It is also + important to note that the profiler is stopped as soon as the code has finished running, + and this may need special attention, when: running asynchronous code as function calls which were + called before the profiler stopped will not be counted; running synchronous code as long + running computations and a profiler without a proper MFA trace pattern or filter may + lead to a result set which is difficult to comprehend. + + You should expect a slowdown in your code execution using this tool since `:tprof` has + some performance impact on the execution, but the impact is considerably lower than + `Mix.Tasks.Profile.Fprof`. If you have a large system try to profile a limited + scenario or focus on the main modules or processes. Another alternative is to use + `Mix.Tasks.Profile.Cprof` that uses [`:cprof`](`:cprof`) and has a low performance degradation effect. + """ + + @switches [ + parallel: :boolean, + require: :keep, + eval: :keep, + config: :keep, + matching: :string, + halt: :boolean, + compile: :boolean, + deps_check: :boolean, + calls: :integer, + time: :integer, + sort: :string, + start: :boolean, + archives_check: :boolean, + warmup: :boolean, + elixir_version_check: :boolean, + parallel_require: :keep + ] + + @aliases [ + r: :require, + p: :parallel, + e: :eval, + c: :config + ] + + @impl true + def run(args) do + {opts, head} = OptionParser.parse_head!(args, aliases: @aliases, strict: @switches) + Mix.Task.reenable("profile.tprof") + + Mix.Tasks.Run.run( + ["--no-mix-exs" | args], + opts, + head, + &profile_code(&1, opts), + &profile_code(File.read!(&1), opts) + ) + end + + defp profile_code(code_string, opts) do + opts = Enum.map(opts, &parse_opt/1) + + content = + quote do + unquote(__MODULE__).profile( + fn -> + unquote(Code.string_to_quoted!(code_string)) + end, + unquote(Macro.escape(opts)) + ) + end + + # Use compile_quoted since it leaves less noise than eval_quoted + Code.compile_quoted(content) + end + + defp parse_opt({:matching, matching}) do + case Mix.Utils.parse_mfa(matching) do + {:ok, [m, f, a]} -> {:matching, {m, f, a}} + {:ok, [m, f]} -> {:matching, {m, f, :_}} + {:ok, [m]} -> {:matching, {m, :_, :_}} + :error -> Mix.raise("Invalid matching pattern: #{matching}") + end + end + + defp parse_opt({:sort, "time"}), do: {:sort, :time} + defp parse_opt({:sort, "calls"}), do: {:sort, :calls} + defp parse_opt({:sort, other}), do: Mix.raise("Invalid sort option: #{other}") + defp parse_opt(other), do: other + + @doc """ + Allows to programmatically run the `tprof` profiler on expression in `fun`. + + Returns the return value of `fun`. + + ## Options + + * `:matching` - only profile calls matching the given pattern in form of + `{module, function, arity}`, where each element may be replaced by `:_` + to allow any value + * `:calls` - filters out any results with a call count lower than this + * `:time` - filters out any results that took lower than specified (in µs) + * `:sort` - sort the results by `:time` or `:calls` (default: `:time`) + * `:warmup` - if the code should be warmed up before profiling (default: `true`) + * `:set_on_spawn` - if newly spawned processes should be measured (default: `true`) + + """ + @spec profile((-> result), keyword()) :: result when result: any() + def profile(fun, opts \\ []) when is_function(fun, 0) do + Mix.ensure_application!(:tools) + {return_value, results} = profile_and_analyse(fun, opts) + print_output(results) + return_value + end + + defp profile_and_analyse(fun, opts) do + if Keyword.get(opts, :warmup, true) do + IO.puts("Warmup...\n") + fun.() + end + + :tprof.start() + matching = Keyword.get(opts, :matching, {:_, :_, :_}) + set_on_spawn = Keyword.get(opts, :set_on_spawn, true) + {:ok, return_value} = :tprof.profile([], fun, matching, set_on_spawn: set_on_spawn) + + results = + Enum.map(:tprof.dump(), fn {pid, call_results} -> + parsed_calls = + call_results + |> filter_results(opts) + |> sort_results(opts) + |> add_totals() + + {pid, parsed_calls} + end) + + :tprof.stop() + + {return_value, results} + end + + defp filter_results(call_results, opts) do + calls_opt = Keyword.get(opts, :calls, 0) + time_opt = Keyword.get(opts, :time, 0) + + call_results + |> Stream.filter(fn {_mfa, {count, _time}} -> count >= calls_opt end) + |> Stream.filter(fn {_mfa, {_count, time}} -> time >= time_opt end) + end + + defp sort_results(call_results, opts) do + Enum.sort_by(call_results, sort_function(Keyword.get(opts, :sort, :time))) + end + + defp sort_function(:time), do: fn {_mfa, {_count, time}} -> time end + defp sort_function(:calls), do: fn {_mfa, {count, _time}} -> count end + + defp add_totals(call_results) do + {function_count, call_count, total_time} = + Enum.reduce(call_results, {0, 0, 0}, fn {_, {count, time}}, acc -> + {function_count, call_count, total_time} = acc + {function_count + 1, call_count + count, total_time + time} + end) + + {function_count, call_results, call_count, total_time} + end + + @header ["#", "CALLS", "%", "TIME", "µS/CALL"] + + defp print_output([]) do + print_function_count(0) + end + + defp print_output(results) do + Enum.each(results, &print_result/1) + end + + defp print_result({pid, {function_count, call_results, call_count, total_time}}) do + formatted_rows = Enum.map(call_results, &format_row(&1, total_time)) + formatted_total = format_total(total_time, call_count) + + column_lengths = column_lengths(@header, formatted_rows) + + IO.puts("") + + print_pid_row(pid) + print_row(@header, column_lengths) + print_row(formatted_total, column_lengths) + Enum.each(formatted_rows, &print_row(&1, column_lengths)) + + IO.puts("") + + print_function_count(function_count) + end + + defp print_pid_row(pid) do + IO.puts("Profile results of #{inspect(pid)}") + end + + defp format_row({{module, function, arity}, {count, time}}, total_time) do + mfa = Exception.format_mfa(module, function, arity) + time_percentage = :erlang.float_to_binary(100 * divide(time, total_time), [{:decimals, 2}]) + time_per_call = :erlang.float_to_binary(divide(time, count), [{:decimals, 2}]) + count = Integer.to_string(count) + time = Integer.to_string(time) + + [mfa, count, time_percentage, time, time_per_call] + end + + defp format_total(total_time, total_count) do + time_per_call = :erlang.float_to_binary(divide(total_time, total_count), [{:decimals, 2}]) + + [ + "Total", + Integer.to_string(total_count), + "100.00", + Integer.to_string(total_time), + time_per_call + ] + end + + defp divide(_, 0), do: 0.0 + defp divide(t, n), do: t / n + + defp column_lengths(header, rows) do + max_lengths = Enum.map(header, &String.length/1) + + Enum.reduce(rows, max_lengths, fn row, max_lengths -> + Stream.map(row, &String.length/1) + |> Stream.zip(max_lengths) + |> Enum.map(&max/1) + end) + end + + defp max({a, b}) when a >= b, do: a + defp max({_, b}), do: b + + @format "~-*s ~*s ~*s ~*s ~*s~n" + + defp print_row(row, column_lengths) do + to_print = + column_lengths + |> Stream.zip(Stream.map(row, &String.to_charlist/1)) + |> Enum.flat_map(&Tuple.to_list/1) + + :io.format(@format, to_print) + end + + defp print_function_count(count) do + IO.puts("Profile done over #{count} matching functions") + end +end diff --git a/lib/mix/test/mix/tasks/profile.tprof_test.exs b/lib/mix/test/mix/tasks/profile.tprof_test.exs new file mode 100644 index 00000000000..68c413acfc9 --- /dev/null +++ b/lib/mix/test/mix/tasks/profile.tprof_test.exs @@ -0,0 +1,123 @@ +Code.require_file("../../test_helper.exs", __DIR__) + +defmodule Mix.Tasks.Profile.TprofTest do + use MixTest.Case + + import ExUnit.CaptureIO + alias Mix.Tasks.Profile.Tprof + + @expr "Enum.each(1..5, &String.Chars.Integer.to_string/1)" + + test "profiles evaluated expression", context do + in_tmp(context.test, fn -> + assert capture_io(fn -> + Tprof.run(["-e", @expr]) + end) =~ ~r/String\.Chars\.Integer\.to_string\/1\s+\d/ + end) + end + + test "profiles evaluated expression in multiple processes", context do + in_tmp(context.test, fn -> + assert capture_io(fn -> + Tprof.run(["-e", "spawn(fn -> #{@expr} end)"]) + end) =~ ~r/String\.Chars\.Integer\.to_string\/1\s+\d/ + end) + end + + test "profiles the script", context do + in_tmp(context.test, fn -> + profile_script_name = "profile_script.ex" + File.write!(profile_script_name, @expr) + + assert capture_io(fn -> + Tprof.run([profile_script_name]) + end) =~ ~r/String\.Chars\.Integer\.to_string\/1\s+\d/ + end) + end + + test "filters based on count", context do + in_tmp(context.test, fn -> + refute capture_io(fn -> + Tprof.run(["--calls", "5", "-e", @expr]) + end) =~ ":erlang.apply/2" + end) + end + + test "sorts based on the calls count", context do + in_tmp(context.test, fn -> + assert capture_io(fn -> + Tprof.run(["--sort", "calls", "-e", @expr]) + end) =~ ~r/erlang\.apply\/2.*String\.Chars\.Integer\.to_string\/1/s + end) + end + + test "Module matching", context do + in_tmp(context.test, fn -> + refute capture_io(fn -> + Tprof.run(["--matching", "Enum", "-e", @expr]) + end) =~ ~r/String\.Chars\.Integer\.to_string\/1/ + end) + end + + test "Module.function matching", context do + in_tmp(context.test, fn -> + refute capture_io(fn -> + Tprof.run(["--matching", "Enum.each", "-e", @expr]) + end) =~ ~r/anonymous fn\/3 in Enum\.each\/2/ + end) + end + + test "Module.function/arity matching", context do + in_tmp(context.test, fn -> + assert capture_io(fn -> + Tprof.run(["--matching", "Enum.each/8", "-e", @expr]) + end) =~ ~r/Profile done over 0 matching functions/ + end) + end + + test "errors on missing files", context do + in_tmp(context.test, fn -> + message = "No files matched pattern \"non-existent\" given to --require" + + assert_raise Mix.Error, message, fn -> + capture_io(fn -> Tprof.run(["-r", "non-existent"]) end) + end + + message = "No files matched pattern \"non-existent\" given to --require" + + assert_raise Mix.Error, message, fn -> + capture_io(fn -> Tprof.run(["-pr", "non-existent"]) end) + end + + assert_raise Mix.Error, "No such file: non-existent", fn -> + capture_io(fn -> Tprof.run(["non-existent"]) end) + end + + File.mkdir_p!("lib") + + assert_raise Mix.Error, "No such file: lib", fn -> + capture_io(fn -> Tprof.run(["lib"]) end) + end + end) + end + + test "warmup", context do + in_tmp(context.test, fn -> + assert capture_io(fn -> + Tprof.run(["-e", @expr]) + end) =~ "Warmup..." + + refute capture_io(fn -> + Tprof.run(["-e", @expr, "--no-warmup"]) + end) =~ "Warmup..." + end) + end + + describe ".profile/2" do + test "returns the return value of the function call" do + capture_io(fn -> + assert 42 == Tprof.profile(fn -> 42 end) + end) + end + end +end From 9660059684860de513a52d5024a6038254eb932c Mon Sep 17 00:00:00 2001 From: sabiwara Date: Sun, 26 May 2024 17:14:41 +0900 Subject: [PATCH 2/7] Skip tests on OTP < 27 --- lib/mix/test/mix/tasks/profile.tprof_test.exs | 2 ++ 1 file changed, 2 insertions(+) diff --git a/lib/mix/test/mix/tasks/profile.tprof_test.exs b/lib/mix/test/mix/tasks/profile.tprof_test.exs index 68c413acfc9..0f6955402cd 100644 --- a/lib/mix/test/mix/tasks/profile.tprof_test.exs +++ b/lib/mix/test/mix/tasks/profile.tprof_test.exs @@ -6,6 +6,8 @@ defmodule Mix.Tasks.Profile.TprofTest do import ExUnit.CaptureIO alias Mix.Tasks.Profile.Tprof + @moduletag skip: System.otp_release() < "27" + @expr "Enum.each(1..5, &String.Chars.Integer.to_string/1)" test "profiles evaluated expression", context do From a88c9ba031732c2266452ff953cb4d7e645a34c8 Mon Sep 17 00:00:00 2001 From: sabiwara Date: Sun, 26 May 2024 17:48:33 +0900 Subject: [PATCH 3/7] Backport simplification to eprof --- lib/mix/lib/mix/tasks/profile.eprof.ex | 13 ++++--------- 1 file changed, 4 insertions(+), 9 deletions(-) diff --git a/lib/mix/lib/mix/tasks/profile.eprof.ex b/lib/mix/lib/mix/tasks/profile.eprof.ex index 14ff7413f7f..fb25222fe17 100644 --- a/lib/mix/lib/mix/tasks/profile.eprof.ex +++ b/lib/mix/lib/mix/tasks/profile.eprof.ex @@ -224,9 +224,9 @@ defmodule Mix.Tasks.Profile.Eprof do calls_opt = Keyword.get(opts, :calls, 0) time_opt = Keyword.get(opts, :time, 0) - call_results - |> Stream.filter(fn {_mfa, {count, _time}} -> count >= calls_opt end) - |> Stream.filter(fn {_mfa, {_count, time}} -> time >= time_opt end) + Enum.filter(call_results, fn {_mfa, {count, time}} -> + count >= calls_opt and time >= time_opt + end) end defp sort_results(call_results, opts) do @@ -307,15 +307,10 @@ defmodule Mix.Tasks.Profile.Eprof do max_lengths = Enum.map(header, &String.length/1) Enum.reduce(rows, max_lengths, fn row, max_lengths -> - Stream.map(row, &String.length/1) - |> Stream.zip(max_lengths) - |> Enum.map(&max/1) + Enum.zip_with(row, max_lengths, fn cell, length -> String.length(cell) |> max(length) end) end) end - defp max({a, b}) when a >= b, do: a - defp max({_, b}), do: b - @format "~-*s ~*s ~*s ~*s ~*s~n" defp print_row(row, column_lengths) do From ced76f90fdac813037b2c896314b97960305bd31 Mon Sep 17 00:00:00 2001 From: sabiwara Date: Mon, 27 May 2024 09:04:53 +0900 Subject: [PATCH 4/7] Actually implement tprof --- lib/mix/lib/mix/tasks/profile.tprof.ex | 191 ++++++++++++------ lib/mix/test/mix/tasks/profile.tprof_test.exs | 75 ++++++- 2 files changed, 198 insertions(+), 68 deletions(-) diff --git a/lib/mix/lib/mix/tasks/profile.tprof.ex b/lib/mix/lib/mix/tasks/profile.tprof.ex index 0cf3913cca4..ce98b81db81 100644 --- a/lib/mix/lib/mix/tasks/profile.tprof.ex +++ b/lib/mix/lib/mix/tasks/profile.tprof.ex @@ -6,8 +6,10 @@ defmodule Mix.Tasks.Profile.Tprof do @moduledoc """ Profiles the given file or expression using Erlang's `tprof` tool. - [`:tprof`](`:tprof`) provides time information of each function call and can be useful - when you want to discover the bottlenecks related to this. + Requires Erlang/OTP27 or above. + + [`:tprof`](`:tprof`) can provide time or memory information of each function call + and can be useful when you want to discover the bottlenecks related to these. Before running the code, it invokes the `app.start` task which compiles and loads your project. After that, the target expression is profiled together @@ -21,15 +23,26 @@ defmodule Mix.Tasks.Profile.Tprof do $ mix profile.tprof -e "[1, 2, 3] |> Enum.reverse |> Enum.map(&Integer.to_string/1)" $ mix profile.tprof my_script.exs arg1 arg2 arg3 + By default, tprof uses the `time` type, but you can profile memory too: + + $ mix profile.tprof -e "Enum.map([1, 2, 3], &Integer.to_string/1)" --type memory + + Call count is present with both type `time` and `memory`, but if you only need + the call count information, you can use the type `calls`: + + $ mix profile.tprof -e "Enum.map([1, 2, 3], &Integer.to_string/1)" --type calls + This task is automatically re-enabled, so you can profile multiple times in the same Mix invocation. ## Command line options * `--matching` - only profile calls matching the given `Module.function/arity` pattern + * `--type` - the type of profiling, `calls`, `time` or `memory` (default: `time`) * `--calls` - filters out any results with a call count lower than this - * `--time` - filters out any results that took lower than specified (in µs) - * `--sort` - sorts the results by `time` or `calls` (default: `time`) + * `--time` - filters out any results that took lower than specified (in µs), the `type` needs to be `time` + * `--memory` - filters out any results that used less memory than specified (in words), the `type` needs to be `memory` + * `--sort` - sorts the results by `calls` or by the value of `type` (default: the value of `type`) * `--eval`, `-e` - evaluates the given code * `--require`, `-r` - requires pattern before running the command * `--parallel`, `-p` - makes all requires parallel @@ -106,8 +119,10 @@ defmodule Mix.Tasks.Profile.Tprof do halt: :boolean, compile: :boolean, deps_check: :boolean, + type: :string, calls: :integer, time: :integer, + memory: :integer, sort: :string, start: :boolean, archives_check: :boolean, @@ -163,8 +178,14 @@ defmodule Mix.Tasks.Profile.Tprof do end end + defp parse_opt({:type, "time"}), do: {:type, :time} + defp parse_opt({:type, "calls"}), do: {:type, :calls} + defp parse_opt({:type, "memory"}), do: {:type, :memory} + defp parse_opt({:type, other}), do: Mix.raise("Invalid type option: #{other}") + defp parse_opt({:sort, "time"}), do: {:sort, :time} defp parse_opt({:sort, "calls"}), do: {:sort, :calls} + defp parse_opt({:sort, "memory"}), do: {:sort, :memory} defp parse_opt({:sort, other}), do: Mix.raise("Invalid sort option: #{other}") defp parse_opt(other), do: other @@ -178,9 +199,16 @@ defmodule Mix.Tasks.Profile.Tprof do * `:matching` - only profile calls matching the given pattern in form of `{module, function, arity}`, where each element may be replaced by `:_` to allow any value + * `:type` - the type of profiling, possible values are `:time`, `:memory` or `:calls`, + (default: `:time`), see [moduledoc](`Mix.Tasks.Profile.Tprof`) for more information + * `:calls` - filters out any results with a call count lower than this - * `:time` - filters out any results that took lower than specified (in µs) - * `:sort` - sort the results by `:time` or `:calls` (default: `:time`) + * `:time` - filters out any results that took lower than specified (in µs), + `type` needs to be `:time` + * `:memory` - filters out any results that used less memory than specified (in words), + `type` needs to be `:memory` + * `:sort` - sort the results by `:calls` or by the value of `type` + (default: the value of `type`) * `:warmup` - if the code should be warmed up before profiling (default: `true`) * `:set_on_spawn` - if newly spawned processes should be measured (default: `true`) @@ -188,8 +216,8 @@ defmodule Mix.Tasks.Profile.Tprof do @spec profile((-> result), keyword()) :: result when result: any() def profile(fun, opts \\ []) when is_function(fun, 0) do Mix.ensure_application!(:tools) - {return_value, results} = profile_and_analyse(fun, opts) - print_output(results) + {type, return_value, results} = profile_and_analyse(fun, opts) + print_output(type, results) return_value end @@ -202,101 +230,141 @@ defmodule Mix.Tasks.Profile.Tprof do :tprof.start() matching = Keyword.get(opts, :matching, {:_, :_, :_}) set_on_spawn = Keyword.get(opts, :set_on_spawn, true) - {:ok, return_value} = :tprof.profile([], fun, matching, set_on_spawn: set_on_spawn) + type = Keyword.get(opts, :type, :time) + + sort_by = + case Keyword.get(opts, :sort) do + nil -> :measurement + :calls -> :calls + ^type -> :measurement + other -> Mix.raise("Incompatible sort option `#{other}` with type `#{type}`") + end + + tprof_type = to_tprof_type(type) + + {return_value, {^tprof_type, traces}} = + :tprof.profile(fun, %{ + set_on_spawn: set_on_spawn, + pattern: matching, + type: tprof_type, + report: :return + }) + + inspected = :tprof.inspect({tprof_type, traces}, :process, sort_by) + + :tprof.stop() results = - Enum.map(:tprof.dump(), fn {pid, call_results} -> + inspected + |> Enum.map(fn {pid, {^tprof_type, measurement_total, call_results}} -> parsed_calls = call_results - |> filter_results(opts) - |> sort_results(opts) - |> add_totals() + |> filter_results(type, opts) + |> add_totals(measurement_total) {pid, parsed_calls} end) - :tprof.stop() - - {return_value, results} + {type, return_value, results} end - defp filter_results(call_results, opts) do + defp to_tprof_type(:calls), do: :call_count + defp to_tprof_type(:time), do: :call_time + defp to_tprof_type(:memory), do: :call_memory + + defp filter_results(call_results, type, opts) do calls_opt = Keyword.get(opts, :calls, 0) - time_opt = Keyword.get(opts, :time, 0) - call_results - |> Stream.filter(fn {_mfa, {count, _time}} -> count >= calls_opt end) - |> Stream.filter(fn {_mfa, {_count, time}} -> time >= time_opt end) + measurement_opt = + get_filter_value!(type, Keyword.get(opts, :time), Keyword.get(opts, :memory)) + + Enum.filter(call_results, fn {_module, _fa, count, measurement, _, _} -> + count >= calls_opt and measurement >= measurement_opt + end) end - defp sort_results(call_results, opts) do - Enum.sort_by(call_results, sort_function(Keyword.get(opts, :sort, :time))) + defp get_filter_value!(type, time, _memory) when is_integer(time) and type != :time do + Mix.raise("Incompatible use of time option with type `#{type}`") end - defp sort_function(:time), do: fn {_mfa, {_count, time}} -> time end - defp sort_function(:calls), do: fn {_mfa, {count, _time}} -> count end + defp get_filter_value!(type, _time, memory) when is_integer(memory) and type != :memory do + Mix.raise("Incompatible use of memory option with type `#{type}`") + end + + defp get_filter_value!(:time, time, nil) when is_integer(time), do: time + defp get_filter_value!(:memory, nil, memory) when is_integer(memory), do: memory + + defp get_filter_value!(_, nil, nil), do: 0 - defp add_totals(call_results) do - {function_count, call_count, total_time} = - Enum.reduce(call_results, {0, 0, 0}, fn {_, {count, time}}, acc -> - {function_count, call_count, total_time} = acc - {function_count + 1, call_count + count, total_time + time} + defp add_totals(call_results, measurement_total) do + {function_count, calls} = + Enum.reduce(call_results, {0, 0}, fn {_mod, _fa, count, _, _, _}, acc -> + {function_count, calls} = acc + {function_count + 1, calls + count} end) - {function_count, call_results, call_count, total_time} + {function_count, call_results, calls, measurement_total} end - @header ["#", "CALLS", "%", "TIME", "µS/CALL"] - - defp print_output([]) do + defp print_output(_type, []) do print_function_count(0) end - defp print_output(results) do - Enum.each(results, &print_result/1) + defp print_output(type, results) do + Enum.each(results, &print_result(type, &1)) end - defp print_result({pid, {function_count, call_results, call_count, total_time}}) do - formatted_rows = Enum.map(call_results, &format_row(&1, total_time)) - formatted_total = format_total(total_time, call_count) + defp print_result(type, {pid, {function_count, call_results, calls, total_measurement}}) do + header = header(type) + + formatted_rows = Enum.map(call_results, &format_row/1) + formatted_total = format_total(total_measurement, calls) - column_lengths = column_lengths(@header, formatted_rows) + column_lengths = column_lengths(header, [formatted_total | formatted_rows]) IO.puts("") print_pid_row(pid) - print_row(@header, column_lengths) - print_row(formatted_total, column_lengths) - Enum.each(formatted_rows, &print_row(&1, column_lengths)) + print_row(header, column_lengths, type) + print_row(formatted_total, column_lengths, type) + Enum.each(formatted_rows, &print_row(&1, column_lengths, type)) IO.puts("") print_function_count(function_count) end - defp print_pid_row(pid) do + defp header(:calls), do: ["#", "CALLS", "%"] + defp header(:time), do: ["#", "CALLS", "%", "TIME", "µS/CALL"] + defp header(:memory), do: ["#", "CALLS", "%", "WORDS", "PER CALL"] + + defp print_pid_row(:all) do + IO.puts("Profile results over all processes") + end + + defp print_pid_row(pid) when is_pid(pid) do IO.puts("Profile results of #{inspect(pid)}") end - defp format_row({{module, function, arity}, {count, time}}, total_time) do + defp format_row({module, {function, arity}, count, measurement, per_call, percentage}) do mfa = Exception.format_mfa(module, function, arity) - time_percentage = :erlang.float_to_binary(100 * divide(time, total_time), [{:decimals, 2}]) - time_per_call = :erlang.float_to_binary(divide(time, count), [{:decimals, 2}]) + percentage = :erlang.float_to_binary(percentage, [{:decimals, 2}]) + per_call = :erlang.float_to_binary(per_call, [{:decimals, 2}]) count = Integer.to_string(count) - time = Integer.to_string(time) + measurement = Integer.to_string(measurement) - [mfa, count, time_percentage, time, time_per_call] + [mfa, count, percentage, measurement, per_call] end - defp format_total(total_time, total_count) do - time_per_call = :erlang.float_to_binary(divide(total_time, total_count), [{:decimals, 2}]) + defp format_total(total_measurement, total_count) do + per_call = :erlang.float_to_binary(divide(total_measurement, total_count), [{:decimals, 2}]) [ "Total", Integer.to_string(total_count), "100.00", - Integer.to_string(total_time), - time_per_call + Integer.to_string(total_measurement), + per_call ] end @@ -307,24 +375,23 @@ defmodule Mix.Tasks.Profile.Tprof do max_lengths = Enum.map(header, &String.length/1) Enum.reduce(rows, max_lengths, fn row, max_lengths -> - Stream.map(row, &String.length/1) - |> Stream.zip(max_lengths) - |> Enum.map(&max/1) + Enum.zip_with(row, max_lengths, fn cell, length -> String.length(cell) |> max(length) end) end) end - defp max({a, b}) when a >= b, do: a - defp max({_, b}), do: b - - @format "~-*s ~*s ~*s ~*s ~*s~n" + @call_format "~-*s ~*s ~*s~n" + @measurement_format "~-*s ~*s ~*s ~*s ~*s~n" - defp print_row(row, column_lengths) do + defp print_row(row, column_lengths, type) do to_print = column_lengths |> Stream.zip(Stream.map(row, &String.to_charlist/1)) |> Enum.flat_map(&Tuple.to_list/1) - :io.format(@format, to_print) + case type do + :calls -> :io.format(@call_format, to_print) + _ -> :io.format(@measurement_format, to_print) + end end defp print_function_count(count) do diff --git a/lib/mix/test/mix/tasks/profile.tprof_test.exs b/lib/mix/test/mix/tasks/profile.tprof_test.exs index 0f6955402cd..fb5f5af49cf 100644 --- a/lib/mix/test/mix/tasks/profile.tprof_test.exs +++ b/lib/mix/test/mix/tasks/profile.tprof_test.exs @@ -37,19 +37,54 @@ defmodule Mix.Tasks.Profile.TprofTest do end) end - test "filters based on count", context do + test "filters based on calls count", context do in_tmp(context.test, fn -> - refute capture_io(fn -> - Tprof.run(["--calls", "5", "-e", @expr]) - end) =~ ":erlang.apply/2" + result = + capture_io(fn -> + Tprof.run(["--calls", "5", "-e", @expr]) + end) + + assert result =~ "\nString.Chars.Integer.to_string/1" + refute result =~ "\nEnum.each/2" + end) + end + + test "filters based on time", context do + in_tmp(context.test, fn -> + result = + capture_io(fn -> + Tprof.run(["--time", "50", "-e", @expr]) + end) + + refute result =~ "\nEnum.each/2" + end) + end + + test "filters based on memory", context do + in_tmp(context.test, fn -> + result = + capture_io(fn -> + Tprof.run(["--type", "memory", "--memory", "10", "-e", @expr]) + end) + + assert result =~ "\n:erlang.integer_to_binary/1" + refute result =~ "\nEnum.each/2" end) end - test "sorts based on the calls count", context do + test "sorts based on calls count", context do in_tmp(context.test, fn -> assert capture_io(fn -> Tprof.run(["--sort", "calls", "-e", @expr]) - end) =~ ~r/erlang\.apply\/2.*String\.Chars\.Integer\.to_string\/1/s + end) =~ ~r/Enum\.each\/2.*String\.Chars\.Integer\.to_string\/1/s + end) + end + + test "sorts based on memory usage", context do + in_tmp(context.test, fn -> + assert capture_io(fn -> + Tprof.run(["--type", "memory", "--sort", "calls", "-e", @expr]) + end) =~ ~r/Enum\.each\/2.*:erlang\.integer_to_binary\/1/s end) end @@ -115,6 +150,34 @@ defmodule Mix.Tasks.Profile.TprofTest do end) end + test "errors on incompatible options", context do + in_tmp(context.test, fn -> + message = "Incompatible sort option `memory` with type `time`" + + assert_raise Mix.Error, message, fn -> + capture_io(fn -> Tprof.run(["-e", @expr, "--sort", "memory"]) end) + end + + message = "Incompatible sort option `time` with type `calls`" + + assert_raise Mix.Error, message, fn -> + capture_io(fn -> Tprof.run(["-e", @expr, "--type", "calls", "--sort", "time"]) end) + end + + message = "Incompatible use of memory option with type `time`" + + assert_raise Mix.Error, message, fn -> + capture_io(fn -> Tprof.run(["-e", @expr, "--time", "1", "--memory", "2"]) end) + end + + message = "Incompatible use of time option with type `calls`" + + assert_raise Mix.Error, message, fn -> + capture_io(fn -> Tprof.run(["-e", @expr, "--type", "calls", "--time", "1"]) end) + end + end) + end + describe ".profile/2" do test "returns the return value of the function call" do capture_io(fn -> From bdea2593f28c3f3fc2db8922e04a77cff7a03fbd Mon Sep 17 00:00:00 2001 From: sabiwara Date: Mon, 27 May 2024 09:38:31 +0900 Subject: [PATCH 5/7] Fix CI and raise if :tprof is not present --- lib/mix/lib/mix/tasks/profile.tprof.ex | 17 +++++++++++++---- lib/mix/test/mix/tasks/profile.tprof_test.exs | 1 + 2 files changed, 14 insertions(+), 4 deletions(-) diff --git a/lib/mix/lib/mix/tasks/profile.tprof.ex b/lib/mix/lib/mix/tasks/profile.tprof.ex index ce98b81db81..aeb122f5c20 100644 --- a/lib/mix/lib/mix/tasks/profile.tprof.ex +++ b/lib/mix/lib/mix/tasks/profile.tprof.ex @@ -227,7 +227,7 @@ defmodule Mix.Tasks.Profile.Tprof do fun.() end - :tprof.start() + tprof_module().start() matching = Keyword.get(opts, :matching, {:_, :_, :_}) set_on_spawn = Keyword.get(opts, :set_on_spawn, true) type = Keyword.get(opts, :type, :time) @@ -243,16 +243,16 @@ defmodule Mix.Tasks.Profile.Tprof do tprof_type = to_tprof_type(type) {return_value, {^tprof_type, traces}} = - :tprof.profile(fun, %{ + tprof_module().profile(fun, %{ set_on_spawn: set_on_spawn, pattern: matching, type: tprof_type, report: :return }) - inspected = :tprof.inspect({tprof_type, traces}, :process, sort_by) + inspected = tprof_module().inspect({tprof_type, traces}, :process, sort_by) - :tprof.stop() + tprof_module().stop() results = inspected @@ -397,4 +397,13 @@ defmodule Mix.Tasks.Profile.Tprof do defp print_function_count(count) do IO.puts("Profile done over #{count} matching functions") end + + # TODO remove once we require Erlang/OTP 27+ + defp tprof_module do + if Code.ensure_loaded?(:tprof) do + :tprof + else + Mix.raise("mix profile.tprof requires Erlang/OTP 27 or above") + end + end end diff --git a/lib/mix/test/mix/tasks/profile.tprof_test.exs b/lib/mix/test/mix/tasks/profile.tprof_test.exs index fb5f5af49cf..87a4bf2b147 100644 --- a/lib/mix/test/mix/tasks/profile.tprof_test.exs +++ b/lib/mix/test/mix/tasks/profile.tprof_test.exs @@ -6,6 +6,7 @@ defmodule Mix.Tasks.Profile.TprofTest do import ExUnit.CaptureIO alias Mix.Tasks.Profile.Tprof + # TODO remove once we require Erlang/OTP 27+ @moduletag skip: System.otp_release() < "27" @expr "Enum.each(1..5, &String.Chars.Integer.to_string/1)" From 27e56dc01ae5ff6f97c5d175237515bd2226ff4c Mon Sep 17 00:00:00 2001 From: sabiwara Date: Mon, 27 May 2024 19:22:11 +0900 Subject: [PATCH 6/7] Apply review suggestions --- lib/mix/lib/mix/tasks/profile.tprof.ex | 22 +++++++++++-------- lib/mix/test/mix/tasks/profile.tprof_test.exs | 8 +++---- 2 files changed, 17 insertions(+), 13 deletions(-) diff --git a/lib/mix/lib/mix/tasks/profile.tprof.ex b/lib/mix/lib/mix/tasks/profile.tprof.ex index aeb122f5c20..6e9bf15ca33 100644 --- a/lib/mix/lib/mix/tasks/profile.tprof.ex +++ b/lib/mix/lib/mix/tasks/profile.tprof.ex @@ -227,17 +227,23 @@ defmodule Mix.Tasks.Profile.Tprof do fun.() end - tprof_module().start() matching = Keyword.get(opts, :matching, {:_, :_, :_}) set_on_spawn = Keyword.get(opts, :set_on_spawn, true) type = Keyword.get(opts, :type, :time) sort_by = case Keyword.get(opts, :sort) do - nil -> :measurement - :calls -> :calls - ^type -> :measurement - other -> Mix.raise("Incompatible sort option `#{other}` with type `#{type}`") + nil -> + :measurement + + :calls -> + :calls + + ^type -> + :measurement + + other -> + Mix.raise("Incompatible sort option #{inspect(other)} with type #{inspect(type)}") end tprof_type = to_tprof_type(type) @@ -252,8 +258,6 @@ defmodule Mix.Tasks.Profile.Tprof do inspected = tprof_module().inspect({tprof_type, traces}, :process, sort_by) - tprof_module().stop() - results = inspected |> Enum.map(fn {pid, {^tprof_type, measurement_total, call_results}} -> @@ -284,11 +288,11 @@ defmodule Mix.Tasks.Profile.Tprof do end defp get_filter_value!(type, time, _memory) when is_integer(time) and type != :time do - Mix.raise("Incompatible use of time option with type `#{type}`") + Mix.raise("Incompatible use of time option with type #{inspect(type)}") end defp get_filter_value!(type, _time, memory) when is_integer(memory) and type != :memory do - Mix.raise("Incompatible use of memory option with type `#{type}`") + Mix.raise("Incompatible use of memory option with type #{inspect(type)}") end defp get_filter_value!(:time, time, nil) when is_integer(time), do: time diff --git a/lib/mix/test/mix/tasks/profile.tprof_test.exs b/lib/mix/test/mix/tasks/profile.tprof_test.exs index 87a4bf2b147..e8f55280021 100644 --- a/lib/mix/test/mix/tasks/profile.tprof_test.exs +++ b/lib/mix/test/mix/tasks/profile.tprof_test.exs @@ -153,25 +153,25 @@ defmodule Mix.Tasks.Profile.TprofTest do test "errors on incompatible options", context do in_tmp(context.test, fn -> - message = "Incompatible sort option `memory` with type `time`" + message = "Incompatible sort option :memory with type :time" assert_raise Mix.Error, message, fn -> capture_io(fn -> Tprof.run(["-e", @expr, "--sort", "memory"]) end) end - message = "Incompatible sort option `time` with type `calls`" + message = "Incompatible sort option :time with type :calls" assert_raise Mix.Error, message, fn -> capture_io(fn -> Tprof.run(["-e", @expr, "--type", "calls", "--sort", "time"]) end) end - message = "Incompatible use of memory option with type `time`" + message = "Incompatible use of memory option with type :time" assert_raise Mix.Error, message, fn -> capture_io(fn -> Tprof.run(["-e", @expr, "--time", "1", "--memory", "2"]) end) end - message = "Incompatible use of time option with type `calls`" + message = "Incompatible use of time option with type :calls" assert_raise Mix.Error, message, fn -> capture_io(fn -> Tprof.run(["-e", @expr, "--type", "calls", "--time", "1"]) end) From adf24b64a1cfafd1433d074e8fcc8a44bf724bdc Mon Sep 17 00:00:00 2001 From: sabiwara Date: Mon, 27 May 2024 21:13:13 +0900 Subject: [PATCH 7/7] Write moduledoc for tprof --- lib/mix/lib/mix/tasks/profile.tprof.ex | 76 ++++++++++++++++++-------- 1 file changed, 52 insertions(+), 24 deletions(-) diff --git a/lib/mix/lib/mix/tasks/profile.tprof.ex b/lib/mix/lib/mix/tasks/profile.tprof.ex index 6e9bf15ca33..51ad7a7467f 100644 --- a/lib/mix/lib/mix/tasks/profile.tprof.ex +++ b/lib/mix/lib/mix/tasks/profile.tprof.ex @@ -8,8 +8,11 @@ defmodule Mix.Tasks.Profile.Tprof do Requires Erlang/OTP27 or above. - [`:tprof`](`:tprof`) can provide time or memory information of each function call - and can be useful when you want to discover the bottlenecks related to these. + [`:tprof`](`:tprof`) is an experimental module introduced in Erlang/OTP 27 which + provides a unified API for measuring call count, time, and allocation, and aims to + replace [`:eprof`](`:eprof`) and [`:cprof`](`:cprof`). + It can be useful when you want to discover the bottlenecks related to any of these + measurements. Before running the code, it invokes the `app.start` task which compiles and loads your project. After that, the target expression is profiled together @@ -28,7 +31,7 @@ defmodule Mix.Tasks.Profile.Tprof do $ mix profile.tprof -e "Enum.map([1, 2, 3], &Integer.to_string/1)" --type memory Call count is present with both type `time` and `memory`, but if you only need - the call count information, you can use the type `calls`: + the call count information, you can use the type `calls` which has the lowest footprint: $ mix profile.tprof -e "Enum.map([1, 2, 3], &Integer.to_string/1)" --type calls @@ -56,34 +59,59 @@ defmodule Mix.Tasks.Profile.Tprof do ## Profile output - Example output: + Example output (`time` type): - # CALLS % TIME µS/CALL - Total 24 100.0 26 1.08 - Enum.reduce_range_inc/4 5 3.85 1 0.20 - :erlang.make_fun/3 1 7.69 2 2.00 - Enum.each/2 1 7.69 2 2.00 - anonymous fn/0 in :elixir_compiler_0.__FILE__/1 1 7.69 2 2.00 - :erlang.integer_to_binary/1 5 15.39 4 0.80 - :erlang.apply/2 1 15.39 4 4.00 - anonymous fn/3 in Enum.each/2 5 19.23 5 1.00 - String.Chars.Integer.to_string/1 5 23.08 6 1.20 + Profile results of #PID<0.107.0> + # CALLS % TIME µS/CALL + Total 20 100.00 2 0.10 + String.Chars.Integer.to_string/1 5 0.00 0 0.00 + anonymous fn/0 in :elixir_compiler_1.__FILE__/1 1 0.00 0 0.00 + Enum.each/2 1 0.00 0 0.00 + Enum.reduce_range/5 3 0.00 0 0.00 + :erlang.integer_to_binary/1 5 50.00 1 0.20 + anonymous fn/3 in Enum.each/2 5 50.00 1 0.20 - Profile done over 8 matching functions + Profile done over 6 matching functions + + Example output (`memory` type): + + Profile results of #PID<0.107.0> + # CALLS % WORDS PER CALL + Total 6 100.00 19 3.17 + Enum.each/2 1 21.05 4 4.00 + :erlang.integer_to_binary/1 5 78.95 15 3.00 + + Profile done over 2 matching functions + + Example output (`calls` type) + + Profile results over all processes + # CALLS % + Total 20 100.00 + anonymous fn/0 in :elixir_compiler_1.__FILE__/1 1 5.00 + Enum.each/2 1 5.00 + Enum.reduce_range/5 3 15.00 + :erlang.integer_to_binary/1 5 25.00 + String.Chars.Integer.to_string/1 5 25.00 + anonymous fn/3 in Enum.each/2 5 25.00 + + Profile done over 6 matching functions The default output contains data gathered from all matching functions. The first row after the header contains the sums of the partial results and the average time - for all the function calls listed. The following rows contain the function call, - followed by the number of times that the function was called, then by the percentage - of time that the call uses, then the total time for that function in microseconds, - and, finally, the average time per call in microseconds. + or memory usage for all the function calls listed. + The following rows contain the function call, followed by the number of times that + the function was called, then by the percentage of time/memory that the call uses, + then the total time/memory for that function in microseconds/words, and, finally, + the average time/memory per call in microseconds/words. When `--matching` option is specified, call count tracing will be started only for the functions matching the given pattern: - # CALLS % TIME µS/CALL - Total 5 100.0 6 1.20 - String.Chars.Integer.to_string/1 5 100.0 6 1.20 + Profile results of #PID<0.106.0> + # CALLS % TIME µS/CALL + Total 5 100.00 1 0.20 + String.Chars.Integer.to_string/1 5 100.00 1 0.20 Profile done over 1 matching functions @@ -106,8 +134,8 @@ defmodule Mix.Tasks.Profile.Tprof do You should expect a slowdown in your code execution using this tool since `:tprof` has some performance impact on the execution, but the impact is considerably lower than `Mix.Tasks.Profile.Fprof`. If you have a large system try to profile a limited - scenario or focus on the main modules or processes. Another alternative is to use - `Mix.Tasks.Profile.Cprof` that uses [`:cprof`](`:cprof`) and has a low performance degradation effect. + scenario or focus on the main modules or processes. The `calls` type can also be used, + which is more limited but has a lower footprint. """ @switches [