1defmodule Mix.Tasks.Profile.Cprof do
2  use Mix.Task
3
4  @shortdoc "Profiles the given file or expression with cprof"
5
6  @moduledoc """
7  Profiles the given file or expression using Erlang's `cprof` tool.
8
9  `cprof` can be useful when you want to discover the bottlenecks related
10  to function calls.
11
12  Before running the code, it invokes the `app.start` task which compiles
13  and loads your project. After that, the target expression is profiled together
14  with all matching function calls, by setting breakpoints containing
15  counters. These can only be set on BEAM code so BIFs cannot be call
16  count traced.
17
18  To profile the code, you can use syntax similar to the `mix run` task:
19
20      mix profile.cprof -e Hello.world
21      mix profile.cprof -e "[1, 2, 3] |> Enum.reverse |> Enum.map(&Integer.to_string/1)"
22      mix profile.cprof my_script.exs arg1 arg2 arg3
23
24  This task is automatically reenabled, so you can profile multiple times
25  in the same Mix invocation.
26
27  ## Command line options
28
29    * `--matching` - only profile calls matching the given `Module.function/arity` pattern
30    * `--limit` - filters out any results with a call count less than the limit
31    * `--module` - filters out any results not pertaining to the given module
32    * `--eval`, `-e` - evaluate the given code
33    * `--require`, `-r` - requires pattern before running the command
34    * `--parallel`, `-p` - makes all requires parallel
35    * `--no-compile` - does not compile even if files require compilation
36    * `--no-deps-check` - does not check dependencies
37    * `--no-archives-check` - does not check archives
38    * `--no-halt` - does not halt the system after running the command
39    * `--no-start` - does not start applications after compilation
40    * `--no-elixir-version-check` - does not check the Elixir version from mix.exs
41
42  ## Profile output
43
44  Example output:
45                                                                           CNT
46      Total                                                                 15
47      Enum                                                                   6  <--
48        Enum."-map/2-lists^map/1-0-"/2                                       4
49        Enum.reverse/1                                                       1
50        Enum.map/2                                                           1
51      :elixir_compiler                                                       4  <--
52        anonymous fn/1 in :elixir_compiler.__FILE__/1                        3
53        anonymous fn/0 in :elixir_compiler.__FILE__/1                        1
54      String.Chars.Integer                                                   3  <--
55        String.Chars.Integer.to_string/1                                     3
56      :erlang                                                                2  <--
57        :erlang.trace_pattern/3                                              2
58      Profile done over 20229 matching functions
59
60  The default output contains data gathered from all matching functions. The left
61  column structures each module and its total call count trace is presented on the right.
62  Each module has its count discriminated by function below. The `<--` symbol is meant to
63  help visualize where a new module call count begins.
64
65  The first row (Total) is the sum of all function calls. In the last row the number of
66  matching functions that were considered for profiling is presented.
67
68  When `--matching` option is specified, call count tracing will be started only for
69  the functions matching the given pattern:
70
71      String.Chars.Integer                                                   3  <--
72        String.Chars.Integer.to_string/1                                     3
73      Profile done over 1 matching functions
74
75  The pattern can be a module name, such as `String` to count all calls to that module,
76  a call without arity, such as `String.split`, to count all calls to that function
77  regardless of arity, or a call with arity, such as `String.split/2`, to count all
78  calls to that exact module, function and arity.
79
80  ## Caveats
81
82  You should be aware the profiler is stopped as soon as the code has finished running. This
83  may need special attention, when:  running asynchronous code as function calls which were
84  called before the profiler stopped will not be counted; running synchronous code as long
85  running computations and a profiler without a proper MFA trace pattern or filter may
86  lead to a result set which is difficult to comprehend.
87
88  Other caveats are the impossibility to call count trace BIFs, since breakpoints can
89  only be set on BEAM code; functions calls performed by `:cprof` are not traced; the
90  maximum size of a call counter is equal to the host machine's word size
91  (for example, 2147483647 in a 32-bit host).
92  """
93
94  @switches [
95    parallel: :boolean,
96    require: :keep,
97    eval: :keep,
98    config: :keep,
99    matching: :string,
100    halt: :boolean,
101    compile: :boolean,
102    deps_check: :boolean,
103    limit: :integer,
104    module: :string,
105    start: :boolean,
106    archives_check: :boolean,
107    warmup: :boolean,
108    elixir_version_check: :boolean,
109    parallel_require: :keep
110  ]
111
112  @aliases [r: :require, p: :parallel, e: :eval, c: :config]
113
114  @impl true
115  def run(args) do
116    {opts, head} = OptionParser.parse_head!(args, aliases: @aliases, strict: @switches)
117    Mix.Task.reenable("profile.cprof")
118
119    Mix.Tasks.Run.run(
120      ["--no-mix-exs" | args],
121      opts,
122      head,
123      &profile_code(&1, opts),
124      &profile_code(File.read!(&1), opts)
125    )
126  end
127
128  defp profile_code(code_string, opts) do
129    opts = Enum.map(opts, &parse_opt/1)
130
131    content =
132      quote do
133        unquote(__MODULE__).profile(
134          fn ->
135            unquote(Code.string_to_quoted!(code_string))
136          end,
137          unquote(Macro.escape(opts))
138        )
139      end
140
141    # Use compile_quoted since it leaves less noise than eval_quoted
142    Code.compile_quoted(content)
143  end
144
145  defp parse_opt({:matching, matching}) do
146    case Mix.Utils.parse_mfa(matching) do
147      {:ok, [m, f, a]} -> {:matching, {m, f, a}}
148      {:ok, [m, f]} -> {:matching, {m, f, :_}}
149      {:ok, [m]} -> {:matching, {m, :_, :_}}
150      :error -> Mix.raise("Invalid matching pattern: #{matching}")
151    end
152  end
153
154  defp parse_opt({:module, module}), do: {:module, string_to_existing_module(module)}
155  defp parse_opt(other), do: other
156
157  @doc """
158  Allows to programmatically run the `cprof` profiler on expression in `fun`.
159
160  ## Options
161
162    * `:matching` - only profile calls matching the given pattern in form of
163      `{module, function, arity}`, where each element may be replaced by `:_`
164      to allow any value
165    * `:limit` - filters out any results with a call count less than the limit
166    * `:module` - filters out any results not pertaining to the given module
167
168  """
169  def profile(fun, opts \\ []) when is_function(fun, 0) do
170    fun
171    |> profile_and_analyse(opts)
172    |> print_output
173
174    :cprof.stop()
175  end
176
177  defp profile_and_analyse(fun, opts) do
178    if Keyword.get(opts, :warmup, true) do
179      IO.puts("Warmup...")
180      fun.()
181    end
182
183    num_matched_functions =
184      case Keyword.fetch(opts, :matching) do
185        {:ok, matching} -> :cprof.start(matching)
186        :error -> :cprof.start()
187      end
188
189    apply(fun, [])
190
191    :cprof.pause()
192
193    limit = Keyword.get(opts, :limit)
194    module = Keyword.get(opts, :module)
195
196    analysis_result =
197      case {limit, module} do
198        {nil, nil} ->
199          :cprof.analyse()
200
201        {limit, nil} ->
202          :cprof.analyse(limit)
203
204        {limit, module} ->
205          if limit do
206            :cprof.analyse(module, limit)
207          else
208            :cprof.analyse(module)
209          end
210      end
211
212    {num_matched_functions, analysis_result}
213  end
214
215  defp string_to_existing_module(":" <> module), do: String.to_existing_atom(module)
216  defp string_to_existing_module(module), do: Module.concat([module])
217
218  defp print_output({num_matched_functions, {all_call_count, mod_analysis_list}}) do
219    print_total_row(all_call_count)
220    Enum.each(mod_analysis_list, &print_analysis_result/1)
221    print_number_of_matched_functions(num_matched_functions)
222  end
223
224  defp print_output({num_matched_functions, {_mod, _call_count, _mod_fun_list} = mod_analysis}) do
225    print_analysis_result(mod_analysis)
226    print_number_of_matched_functions(num_matched_functions)
227  end
228
229  defp print_number_of_matched_functions(num_matched_functions) do
230    IO.puts("Profile done over #{num_matched_functions} matching functions")
231  end
232
233  defp print_total_row(all_call_count) do
234    IO.puts("")
235    print_row(["s", "s", "s"], ["", "CNT", ""])
236    print_row(["s", "B", "s"], ["Total", all_call_count, ""])
237  end
238
239  defp print_analysis_result({module, total_module_count, module_fun_list}) do
240    module
241    |> Atom.to_string()
242    |> module_name_for_printing()
243    |> print_module(total_module_count, "", "<--")
244
245    Enum.each(module_fun_list, &print_function(&1, "  "))
246  end
247
248  defp print_module(module, count, prefix, suffix) do
249    print_row(["s", "B", "s"], ["#{prefix}#{module}", count, suffix])
250  end
251
252  defp module_name_for_printing("Elixir." <> rest = _module_name), do: rest
253  defp module_name_for_printing(module_name), do: ":" <> module_name
254
255  defp print_function({fun, count}, prefix, suffix \\ "") do
256    print_row(["s", "B", "s"], ["#{prefix}#{function_text(fun)}", count, suffix])
257  end
258
259  defp function_text({module, function, arity}) do
260    Exception.format_mfa(module, function, arity)
261  end
262
263  defp function_text(other), do: inspect(other)
264
265  @columns [-60, 12, 5]
266  defp print_row(formats, data) do
267    Stream.zip(@columns, formats)
268    |> Stream.map(fn {width, format} -> "~#{width}#{format}" end)
269    |> Enum.join()
270    |> :io.format(data)
271
272    IO.puts("")
273  end
274end
275