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