Measure each_cycle callback + deadlock detection (#13941)

lib/elixir/lib/kernel/parallel_compiler.ex

@@ -475,7 +475,7 @@ defmodule Kernel.ParallelCompiler do
     end)
 
     [] = files
-    cycle_return = each_cycle_return(state.each_cycle.())
+    cycle_return = measure_timing(state, "each_cycle callback", fn -> each_cycle_return(state.each_cycle.()) end)
     state = cycle_timing(result, state)
 
     case cycle_return do
@@ -519,21 +519,23 @@ defmodule Kernel.ParallelCompiler do
     # Finally, note there is no difference between hard and raise, the
     # difference is where the raise is happening, inside the compiler
     # or in the caller.
-    waiting_list = Map.to_list(waiting)
+    measure_timing(state, "spawn_workers/8 in potential deadlock situation", fn ->
+      waiting_list = Map.to_list(waiting)
 
-    deadlocked =
-      deadlocked(waiting_list, :soft, false) ||
-        deadlocked(waiting_list, :soft, true) ||
-        deadlocked(waiting_list, :hard, false) ||
-        without_definition(waiting_list, files)
+      deadlocked =
+        deadlocked(waiting_list, :soft, false) ||
+          deadlocked(waiting_list, :soft, true) ||
+          deadlocked(waiting_list, :hard, false) ||
+          without_definition(waiting_list, files)
 
-    if deadlocked do
-      spawn_workers(deadlocked, spawned, waiting, files, result, warnings, errors, state)
-    else
-      return_error(warnings, errors, state, fn ->
-        handle_deadlock(waiting, files)
-      end)
-    end
+      if deadlocked do
+        spawn_workers(deadlocked, spawned, waiting, files, result, warnings, errors, state)
+      else
+        return_error(warnings, errors, state, fn ->
+          handle_deadlock(waiting, files)
+        end)
+      end
+    end)
   end
 
   # No more queue, but spawned and map_size(waiting) do not match
@@ -558,6 +560,15 @@ defmodule Kernel.ParallelCompiler do
     end
   end
 
+  defp measure_timing(%{profile: :none}, _what, fun), do: fun.()
+  defp measure_timing(%{profile: {:time, _, _}}, what, fun) do
+    {time, result} = :timer.tc(fun)
+    time = div(time, 1000)
+
+    IO.puts(:stderr, "[profile] Executed #{what} in #{time}ms")
+    result
+  end
+
   defp cycle_timing(_result, %{profile: :none} = state) do
     state
   end